Python logger ignores FileHandler and StreamHandler levels in class

I am trying to set a different logger level for my log files and stream, and I have (seemingly) followed the demo (https://docs.python.org/3/howto/logging-cookbook.html) to the dot. However, in my actual code it does not work. Running this demo bare in a test script works:

import logging

logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)
# add the handlers to logger
logger.addHandler(ch)
logger.addHandler(fh)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

print(logger.handlers)
print(logger)

results in

alex@alexpc:~/Projects/claritydb$ python test.py ; cat spam.log
2019-09-16 11:53:44,293 - simple_example - ERROR - error message
2019-09-16 11:53:44,293 - simple_example - CRITICAL - critical message
[<StreamHandler <stderr> (ERROR)>, <FileHandler /home/Projects/claritydb/spam.log (DEBUG)>]
<Logger simple_example (DEBUG)>
2019-09-16 11:53:44,293 - simple_example - DEBUG - debug message
2019-09-16 11:53:44,293 - simple_example - INFO - info message
2019-09-16 11:53:44,293 - simple_example - WARNING - warn message
2019-09-16 11:53:44,293 - simple_example - ERROR - error message
2019-09-16 11:53:44,293 - simple_example - CRITICAL - critical message

But this for some reason will not execute properly in the actual code:

class MyClass(object):

    def __init__(self,
                 verbosity_stream="WARNING", 
                 verbosity_log="INFO"):

        self.logger = self.setup_logger(verbosity_stream=verbosity_stream, verbosity_log=verbosity_log)

    def setup_logger(self, verbosity_stream="ERROR", verbosity_log="WARNING"):

        # Create a custom logger

        logger = logging.getLogger(f"do_stuff")
        logger.setLevel(logging.DEBUG)

        fh = logging.FileHandler(f"do_stuff.log", mode='w')
        fh.setLevel(getattr(logging, verbosity_log))

        ch = logging.StreamHandler()
        ch.setLevel(getattr(logging, verbosity_stream))

        # create formatter and add it to the handlers
        formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
        ch.setFormatter(formatter)
        fh.setFormatter(formatter)

        # add the handlers to the self.logger
        logger.addHandler(ch)
        logger.addHandler(fh)

        print(logger.handlers)

        return logger

Any invocations to self.logger output both to the console and the logfile at the logging.DEBUG level -- which is obviously not what I want. I am very confused as to what I am missing since when I ask the main method what its filehandlers are I get

print(self.logger.handlers)
print(self.logger)

[<StreamHandler <stderr> (ERROR)>, <FileHandler /home/Projects/claritydb/do_stuff.log (DEBUG)>]
<Logger do_stuff (DEBUG)>

Which is identical to the test case, but there are all the info level outputs in both my console and log file. Changing my handler.setLevel commands has no effect on the output, the only thing that changes it is the change of the setLevel command to the initial logger call at the very top of the definitions (i.e. ch.setLevel and fh.setLevel have no effect, but logger.setLevel does [And I think it is only supposed to be the initial filter).

This is driving me nuts, does anyone have any idea?

EDIT1: Changing the

logger = logging.getLogger(f"do_stuff")

line to

logger = logging.getLogger()

seems to solve the problem, but I have no idea why...

When you call logger = logging.getLogger() you are getting the root logger and afterwards append your handlers and set its level and so on. When you do logger = logging.getLogger(f"do_stuff") you are getting a logger called do_stuff but the root logger still exists and your newly created logger propagates it's logs to the root loggers handlers. Since in that scenario the root logger has no handlers added to it, it uses the default logging.lastResort with it's default level. You can fix this in a number of ways. One easy solution is to set logger.propagate = False.

You also don't need this fh.setLevel(getattr(logging, verbosity_log)). Python handles the strings passed in directly just fine.

Recommended topics

Hot tags