What is the point of setLevel in a python logging handler?

Question

Let's say I have the following code:

import logging
import logging.handlers

a = logging.getLogger('myapp')
h = logging.handlers.RotatingFileHandler('foo.log')
h.setLevel(logging.DEBUG)
a.addHandler(h)

# The effective log level is still logging.WARN
print a.getEffectiveLevel() 
a.debug('foo message')
a.warn('warning message')

I expect that setting logging.DEBUG on the handler would cause debug-level messages to be written to the log file. However, this prints 30 for the effective level (equal to logging.WARNING, the default), and only logs the warn message to the log file, not the debug message.

It appears that the handler's log level is being dropped on the floor, e.g. it's silently ignored. Which makes me wonder, why have setLevel on the handler at all?

Armendariz

Good question, but for the sake of coherence if you are testing a.getEffectiveLevel, a.setLevel makes more sense than h.setLevel. – Hallo

In this case the handler does not have a getEffectiveLevel command – Armendariz

One could say that logger levels control which log messages come in and become log records, while handler levels control which log records come out and are emitted. I have a pseudocode gist that summarises some of the logging logic here: gist.github.com/Stannislav/dd0c44a9b3f6d9e8dd30756582228877 – Cutshall

Answer 1

It allows finer control. By default the root logger has WARNING level set; this means that it won't print messages with a lower level (no matter how the handlers' levels are set!). But, if you set the root logger's level to DEBUG, indeed the message gets sent to the log file:

import logging
import logging.handlers

a = logging.getLogger('myapp')
a.setLevel(logging.DEBUG)   # set root's level
h = logging.handlers.RotatingFileHandler('foo.log')
h.setLevel(logging.DEBUG)
a.addHandler(h)
print a.getEffectiveLevel() 
a.debug('foo message')
a.warn('warning message')

Now, imagine that you want to add a new handler that doesn't record debug information. You can do this by simply setting the handler logging level:

import logging
import logging.handlers

a = logging.getLogger('myapp')
a.setLevel(logging.DEBUG)   # set root's level

h = logging.handlers.RotatingFileHandler('foo.log')
h.setLevel(logging.DEBUG)
a.addHandler(h)

h2 = logging.handlers.RotatingFileHandler('foo2.log')
h2.setLevel(logging.WARNING)
a.addHandler(h2)

print a.getEffectiveLevel() 
a.debug('foo message')
a.warn('warning message')

Now, the log file foo.log will contain both messages, while the file foo2.log will only contain the warning message. You could be interested in having a log file of only error-level messages; then, simply add a Handler and set its level to logging.ERROR, everything using the same Logger.

You may think of the Logger logging level as a global restriction on which messages are "interesting" for a given logger and its handlers. The messages that are considered by the logger afterwards get sent to the handlers, which perform their own filtering and logging process.

Bittner

So best practice is to set a lower level of root logger and controls logging via handlers' level. Am I correct? – Lussier

It's not "best practice", it's just that doing anything else is rather useless. If the handler's level is DEBUG but the logger only sends ERROR, the handler of course will only receive (and pass) ERROR. – Replevy

One wonders, then, why the default log level of the root logger is not DEBUG or 0, actually, because if you don't know this "trick", then you just scratch your head like the OP, and wonder why your log messages don't get printed. – Ramayana

@Ramayana I believe because DEBUG is meant for debugging the application, and hence should only appear when a developer is debugging it. Setting the default level to `WARNING avoids that some missing configuration causes noise to be printed when real users use the app. In other words: displaying low level messages should require intervention from the user. (Obviously this is just an opinion and people can argue the contrary too). – Bittner

OK, but in that case, as I understand it, I'd at least expect INFO to be the default, then...anyway, opinions, as you say. – Ramayana

@Replevy "If the handler's level is DEBUG but the logger only sends ERROR, the handler of course will only receive (and pass) ERROR." Not if the log records come from a child logger (in this case the parent logger's level and filters are not considered and the log records are passed directly to the logger's handlers, as stated in the documentation and illustrated by the Vinay Sajip's flow diagram below). – Zerk

@hmijailmournsresignees I disagree that anything else is "useless". For instance, I might some rotating filehandler that is connected to multiple loggers (that may have different levels). Perhaps I want that file handler to just log everything, regardless of levels, for debugging for instance. – Zimmermann

@Ramayana the official tutorial says early on "The default level is WARNING, which means that only events of this level and above will be tracked". Then, in its first "simple example" it says "The INFO message doesn’t appear because the default level is WARNING." So it's only a head-scratcher for those who don't check the official tutorial. – Replevy

As Bakuriu explained, those defaults make sense even for production, and seem to be the standard across logging libraries and languages. – Replevy

@Zimmermann not sure I follow. In your example the handler must be set to DEBUG to catch everything, and then of course any DEBUG logging is pertinent, right? Not sure how that relates to/negates the point. – Replevy

@hmijailmournsresignees well the initial statement was "the root logger is always set at a lower level than the handler". Which most of the times does make sense. But in the case mentioned, SOME root loggers may be set to ERROR, but one of its handler (the shared filehandler) may still be set to DEBUG (as some other root loggers pipped through it may be logging DEBUG as well). – Zimmermann

@Maggyero in your example (as in any case?) you have a logger with a level L and a handler with a level H. If L>=H (like ERROR>=DEBUG), the log record gets acted on by the handler (assuming no filters). As you (and your doc link) say, the ancestor loggers do nothing, so I don't see how the logger being a child or not changes anything. – Replevy

@Zimmermann No initial statement said "always", so I'm not sure what you're discussing. And I have a feeling you're taking my example upside down. ERROR>DEBUG, so it will get always acted on by the handler (assuming no filters). – Replevy

@hmijailmournsresignees Your statement ‘If the handler's level is DEBUG but the logger only sends ERROR, the handler of course will only receive (and pass) ERROR’ is incorrect because it assumes that the logger on which the handler is attached is the logger making the log record. But a child logger of the logger on which the handler is attached could make the log record, in which case the handler would receive a log record with potentially a lower level than the level of the logger on which the handler is attached. That is what logicOnAbstractions was trying to convey. – Zerk

@hmijailmournsresignees yeah wasn't a word for word quote (though you formulation did say it was "useless"). All I mean to convey is that there is a use case for a handler with a lower level than (some) of its root logger. Maggyero understood. – Zimmermann

@Maggyero, my statement has 2 "only" that you violate, so it's a different case. @logicOnAbstractions, of course there are tons of different possible configurations which might make sense or not. Both of you are adding new entities to create different cases; I don't see the point? My statement was very simple and limited to exemplify that If L>=H then handle, and if H==minimum, you lose the utility of the conditional (and that's why I said it turns "rather useless" if you do that as a general practice). No more, no less. – Replevy

I see. Your initial formulation "anything else is rather useless" was rather black & white. Your recent explantion makes more sense to me. – Zimmermann

I wonder, apart from all said, from an efficiency standpoint, does having the logger "root level" at logging.DEBUG make the system slower because it sends every debug log although no handler is listening to it? I imagine it's more intelligent than that but does someone know? I wouldn't leave the root at DEBUG at production by default just in case. EDIT: According to Vinay Sajip's diagram, https://mcmap.net/q/223665/-what-is-the-point-of-setlevel-in-a-python-logging-handler, I'd say it works as I supposed, so it would "delay" the system unnecessarily. – Gilstrap

Answer 2

In Python logging there are two different concepts: the level that the logger logs at and the level that the handler actually activates.

When a call to log is made, what is basically happening is:

if self.level <= loglevel:
    for handler in self.handlers:
        handler(loglevel, message)

While each of those handlers will then call:

if self.level <= loglevel:
    # do something spiffy with the log!

If you'd like a real-world demonstration of this, you can look at Django's config settings. I'll include the relevant code here.

LOGGING = {
    #snip
    'handlers': {
        'null': {
            'level': 'DEBUG',
            'class': 'logging.NullHandler',
        },
        'console':{
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filters': ['special']
        }
    },
    'loggers': {
        #snip
        'myproject.custom': {
            # notice how there are two handlers here!
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filters': ['special']
        }
    }
}

So, in the configuration above, only logs to getLogger('myproject.custom').info and above will get processed for logging. When that happens, the console will output all of the results (it will output everything because it is set to DEBUG level), while the mail_admins logger will happen for all ERRORs, FATALs and CRITICALs.

I suppose some code which isn't Django might help too:

import logging.handlers as hand
import logging as logging

# to make things easier, we'll name all of the logs by the levels
fatal = logging.getLogger('fatal')
warning = logging.getLogger('warning')
info = logging.getLogger('info')

fatal.setLevel(logging.FATAL)
warning.setLevel(logging.WARNING)
info.setLevel(logging.INFO)    

fileHandler = hand.RotatingFileHandler('rotating.log')

# notice all three are re-using the same handler.
fatal.addHandler(fileHandler)
warning.addHandler(fileHandler)
info.addHandler(fileHandler)

# the handler should log everything except logging.NOTSET
fileHandler.setLevel(logging.DEBUG)

for logger in [fatal,warning,info]:
    for level in ['debug','info','warning','error','fatal']:
        method = getattr(logger,level)
        method("Debug " + logger.name + " = " + level)

# now, the handler will only do anything for *fatal* messages...
fileHandler.setLevel(logging.FATAL)

for logger in [fatal,warning,info]:
    for level in ['debug','info','warning','error','fatal']:
        method = getattr(logger,level)
        method("Fatal " + logger.name + " = " + level)

That results in:

Debug fatal = fatal
Debug warning = warning
Debug warning = error
Debug warning = fatal
Debug info = info
Debug info = warning
Debug info = error
Debug info = fatal
Fatal fatal = fatal
Fatal warning = fatal
Fatal info = fatal

Again, notice how info logged something at info, warning, error, and fatal when the log handler was set to DEBUG, but when the handler was set to FATAL all of a sudden only FATAL messages made it to the file.

Reade

Answer 3

Handlers represent different audiences for logging events. Levels on handlers are used to control the verbosity of output seen by a particular audience, and act in addition to any levels set on loggers. Levels on loggers are used to control the overall verbosity of logging from different parts of an application or library.

See this diagram for more information about how logging events are handled:

Stepp

Hello @Vinay Sajip! so if you omit the level of a Handler what does it default to? I'm using the dictConfig method to do some custom logging config globally for my app and I've read the docs and it says that the handler's level is optional but it doesn't say what it defaults to. Also I can't deduce that from the above diagram, because when it gets to the Handler enabled for level of LogRecord? part how can I tell whether the Handler is enabled or not? does this mean that if it doesn't have an explicit level set it inherits the level of the logger it's attached to? or the root logger? – Bottom

It defaults to allowing all events through. – Stepp

@MariusMucenicu you can also check a handler or a logger's level via its .level attribute, e.g., file_handler.level. – Diu

Answer 4

the rule

if and only if

handler.level <= message.level
&&
logger.level <= message.level

then the message prints.

Reminder: lower values are more verbose

Level    | Numeric value
---------|--------------
CRITICAL | 50
ERROR    | 40
WARNING  | 30
INFO     | 20
DEBUG    | 10
NOTSET   | 0

ref: https://docs.python.org/3/library/logging.html#logging-levels

in other words

if the logger is set to WARNING, it won't matter if the handler has a more verbose setting. it'll already be filtered by the time it gets to the handler.

a full example

import logging


handler_info = logging.StreamHandler()
handler_info.setLevel("INFO")
handler_info.setFormatter(logging.Formatter(
    f"%(levelname)s message for %(name)s handled by handler_info: %(message)s"))

handler_debug = logging.StreamHandler()
handler_debug.setLevel("DEBUG")
handler_debug.setFormatter(logging.Formatter(
    f"%(levelname)s message for %(name)s handled by handler_debug: %(message)s"))

logger_info = logging.getLogger('logger_info')
logger_info.setLevel("INFO")
logger_info.addHandler(handler_info)
logger_info.addHandler(handler_debug)

logger_debug = logging.getLogger('logger_debug')
logger_debug.setLevel("DEBUG")
logger_debug.addHandler(handler_info)
logger_debug.addHandler(handler_debug)

print()
print("output for `logger_info.info('hello')`")
logger_info.info("hello")
print()
print("output for `logger_info.debug('bonjour')`")
logger_info.debug("bonjour")
print()
print("output for `logger_debug.info('hola')`")
logger_debug.info("hola")
print()
print("output for `logger_debug.debug('ciao')`")
logger_debug.debug("ciao")
print()

which gives

output for `logger_info.info('hello')`
INFO message for logger_info handled by handler_info: hello
INFO message for logger_info handled by handler_debug: hello

output for `logger_info.debug('bonjour')`
# nothing, because message.level < logger.level

output for `logger_debug.info('hola')`
INFO message for logger_debug handled by handler_info: hola
INFO message for logger_debug handled by handler_debug: hola

output for `logger_debug.debug('ciao')`
DEBUG message for logger_debug handled by handler_debug: ciao
# nothing from handler_info, because message.level < handler.level

Lotetgaronne