On Monday, October 16, 2017 at 11:58:12 PM UTC-7, Steve D'Aprano wrote: > On Tue, 17 Oct 2017 03:06 pm, llanitedave wrote: > > [...] > > I set up the logging code at the very beginning of the app, before any other > > work is done. Here's the relevant code: > > > > #!/usr/bin/env python3 > [... snip imports ...] > > class MainWindow(QMainWindow): > > def __init__(self): > > super().__init__() > > # set up logging > > logging.basicConfig(format='%(levelname)s:%(message)s', > > filename="sample.log", level=logging.DEBUG) > > logging.info("Starting system, MainWindow.__init__, %s", > > str(datetime.datetime.today())) > > self.createUI() > > According to this code, no logging will occur because no MainWindow is > created. Nor is there any sort of main event loop. > > I'm sure that you're not actually so silly that you forgot to create a window > at all, but the point is, this example is *not* "the relevant code". It is > only *part* of the relevant code. Who knows what else is happening that might > be preventing logging from working? We don't know because we can't see the > rest of the relevant code. Perhaps you need to focus on that. > > > [...] > > Between the time that the logging was working and the time it quit, the only > > changes I made were to add a couple of logging.info() statements into a > > downstream module. But that seems irrelevant here, as those modules aren't > > included in the above test. > > I doubt that. I expect there must be some other change you have forgotten, and > it is *that* which has disabled logging. Maybe you call something which sets > the logging level above INFO? > > I would start with this: > > import sys > import os > import logging > logging.basicConfig(format='%(levelname)s:%(message)s', > filename="sample.log", level=logging.DEBUG) > logging.info("Starting module, %s", str(datetime.datetime.today())) > > # import everything else > ... > logging.info("Importing complete %s", str(datetime.datetime.today())) > > class MainWindow(QMainWindow): > def __init__(self): > super().__init__() > logging.info("Creating window, %s", str(datetime.datetime.today())) > self.createUI() > > logging.info("Class created %s", str(datetime.datetime.today())) > window = MainWindow() > logging.info("Window created %s", str(datetime.datetime.today())) > logging.critical("Can you see this? %s", str(datetime.datetime.today())) > > # plus whatever else is needed to make the application run > ... > > That will show precisely where and when logging stops: > > 1. Does it work at all, straight out of the logging module? If not, then > something broke it before your module even gets loaded. > > 2. Does it still work after all the other imports? If not, then bisect the > imports until you locate which module breaks logging. > > 3. Do you get the "Class created" and "Window created" messages? If no, then > that helps narrow down where the fault may lie. > > E.g. if you see the first, but not the second, then something in > super().__init__ may be disabling logging; if you don't see the first, then > look at QMainWindow's metaclass, if it has one. If it doesn't have a > metaclass, then that's a mystery -- maybe something in some other thread is > messing you about? > > 4. If you see the CRITICAL message, but not the INFO ones, then something has > reset the logging level. > > 5. What happens if you delete sample.log? Does it get re-created? If not, > maybe there's a permissions error. > > 6. If you're not seeing *any* logging at all, perhaps you need to fall back on > calling print() directly. Run your application from a terminal, and see what > it prints. > > If even print isn't working, then follow the three Rs: Reboot, Reinstall, and > Resign :-) > > 7. Perhaps a bit less drastic, you can insert a debugging checkpoint in the > code, run the application from a terminal, and when it halts at the debugger, > have a look at the state of the logging module. > > 8. Just to be absolutely sure, check logging.__file__ to ensure you haven't > shadowed the real logging module with some sort of mock. But now I'm really > clutching at straws, because if that were the case, I'd expect there to be an > exception, not just logging failing to work. > > > > I'm intrigued by this error, and would love to hear what caused it when you > find out. Please respond back on the list with your diagnosis. > > By the way, this sort of spooky action-at-a-distance is why I prefer to create > my own loggers, rather than use the global one. > > > > -- > Steve > “Cheer up,” they said, “things could be worse.” So I cheered up, and sure > enough, things got worse.
Well, I started with your first suggestion, and sure enough, I found the problem right away. What I was calling"downstream modules" really aren't so downstream after all, since they apparently get parsed on some level as soon as they are loaded. I had placed a call to "logging.info()" in the evocontrol module that was imported prior to MainWindow(), and it was after a class definition but before the __init__() function. I learned that if a call comes within the function it's insulated, but outside the function it interferes with the logging module unless the configuration occurs prior to its import. So, live and learn, that's a mistake that won't be repeated. Thanks for your quick and on the money response. There's a reason I lurk here! -- https://mail.python.org/mailman/listinfo/python-list