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?

Good question, but for the sake of coherence if you are testing `a.getEffectiveLevel`, `a.setLevel` makes more sense than `h.setLevel`. — Paulo Scardine, Jul 16 '13 at 05:43
In this case the handler does not have a `getEffectiveLevel` command — Kevin Burke, Jul 16 '13 at 05:49
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: https://gist.github.com/Stannislav/dd0c44a9b3f6d9e8dd30756582228877 — Stan, Sep 09 '21 at 17:21

Bakuriu · Accepted Answer · 2013-07-16T08:15:38.940

85

It allows finer control. By default the root logger has WARNING level set, this means that it wont print messages with lower level(no matter how the handlers' levels are set!). But, if you set the root logger's level to DEBUG, indeed the message get 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, image 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.

edited Jul 16 '13 at 08:15

answered Jul 16 '13 at 05:43

Bakuriu

98,325
22
197
231

9

So best practice is to set a lower level of root logger and controls logging via handlers' level. Am I correct? – laike9m Dec 28 '15 at 09:18
8

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. – hmijail Aug 27 '17 at 22:24
15

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. – Christoph Apr 17 '18 at 19:19
4

@Christoph 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). – Bakuriu Apr 17 '18 at 20:23
2

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. – Christoph Apr 17 '18 at 20:29
@hmijail "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](https://docs.python.org/3/library/logging.html#logging.Logger.propagate) and illustrated by the Vinay Sajip's flow diagram below). – Géry Ogam Sep 11 '18 at 18:30
1

@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. – logicOnAbstractions Jun 21 '21 at 15:19
@Christoph the [official tutorial](https://docs.python.org/3.9/howto/logging.html) 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"](https://docs.python.org/3.9/howto/logging.html#a-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. – hmijail Jun 22 '21 at 00:24
As Bakuriu explained, those defaults make sense even for production, and seem to be the standard across logging libraries and languages. – hmijail Jun 22 '21 at 00:47
@logicOnAbstractions 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. – hmijail Jun 22 '21 at 00:47
@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). – logicOnAbstractions Jun 22 '21 at 01:14
@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. – hmijail Jun 22 '21 at 01:17
@logicOnAbstractions 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). – hmijail Jun 22 '21 at 01:27
1

@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. – Géry Ogam Jun 22 '21 at 13:59
@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. – logicOnAbstractions Jun 22 '21 at 17:46
1

@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. – hmijail Jun 23 '21 at 15:18
I see. Your initial formulation "anything else is rather useless" was rather black & white. Your recent explantion makes more sense to me. – logicOnAbstractions Jun 28 '21 at 14:06
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://stackoverflow.com/a/17670167/2906290, I'd say it works as I supposed, so it would "delay" the system unnecessarily. – Raúl Moreno Feb 02 '22 at 15:49

cwallenpoole · Answer 2 · 2013-07-16T06:18:56.570

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.

score 27 · Answer 3 · edited Apr 01 '21 at 15:51

27

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:

edited Apr 01 '21 at 15:51

jdhao

24,001
18
134
273

answered Jul 16 '13 at 07:08

Vinay Sajip

95,872
14
179
191

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? – Marius Mucenicu May 17 '19 at 06:01
2

It defaults to allowing all events through. – Vinay Sajip May 27 '19 at 15:20
@MariusMucenicu you can also check a handler or a logger's level via its `.level` attribute, e.g., `file_handler.level`. – jdhao Apr 01 '21 at 15:48

william_grisaitis · Answer 4 · 2020-06-24T00:42:08.670

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

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

4 Answers4

the rule

in other words

a full example

Linked

Related