About NOTSET in python logging

Question

As the logger.setLevel doc says:

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.

so I think if I create a root logger, with level NOTSET, the debug and info log will display.

The code use basicConfig to set root logger's level to NOTSET is right:

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging

logging.basicConfig(level=logging.NOTSET)
log = logging.getLogger()

log.debug('debug')
log.info('info')
log.warning('warning')
log.error('error')
log.critical('critical')

and output is:

DEBUG:root:debug
INFO:root:info
WARNING:root:warning
ERROR:root:error
CRITICAL:root:critical

But if I create a root logger, and add handler with NOTSET level to it, such as:

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging

log = logging.getLogger()
hd = logging.StreamHandler()
hd.setLevel(logging.NOTSET)
log.addHandler(hd)

log.debug('debug')
log.info('info')
log.warning('warning')
log.error('error')
log.critical('critical')

the output is:

warning
error
critical

but I think it will also output the debug and info message.

Findley

What is missing in this test is: log.log(logging.NOTSET, 'notset') which does not seem to log anything to anywhere in spite of what the docs imply. log.handlers is None here. However explicitly adding a handler like your below solution also does not solve the problem of log level zero specifically. – Lophobranch

@Lophobranch you are right, look at this problem now, I think to set root logger with 'logging.DEBUG' is enough and better; logging.NOTSET is not an effective level, it's used for delegation. – Findley

This is very very weird, where in the docs is this behaviour documented? It's had me puzzled the WHOLE day. – Emasculate

Answer 1

OK, I misunderstand the Logger's level and Handler's Level, in the doc:

The setLevel() method, just as in logger objects, specifies the lowest severity that will be dispatched to the appropriate destination. Why are there two setLevel() methods? The level set in the logger determines which severity of messages it will pass to its handlers. The level set in each handler determines which messages that handler will send on.

If I change code to this, will be ok:

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging

log = logging.getLogger()
log.setLevel(logging.NOTSET) # Set Logger's level to NOTSET, default is WARNING
#print "Logger's Level: ", log.level
hd = logging.StreamHandler()
hd.setLevel(logging.NOTSET)
#print "Handler's Level: ", hd.level
log.addHandler(hd)

log.debug('debug')
log.info('info')
log.warning('warning')
log.error('error')
log.critical('critical')

Findley

you need to add more details to this for it to make sense by itself. – Emasculate

Answer 2

I also thought this was confusing. I interpreted NOTSET as don't produce logs. But...

The level and handlers entries are interpreted as for the root logger, except that if a non-root logger’s level is specified as NOTSET, the system consults loggers higher up the hierarchy to determine the effective level of the logger. source

and

The level is interpreted as for loggers, and NOTSET is taken to mean ‘log everything’. source

This makes sense because NOTSET (0) which is below DEBUG (10)

Abandoned

I think this is the answer I (and OP) were looking for. "if a non-root logger’s level is specified as NOTSET, the system consults loggers higher up the hierarchy". From my testing, this also applies to handlers. If the handler is set to NOTSET, it will inherit the logger's level. And the default logger level is WARNING. To be safe, play around with different log level print statements to see what level is actually shown. Thank you for answering! – Presence

it broke my brain too. glad i could help in the end. – Abandoned

Answer 3

Let's explain by example that UNSET does NOT do anything when creating concrete instances of loggers (for some mysterious reason):

def logging_unset_level():
    """My sample logger explaining UNSET level

    Resources: 
    - https://mcmap.net/q/37716/-about-notset-in-python-logging
    - https://www.youtube.com/watch?v=jxmzY9soFXg&t=468s
    - https://github.com/CoreyMSchafer/code_snippets/tree/master/Logging-Advanced
    """
    import logging

    logger = logging.getLogger(__name__) # loggers are created in hierarchy using dot notation, thus __name__ ensures no name collisions.
    print(f'DEFAULT VALUE: logger.level = {logger.level}')

    file_handler = logging.FileHandler(filename='my_log.log')
    log_format = "{asctime}:{levelname}:{lineno}:{name}:{message}" # see for logrecord attributes https://docs.python.org/3/library/logging.html#logrecord-attributes
    formatter = logging.Formatter(fmt=log_format, style='{') 
    file_handler.setFormatter(fmt=formatter) 

    stdout_stream_handler = logging.StreamHandler(stream=sys.stdout)
    stdout_stream_handler.setLevel(logging.INFO) 
    log_format = "{name}:{levelname}:-> {message}" # see for logrecord attributes https://docs.python.org/3/library/logging.html#logrecord-attributes
    formatter = logging.Formatter(fmt=log_format, style='{')
    stdout_stream_handler.setFormatter(fmt=formatter)

    logger.addHandler(hdlr=file_handler)
    logger.addHandler(hdlr=stdout_stream_handler)

    logger.log(logging.NOTSET, 'notset')
    logger.debug('debug')
    logger.info('info')
    logger.warning('warning')
    logger.error('error')
    logger.critical('critical')

the output to screen is:

DEFAULT VALUE: logger.level = 0
__main__:WARNING:-> warning
__main__:ERROR:-> error
__main__:CRITICAL:-> critical

the output to stdout is:

2020-04-15 17:00:38,384:WARNING:200:__main__:warning
2020-04-15 17:00:38,384:ERROR:201:__main__:error
2020-04-15 17:00:38,384:CRITICAL:202:__main__:critical

as expected from the question's body, when the logger is instantiated its setting is UNSET. If you are using the basic config for some reason it does work as the docs imply it should everything from UNSET to higher get logged BUT when instantiating loggers concretely this setting makes only error messages work for some reason (find me a reference!).

Ok, now if you run it again but increase the level of the top logger everything works as you would expect (except the unset):

logger.setLevel(logging.DEBUG)

The output of stdout (note the stdout handler has level INFO in my example for pedagogical reasons, different from the file handler, trying to show inheritance of the .level value from the top logger):

DEFAULT VALUE: logger.level = 10
__main__:INFO:-> info
__main__:WARNING:-> warning
__main__:ERROR:-> error
__main__:CRITICAL:-> critical

and the output of the logger file my_log.log (this one DOES output the debug statements! :D ):

2020-04-15 17:05:58,782:DEBUG:198:__main__:debug
2020-04-15 17:05:58,784:INFO:199:__main__:info
2020-04-15 17:05:58,784:WARNING:200:__main__:warning
2020-04-15 17:05:58,784:ERROR:201:__main__:error
2020-04-15 17:05:58,784:CRITICAL:202:__main__:critica

is as expected. It inherited the top level loggers level so it printed everything from DEBUG level upwards.

Emasculate