Use of the logging module

Python Help
1 
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

logger.debug("Debug") # do nothing
logger.info("Info") # do nothing
logger.warning("Warning") # print
logger.error("Error") # print
logger.critical("Critical") # print

The behavior also doesn’t change when setting the thing to logging.DEBUG. Why doesn’t it print the info ? What am I missing ?

2

logging.basicConfig()

3

The trouble is, I’m also using another library whose infos I don’t want to show. I would also like to show my debug messages, by setting my logger to debug, without being swarmed with that library’s debug messages - which is what happened when I tried using basicConfig.

4

I think they mean something like this:

auxiliary_module.py

# create logger
module_logger = logging.getLogger('spam_application.auxiliary')
module_logger.setLevel(logging.DEBUG)

class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
        self.logger.debug('creating an instance of Auxiliary')

    def do_something(self):
        self.logger.debug('doing something')
        a = 1 + 1
        self.logger.debug('done doing something')

def some_function():
    module_logger.debug('received a call to "some_function"')

main.py

import logging
import auxiliary_module
from auxiliary_module import Auxiliary

logging.basicConfig()

a = Auxiliary()
a.do_something()
auxiliary_module.some_function()

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

logger.debug("Debug") # do nothing
logger.info("Info") # do nothing
logger.warning("Warning") # print
logger.error("Error") # print
logger.critical("Critical") # print

It prints

DEBUG:spam_application.auxiliary.Auxiliary:creating an instance of Auxiliary
DEBUG:spam_application.auxiliary.Auxiliary:doing something
DEBUG:spam_application.auxiliary.Auxiliary:done doing something
DEBUG:spam_application.auxiliary:received a call to "some_function"
INFO:__main__:Info
WARNING:__main__:Warning
ERROR:__main__:Error
CRITICAL:__main__:Critical
5

Pretty much, yes. Apart from the fact that the auxillary logger is set on default WARNING level, and using the basicConfig way in my main file makes it produce all that INFO or DEBUG I don’t want to see in ordinary conditions, as I believe is its normal behavior.

What I don’t understand is why triggering a .info() on a logger which I specifically set to INFO or even to DEBUG, doesn’t do anything. Isn’t that what the doc says is supposed to work ? Cutting the parts about formatters and handlers I don’t need to customize. In your example, you show the “Info” being printed, but I don’t see that on my end.

6

In case things have changed between versions, the output above was with Python 3.10.6 and logging version 0.5.1.2.

Also, take a look at this flow chart. I don’t know what exactly is done in your code, but note that involved in the mix are handlers of each logger and the hierarchy of loggers that your application is using. See how the level of each logger tells when the LogRecord is passed around, and the level of each handler the one that determines which LogRecords that it receives get emitted.

Note also the argument force of basicConfig, in case the time when you are calling this method is not the first time that this method is called.

7

Ok, I think I got it, sort of. The difference is the no-args call to logging.basicConfig(), which I missed in your code - but it still doesn’t totally make sense either.
Here’s my code:

# auxiliary
import logging

# create logger
module_logger = logging.getLogger('spam_application.auxiliary')
module_logger.setLevel(logging.ERROR)

def some_function():
    module_logger.debug("Debug")
    module_logger.info("Info")
    module_logger.warning("Warning")
    module_logger.error("Error")
    module_logger.critical("Critical")

# main
import logging
import auxiliary

logging.basicConfig() # this bad boy right here

auxiliary.some_function()

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

logger.debug("Debug")
logger.info("Info")
logger.warning("Warning")
logger.error("Error")
logger.critical("Critical")

The behavior is as follows, first without the line, and then with it :

PS E:\dev\gouvernabot> py .\main.py
Error
Critical
Warning
Error
Critical
PS E:\dev\gouvernabot> py .\main.py
ERROR:spam_application.auxiliary:Error
CRITICAL:spam_application.auxiliary:Critical
INFO:__main__:Info
WARNING:__main__:Warning
ERROR:__main__:Error
CRITICAL:__main__:Critical

In the first case, the main logger configuration is ignored but the auxiliary one is not : for some reason, the auxiliary module’s warning is not shown. Wth.
Anyway I tested the no-args version and it seems to work in my real code, thanks !

8

Without the basicConfig() line:

  • The root logger has default logging level WARNING and has no handlers.
  • The two loggers that you create don’t have handlers and their propagate attribute is True.

Following the flowchart above, each LogRecord bubbles up to the root logger. The module_logger only lets records of levels ERROR and above to pass through. The logger in main passes all LogRecord from INFO and above to the upstairs.
The root logger doesn’t have handlers, but there is a “handler of last resort” in logging that has level WARNING.

>>> logging.lastResort
<_StderrHandler <stderr> (WARNING)>

So, all the records that got to root of level WARNING and above get printed.

You can see their insides here

>>> import logging
>>> module_logger = logging.getLogger('spam_application.auxiliary')
>>> module_logger.setLevel(logging.ERROR)
>>> module_logger.__dict__
{'filters': [], 'name': 'spam_application.auxiliary', 'level': 40, 'parent': <RootLogger root (WARNING)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f933e210400>}
>>> module_logger.parent.__dict__
{'filters': [], 'name': 'root', 'level': 30, 'parent': None, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}}
>>> logger = logging.getLogger('__main__')
>>> logger.setLevel(logging.INFO)
>>> logger.__dict__
{'filters': [], 'name': '__main__', 'level': 20, 'parent': <RootLogger root (WARNING)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f933e210400>}

With the basicConfig() line: The root logger gets a handler StreamHandler to stderr. This handler has level NOTSET. The loggers module_logger and logger (from main) are as above. The same LogRecords as before are created and bubbled up to the root logger. However, this one has now a handler and this handler (with its NOTSET level) puts all messages that it receives to stderr.

>>> import logging
>>> module_logger = logging.getLogger('spam_application.auxiliary')
>>> module_logger.setLevel(logging.ERROR)
>>> logging.basicConfig()
>>> module_logger.__dict__
{'filters': [], 'name': 'spam_application.auxiliary', 'level': 40, 'parent': <RootLogger root (WARNING)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f7c29e34400>}
>>> module_logger.parent.__dict__
{'filters': [], 'name': 'root', 'level': 30, 'parent': None, 'propagate': True, 'handlers': [<StreamHandler <stderr> (NOTSET)>], 'disabled': False, '_cache': {}}
>>> logger = logging.getLogger('__main__')
>>> logger.setLevel(logging.INFO)
>>> logger.__dict__
{'filters': [], 'name': '__main__', 'level': 20, 'parent': <RootLogger root (WARNING)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f7c29e34400>}

The root logger’s handler comes with a formatter too. This is why now the messages have different style

>>> module_logger.parent.handlers[0].formatter._fmt
'%(levelname)s:%(name)s:%(message)s'

The last resort handler didn’t have a formatter

>>> logging.lastResort.__dict__
{'filters': [], '_name': None, 'level': 30, 'formatter': None, '_closed': False, 'lock': <unlocked _thread.RLock object owner=0 count=0 at 0x7f99c8b77c40>}