python logger level inherited from root set to warning by default

Question

In my program I define a logger at the beginning that looks similar to this:

def start_logger():
        fh = logging.handlers.RotatingFileHandler('logger.log', 
                                                  maxBytes=1000000, 
                                                  backupCount=100)
        fh.setLevel(logging.DEBUG)

        ch = logging.StreamHandler(sys.stdout)
        ch.setLevel(logging.DEBUG)

        fh_fmt = '%(asctime)s %(levelname)8s %(message)s [%(filename)s:%(lineno)d]'
        #fh_fmt = '%(asctime)s - %(funcName)s - %(levelname)s - %(message)s'

        ch_fmt = '%(asctime)s %(levelname)8s %(message)s [%(filename)s:%(lineno)d]'
        #ch_fmt = '%(funcName)s - %(levelname)s - %(message)s'

        fh.setFormatter(logging.Formatter(fh_fmt))
        ch.setFormatter(logging.Formatter(ch_fmt))

        root = logging.getLogger()
        root.addHandler(fh)
        root.addHandler(ch)

I then have multiple files that are called from my main program. In order for them to work correctly I need to do the following:

import logging
log = logging.getLogger(__name__)
log.setLevel(logging.DEBUG)
log.debug("This debug message is ounly output when I set the level again to debug for this file. Otherwise the the log level for this file is WARNING.")

Why is the default level for all modules that I import set to warning. Why do I have to set the level again to DEBUG for each of them when they import my root logger with log = logging.getLogger(__name__)? Is this the best way to create a logging module accross a package with different modules or is there a better solution?

Fractious

Answer 1

Let's start by looking at what Handler.setLevel does:

Sets the threshold for this handler to lvl. Logging messages which are less severe than lvl will be ignored. When a handler is created, the level is set to NOTSET (which causes all messages to be processed).

Any messages less severe than lvl are ignored. Effectively, setting it to DEBUG is meaningless (unless you define your own log levels), because there is no less severe message than debug. So, that means that the handler won't ignore any messages.

setLevel is the right idea, but you're calling it on the wrong object. Look at Logger.setLevel:

Sets the threshold for this logger to lvl. Logging messages which are less severe than lvl will be ignored. When a logger is created, the level is set to NOTSET (which causes all messages to be processed when the logger is the root logger, or delegation to the parent when the logger is a non-root logger). Note that the root logger is created with level WARNING.

The term ‘delegation to the parent’ means that if a logger has a level of NOTSET, its chain of ancestor loggers is traversed until either an ancestor with a level other than NOTSET is found, or the root is reached.

If an ancestor is found with a level other than NOTSET, then that ancestor’s level is treated as the effective level of the logger where the ancestor search began, and is used to determine how a logging event is handled.

You're creating the children right, but they're all children of the root logger. They're level is set to NOTSET, and it propagates up to the root, whose default value is WARNING. Consequently, you don't see any messages.

TL;DR: The solution is simple: set the level on the logger, not the handler. The following code should do what you need:

def start_logger():
    fh = logging.handlers.RotatingFileHandler('logger.log', 
                                              maxBytes=1000000, 
                                              backupCount=100)

    ch = logging.StreamHandler(sys.stdout)

    fh_fmt = '%(asctime)s %(levelname)8s %(message)s [%(filename)s:%(lineno)d]'
    #fh_fmt = '%(asctime)s - %(funcName)s - %(levelname)s - %(message)s'

    ch_fmt = '%(asctime)s %(levelname)8s %(message)s [%(filename)s:%(lineno)d]'
    #ch_fmt = '%(funcName)s - %(levelname)s - %(message)s'

    fh.setFormatter(logging.Formatter(fh_fmt))
    ch.setFormatter(logging.Formatter(ch_fmt))

    logging.basicConfig(level=logging.DEBUG)
    root = logging.getLogger()
    root.addHandler(fh)
    root.addHandler(ch)

Once you do that, you shouldn't need the setLevel call when making the children.

Oh, and to answer your other questions: this is exactly the way you're supposed to use the logging library. (I actually just log everything to the root logger, because I don't need the kind of granularity you developed, but when you have a case for it, you're doing it just as you should.)

EDIT: Evidently, setLevel doesn't seem to work on the root logger. Instead, before accessing the root logger, you have to set basicConfig. Setting the level in logging.basicConfig will do what you need (at least, it worked in my tests). Note, doing this matches the example given in Logging from multiple modules, so should solve your problem.

Moua

Thanks for your advice, but when I add root.setLevel(logging.DEBUG) and removed all the setLevel from the files, they do not produce any output. What could be the reason for that? Which one is defined as the 'root logger'? Simply the first instantiation of the logger? – Fractious

Sorry, I answered lazy. I should have done more testing so I could be more definitive. I'll do some research, then edit. – Moua

Updated and changed my sample code. Looks like instead of root.setLevel, you need logging.basicConfig before ever getting your root logger. – Moua

I see, that seems to work indeed, although my custom formatting is then not applied on all these submodules – Fractious

Are you certain that your custom formatting is applied at the root? Just like root.setLevel didn't work, it's possible that root.addHandler won't. basicConfig does have a handlers argument. – Moua

No, I'm not sure, How can I determine what is the root logger? – Fractious

Let us continue this discussion in chat. – Moua