Logging module stopped working

[llanitedave]

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!