Logging module stopped working

[Steve D'Aprano]

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.