Python logging before you run logging.basicConfig?

Question

It appears that if you invoke logging.info() BEFORE you run logging.basicConfig, the logging.basicConfig call doesn't have any effect. In fact, no logging occurs.

Where is this behavior documented? I don't really understand.

Cinerary

For python >= 3.8 basicConfig has a "force" argument that can be used to solve this. – Farthest

note that the "force" argument can reset logging config on the root logger set by other modules, but if you have already instantiated any non-root loggers with eg logger = logging.getLogger(__name__) then it's too late to reconfigure those, even with force. the only solution really is to do your logging config right at the top of the file, by the imports. – Fidellia

Answer 1

You can remove the default handlers and reconfigure logging like this:

# if someone tried to log something before basicConfig is called, Python creates a default handler that
# goes to the console and will ignore further basicConfig calls. Remove the handler if there is one.
root = logging.getLogger()
if root.handlers:
    for handler in root.handlers:
        root.removeHandler(handler)
logging.basicConfig(format='%(asctime)s %(message)s',level=logging.DEBUG)

Fleshpots

To be used verbatim. If you -like me- tried to reuse a previous logger instantiated like this: logger = logging.getLogger(__name__) and try to loop in logger.handlers it would not work. – Chilung

What's the "if root.handlers:" good for? Iterating an empty sequence has no effect. Is it possible that root.handlers is some other, non-sequence false value? (It isn't on my system) – Integral

Came in handy for debugging logging issue with AWS Lambdas. Looks like they install some handler with name LambdaLoggingHandler during lambda bootstrapping. Removing installed handler solved the problem. – Nabob

Answer 2

Yes.

You've asked to log something. Logging must, therefore, fabricate a default configuration. Once logging is configured... well... it's configured.

"With the logger object configured, the following methods create log messages:"

Further, you can read about creating handlers to prevent spurious logging. But that's more a hack for bad implementation than a useful technique.

There's a trick to this.

1. No module can do anything except logging.getLogger() requests at a global level.

2. Only the if __name__ == "__main__": can do a logging configuration.

If you do logging at a global level in a module, then you may force logging to fabricate it's default configuration.

Don't do logging.info globally in any module. If you absolutely think that you must have logging.info at a global level in a module, then you have to configure logging before doing imports. This leads to unpleasant-looking scripts.

Gutturalize

No, I was wrong - apparently this is by design as basicConfig is called from .info et al to ensure a logger is installed. It still seems like odd behaviour to me. – Tilbury

At a global level, if a module uses logging.getLogger() then its WARNING and ERROR are written to stderr, but INFO are just discarded! I guess this behavior makes sense, but it might not be a good trade-off in your app. – Beal

I'm not sure what the right approach is -- I guess any function that needs logging is probably because it has side effects, and it's better to avoid side effects during module import. – Beal

Answer 3

This answer from Carlos A. Ibarra is in principle right, however that implementation might break since you are iterating over a list that might be changed by calling removeHandler(). This is unsafe. Two alternatives are:

while len(logging.root.handlers) > 0:
    logging.root.removeHandler(logging.root.handlers[-1])
logging.basicConfig(format='%(asctime)s %(message)s',level=logging.DEBUG)

or:

logging.root.handlers = []
logging.basicConfig(format='%(asctime)s %(message)s',level=logging.DEBUG)

where the first of these two using the loop is the safest (since any destruction code for the handler can be called explicitly inside the logging framework). Still, this is a hack, since we rely on logging.root.handlers to be a list.

Cavill

could also do list(logging.root.handlers) to make a copy – Deletion

Answer 4

Here's the one piece of the puzzle that the above answers didn't mention... and then it will all make sense: the "root" logger -- which is used if you call, say, logging.info() before logging.basicConfig(level=logging.DEBUG) -- has a default logging level of WARNING.

That's why logging.info() and logging.debug() don't do anything: because you've configured them not to, by... um... not configuring them.

Possibly related (this one bit me): when NOT calling basicConfig, I didn't seem to be getting my debug messages, even though I set my handlers to DEBUG level. After a bit of hair-pulling, I found you have to set the level of the custom logger to be DEBUG as well. If your logger is set to WARNING, then setting a handler to DEBUG (by itself) won't get you any output on logger.info() and logger.debug().

Kishakishinev

Answer 5

Ran into this same issue today and, as an alternative to the answers above, here's my solution.

import logging
import sys

logging.debug('foo') # IRL, this call is from an imported module

if __name__ == '__main__':
    logging.basicConfig(level=logging.INFO, force=True)
    logging.info('bar') # without force=True, this is not printed to the console

Here's what the docs say about the force argument.

If this keyword argument is specified as true, any existing handlers attached to the root logger are removed and closed, before carrying out the configuration as specified by the other arguments.

Barkeeper

This is the correct, modern solution - but it only works for Python >=3.8 – Farthest

Answer 6

A cleaner version of the answer given by @paul-kremer is:

while len(logging.root.handlers):
    logging.root.removeHandler(logging.root.handlers[-1])

Note: it is generally safe to assume logging.root.handlers will always be a list (see: https://github.com/python/cpython/blob/cebe9ee988837b292f2c571e194ed11e7cd4abbb/Lib/logging/init.py#L1253)

Topsyturvydom

Answer 7

Here is what I did.

I wanted to log to a file which has a name configured in a config-file and also get the debug-logs of the config-parsing.

TL;DR; This logs into a buffer until everything to configure the logger is available

# Log everything into a MemoryHandler until the real logger is ready.
# The MemoryHandler never flushes (flushLevel 100 is above CRITICAL) automatically but only on close.
# If the configuration was loaded successfully, the real logger is configured and set as target of the MemoryHandler
# before it gets flushed by closing.
# This means, that if the log gets to stdout, it is unfiltered by level
root_logger = logging.getLogger()
root_logger.setLevel(logging.NOTSET)
stdout_logging_handler = logging.StreamHandler(sys.stderr)
tmp_logging_handler = logging.handlers.MemoryHandler(1024 * 1024, 100, stdout_logging_handler)
root_logger.addHandler(tmp_logging_handler)

config: ApplicationConfig = ApplicationConfig.from_filename('config.ini')

# because the records are already logged, unwanted ones need to be removed
filtered_buffer = filter(lambda record: record.levelno >= config.main_config.log_level, tmp_logging_handler.buffer)
tmp_logging_handler.buffer = filtered_buffer

root_logger.removeHandler(tmp_logging_handler)
logging.basicConfig(filename=config.main_config.log_filename, level=config.main_config.log_level, filemode='wt')
logging_handler = root_logger.handlers[0]
tmp_logging_handler.setTarget(logging_handler)
tmp_logging_handler.close()
stdout_logging_handler.close()

Subinfeudation