Logging setLevel is being ignored

Question

The below code is copied from the documentation. I am supposed to be able to see all the info logs. But I don't. I am only able to see the warn and above even though I've set setLevel to INFO.

Why is this happening? foo.py:

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

Output:

workingDirectory$ python foo.py
warn message
error message
critical message

Where did the info and debug messages go??

Counterattack

Answer 1

Replace the line

logger.setLevel(logging.DEBUG)

with

logging.basicConfig(level=logging.DEBUG, format='%(message)s')

and it should work as expected. If you don't configure logging with any handlers (as in your post - you only configure a level for your logger, but no handlers anywhere), you'll get an internal handler "of last resort" which is set to output just the message (with no other formatting) at the WARNING level.

Ungrateful

Thanks Vinay, you maintain logging?? Thanks for taking the time to answer a newbie question! I'll try this later tonight and confirm that it worked. – Counterattack

Hold on - this sets the global/root logging settings, but what if I wanted to set the level only for logger? And why doesn't logger.setLevel(logging.DEBUG) work? It should. – Lanai

@Greg because no handler was configured, so logging uses an internal "handler of last resort" which has a level of WARNING: docs.python.org/3.2/library/logging.html#logging.lastResort – Ungrateful

Still, it should work. The user sets the level explicitly. – Edholm

are you telling me that you have add the handler to the logger before you set the logger lever? – Gram

@Gram no, just before you do any logging. – Ungrateful

So calling logger.setlevel(logging.DEBUG) after getLogger() is not enough. I also have to mess with a handler? That not intuitive at all. – Obliterate

@cryanbhu it is a necessary, but not sufficient, step. – Ungrateful

I'm a little confused, but just to get things straight, If I create a logger, I should always create handlers for the logger and do the level setting via the handler itself? – Annisannissa

I think it's clear that the default should be to output to stdout (if possible). Say I'm pulling in a logger from someone else after running their initialization scripts, I'm supposed to go through them and make sure they don't call basicConfig? I just want to make sure that the logger is logging at the DEBUG level. – Chiles

coming from other programming languages, this is stupid. – Neomineomycin

I would really prefer exception if no handler is specified.. – Precancel

Can anyone help me understand why logging.basicConfig, which configures root logger, also affects child logger ? How is this relationship here? – Precancel

I'm changing the accepted answer back to this one because at the time of writing it has more upvotes. – Counterattack

@Neomineomycin even coming from Python, this is stupid. – Puppet

Answer 2

As pointed by some users, using:

logging.basicConfig(level=logging.DEBUG, format='%(message)s')

like written in the accepted answer is not a good option because it sets the log level for the root logger, so it may lead to unexpected behaviours (eg. third party libraries may start to log debug messages if you set loglevel=logging.DEBUG)

In my opinion the best solution is to set log level just for your logger, like this:

import logging

logger = logging.getLogger('MyLogger')
handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)

Not really intuitive solution, but is necessary if you want to set log level only for 'MyLogger' and leave the root logger untouched.

So, why is logging.basicConfig(level=logging.DEBUG, format='%(message)s') setting the log level globally?

Well, actually it doesn't. As said, it's just changing the configuration of the root logger and, as described in the python documentation:

Loggers should NEVER be instantiated directly, but always through the module-level function logging.getLogger(name). Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.

So, logging.basicConfig is creating a StreamHandler with a default Formatter and adding it to the root logger.

The point is that if any other library is using the "root logger", you're going to set that log level for that library too so it can happen that you start to see debug logs from third party libraries.

This is why I think it's better to create your own logger and set your own formatters and handlers, so you can leave the root logger untouched.

Hasan

Elegant answer. Thanks! helped me a lot! – Kentish

Thank you so much, I was looking for this! – Euphemie

I've changed the accepted answer to this one. Disclaimer, I no longer do python logging and have not checked it myself. I'm relying on the fact that, at the time of this writing, there are 40 upotes. – Counterattack

You have not answered the OP's question. The OP did as you suggested and the question is why doesn't the logging level work. – Vandervelde

The OP DID NOT what I am recommending here so I suggest you to read better the code. Do you see any stream handler in the OP code? – Hasan

For simple logging, you can elide the configuration to logger.addHandler(logging.StreamHandler(sys.stderr)); logger.setLevel(logging.DEBUG) – Skydive

Answer 3

Try running logging.basicConfig() in there. Of note, I see you mention INFO, but use DEBUG. As written, it should show all five messages. Swap out DEBUG with INFO, and you should see four messages.

import logging

logging.basicConfig()
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

edit: Do you have logging set up elsewhere in your code already? Can't reproduce the exact behavior you note with the specific code provided.

Lananna

Hi @tabbek, thanks for the reply. I'll try doing the basicConfig() instead. I'll be able to do it later tonight. I do not have any other code. I have another project with a handler, which works. Then I tried starting a new project, did not work. So I wrote this barebones script. The above code is the only content of foo.py. I'm thinking there is some interference going on or something. I'll keep you updated! – Counterattack

basicConfig() does some basic setup and creation of a new log handler. from docs.python.org/2/library/logging.html at logging.basicConfig([**kwargs]) – Lananna

basicConfig() should attach a handler with WARNING level. So does "logger.setLevel(logging.DEBUG)" here set BOTH logger and handler level? – Bairam

Why does this work? What is the reasoning behind it (the need for the parameter-less logging.basicConfig())? – Scherman

It does some basic setup of the logging system using defaults. Ref: docs.python.org/3/library/logging.html#logging.basicConfig "Does basic configuration for the logging system by creating a StreamHandler with a default Formatter and adding it to the root logger." – Lananna

@Lananna The basic handler is set in the root logger, why does the child logger's setLevel(DEBUG) has effect on it? The documentation on setLevel doesn’t say it affects handler’s level, not to mention its ancestor’s handler’s level.. – Precancel

To answer my own question - the handler attached by basicConfig has no explicit level, thus has default level — NOTSET, which effectively emit all messages. This is why no arg would work. – Precancel

Answer 4

This is technically also an "answer", because it can "solve" the problem. BUT I definitely DO NOT like it. It is not intuitive, and I lost 2+ hours over it.

Before:

import logging
logger = logging.getLogger('foo')
logger.setLevel(logging.INFO)
logger.info('You can not see me')
# Or you can just use the following one-liner in command line.
# $ python -c "import logging; logger = logging.getLogger('foo'); logger.setLevel(logging.INFO); logger.info('You can not see me')"

After:

import logging

logging.debug('invisible magic')  # <-- magic

logger = logging.getLogger('foo')
logger.setLevel(logging.INFO)
logger.info('But now you can see me')
# Or you can just use the following one-liner in command line.
$ python -c "import logging; logging.debug('invisible magic'); logger = logging.getLogger('foo'); logger.setLevel(logging.INFO); logger.info('But now you see me')"

PS: Comparing it to the current chosen answer, and @Vinay-Sajip's explanation, I can kind of understand why. But still, I wish it was not working that way.

Piss

This is indeed confusing, which led me to ask #57115895 I found the accepted answer there extremely helpful :-) – Carrew

@sam, thanks for the heads-up! Yes that makes me sleep well now. :-D – Piss

Answer 5

If you want this to work WITHOUT basicConfig, you have to first set up the lowest possible level you'll log onto the logger. Since the logger sets a minimum threshold, handlers which have a lower threshold but belong to the same logger won't get those lower threshold messages since they're ignored by the logger in the first place. Intuitive, but not obvious.

We start by doing this:

lgr = logging.getLogger(name)
lgr.setLevel(logging.DEBUG)

Then, set up the handlers with the different levels you need, in my case I want DEBUG logging on stdout and INFO logging to a rotating file, so I do the following:

rot_hndlr = RotatingFileHandler('filename.log',
                                maxBytes=log_size,
                                backupCount=3)
    
rot_hndlr.setFormatter(formatter)
rot_hndlr.setLevel(logging.INFO)
lgr.addHandler(rot_hndlr)

stream_hndlr = logging.StreamHandler()
stream_hndlr.setFormatter(stream_formatter)
lgr.addHandler(stream_hndlr)

Then, to test, I do this:

lgr.debug("Hello")
lgr.info("There")

My stdout (console) will look like this:

Hello
There

and my filename.log file will look like this:

There

Underskirt

Finally, the missing explanation. I was about to switch languages. – Mistletoe

Finally, the correct reason. If you just call setLevel on the handler, it seems to ignore it because the default logging level is too high. Very strange implementation detail that propagates out to the API, making it very confusing. – Polysaccharide

Answer 6

In short, change the level in logging.basicConfig will influence the global settings. You should better set level for each logger and the specific handler in the logger.

The following is an example that displays all levels on the console and only records messages >= errors in log_file.log. Notice the level for each handler is different.

import logging
# Define logger
logger = logging.getLogger('test')

# Set level for logger
logger.setLevel(logging.DEBUG)

# Define the handler and formatter for console logging
consoleHandler = logging.StreamHandler() # Define StreamHandler
consoleHandler.setLevel(logging.DEBUG) # Set level
concolsFormatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s') # Define formatter
consoleHandler.setFormatter(concolsFormatter) # Set formatter
logger.addHandler(consoleHandler) # Add handler to logger

# Define the handler and formatter for file logging
log_file = 'log_file'
fileHandler = logging.FileHandler(f'{log_file}.log') # Define FileHandler
fileHandler.setLevel(logging.ERROR) # Set level
fileFormatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') # Define formatter
fileHandler.setFormatter(fileFormatter) # Set formatter
logger.addHandler(fileHandler) # Add handler to logger

# Test
logger.debug('This is a debug')
logger.info('This is an info')
logger.warning('This is a warning')
logger.error('This is an error')
logger.critical('This is a critical')

Console output:

# Test
test - DEBUG - This is a debug
test - INFO - This is an info
test - WARNING - This is a warning
test - ERROR - This is an error
test - CRITICAL - This is a critical

File log_file.log content:

2021-09-22 12:50:50,938 - test - ERROR - This is an error
2021-09-22 12:50:50,938 - test - CRITICAL - This is a critical

---

To review your logger's level:

logger.level

The result should be one of the following:

10 # DEBUG
20 # INFO
30 # WARNING
40 # ERROR
50 # CRITICAL

To review your handlers's levels:

logger.handlers

[<StreamHandler stderr (DEBUG)>,
 <FileHandler ***/log_file.log (ERROR)>]

Flanders

This is the best answer if you want to set a logger for each module without relying in the global logger. – Uzziel

Answer 7

The accepted answer does not work for me on Win10, Python 3.7.2.

My solution:

logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

It's order sensitive.

Bose

This one actually works without the setLevel at all, but also means it's the same as the more clear answer above. – Letterhead

Answer 8

You have to set the basicConfig of the root logger to DEBUG, then you can set the level of your individual loggers to more restrictive levels.

This is not what I expected. Here is what I had to do:

#!/usr/bin/env python3

import logging
# by default this is WARNING.  Leaving it as WARNING here overrides 
# whatever setLevel-ing you do later so it seems they are ignored.
logging.basicConfig(level=logging.DEBUG)

l = logging.getLogger(__name__)
l.setLevel(level=logging.INFO)
# if I hadn't called basicConfig with DEBUG level earlier, 
# info messages would STILL not be shown despite calling 
# setLevel above.  However now debug messages will not be shown 
# for l because setLevel set it to INFO

l.warning('A warning message will be displayed')
l.info('A friendly info message will be displayed')
l.debug('A friendly debug message will not be displayed')

Goodhumored

Answer 9

Most of the answers that I've found for this issue uses the basicConfig of the root logger.

It's not helpful for those who intend to use multiple independent loggers that were not initialised with basicConfig. The use of basicConfig implies that the loglevels of ALL loggers will be changed. It also had the unfortunate side effect of generating duplicate logs.

So I tried over several days experimenting with different ways to manipulate the loglevels and came up with one that finally worked.

The trick was to not only change the log levels of all the handlers but also the all the handlers of the parent of the logger.

    def setLevel(self, infoLevel):
    # To dynamically reset the loglevel, you need to also change the parent levels as well as all handlers!

    self.logger.parent.setLevel(infoLevel)
    for handler in self.logger.parent.handlers:
        handler.setLevel(infoLevel)

    self.logger.setLevel(infoLevel)
    for handler in self.logger.handlers:
        handler.setLevel(infoLevel)

The inspiration came from the fact that the basicConfig changes the root logger settings, so I was trying to do the same without using basicConfig.

For those that are interested, I did a little Python project on Github that illustrates the different issues with setting loglevel of the logger (it works partially), proves the SLogger (Sample Logger) implementation works, and also illustrates the duplicate log issue with basicConfig when using multiple loggers not initialised with it.

https://github.com/FrancisChung/python-logging-playground

TLDR: If you're only interested in a working sample code for the logger, the implentation is listed below

import logging

CRITICAL = 50
FATAL = CRITICAL
ERROR = 40
WARNING = 30
WARN = WARNING
INFO = 20
DEBUG = 10
NOTSET = 0


class SLogger():
    """
    SLogger : Sample Logger class using the standard Python logging Library

    Parameters:
        name        : Name of the Logger
        infoLevel   : logging level of the Logger (e.g. logging.DEBUG/INFO/WARNING/ERROR)
    """

    def __init__(self, name: str, infoLevel=logging.INFO):
        try:
            if name is None:
                raise ValueError("Name argument not specified")

            logformat = '%(asctime)s %(levelname)s [%(name)s %(funcName)s] %(message)s'
            self.logformat = logformat
            self.name = name.upper()
            self.logger = logging.getLogger(self.name)
            self.logger.setLevel(infoLevel)

            self.add_consolehandler(infoLevel, logformat)

        except Exception as e:
            if self.logger:
                self.logger.error(str(e))

    def error(self, message):
        self.logger.error(message)

    def info(self, message):
        self.logger.info(message)

    def warning(self, message):
        self.logger.warning(message)

    def debug(self, message):
        self.logger.debug(message)

    def critical(self, message):
        self.logger.critical(message)

    def setLevel(self, infoLevel):
        # To dynamically reset the loglevel, you need to also change the parent levels as well as all handlers!
        self.logger.parent.setLevel(infoLevel)
        for handler in self.logger.parent.handlers:
            handler.setLevel(infoLevel)

        self.logger.setLevel(infoLevel)
        for handler in self.logger.handlers:
            handler.setLevel(infoLevel)

        return self.logger.level

    def add_consolehandler(self, infoLevel=logging.INFO,
                           logformat='%(asctime)s %(levelname)s [%(name)s %(funcName)s] %(message)s'):
        sh = logging.StreamHandler()
        sh.setLevel(infoLevel)

        formatter = logging.Formatter(logformat)
        sh.setFormatter(formatter)
        self.logger.addHandler(sh)

Reviviscence

Answer 10

Create object the right way, e.g. inspired by Google:

import logging

formatter = logging.Formatter('%(asctime)s %(threadName)s: %(message)s')
log = logging.getLogger(__name__)
log.setLevel(logging.DEBUG)

handler = logging.StreamHandler()
handler.setFormatter(formatter)
log.addHandler(handler)

log.debug('debug message')
log.info('info message')
log.warn('warn message')
log.error('error message')
log.critical('critical message')

2022-11-22 23:17:59,342 MainThread: debug message
2022-11-22 23:17:59,342 MainThread: info message
2022-11-22 23:17:59,342 MainThread: warn message
2022-11-22 23:17:59,342 MainThread: error message
2022-11-22 23:17:59,342 MainThread: critical message

Microscopy

Answer 11

As pointed out by @ManuelFedele, logging.basicConfig is not a good solution.

@VinaySajip explained that the setLevel is ignored because the logger is using the internal handler "of last resort", whose level is set to WARNING.

This explanation was also helpful:

The Handler.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.

So a good solution is to add a handler to the logger, with the appropriate level:

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)  # or whatever level should be displayed on the console
logger.addHandler(ch)

Output

>>> logger.debug('debug message')
debug message
>>> logger.info('info message')
info message
>>> logger.warn('warn message')
<stdin>:1: DeprecationWarning: The 'warn' method is deprecated, use 'warning' instead
warn message
>>> logger.error('error message')
error message
>>> logger.critical('critical message')
critical message

Vandervelde

Answer 12

Simply below code works for me :

import logging
logging.basicConfig(format='%(asctime)s %(message)s')
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')   #warn  --> warning as The 'warn' method is deprecated, use 'warning' instead
logger.error('error message')
logger.critical('critical message')

Nappy