Python using basicConfig method to log to console and file

Question

I don't know why this code prints to the screen, but not to the file? File "example1.log" is created, but nothing is written there.

#!/usr/bin/env python3
import logging

logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(message)s',
                    handlers=[logging.FileHandler("example1.log"),
                              logging.StreamHandler()])
logging.debug('This message should go to the log file and to the console')
logging.info('So should this')
logging.warning('And this, too')

I have "bypassed" this problem by creating a logging object, but it keeps bugging me why basicConfig() approach failed?

PS. If I change basicConfig call to:

logging.basicConfig(level=logging.DEBUG,
                    filename="example2.log",
                    format='%(asctime)s %(message)s',
                    handlers=[logging.StreamHandler()])

then all logs are in the file and nothing is displayed in the console.

Solution 1

I can't reproduce it on Python 3.3. The messages are written both to the screen and the 'example2.log'. On Python <3.3 it creates the file but it is empty.

The code:

from logging_tree import printout  # pip install logging_tree
printout()

shows that FileHandler() is not attached to the root logger on Python <3.3.

The docs for logging.basicConfig() say that handlers argument is added in Python 3.3. The handlers argument isn't mentioned in Python 3.2 documentation.

Solution 2

Try this working fine(tested in python 2.7) for both console and file

# set up logging to file
logging.basicConfig(
     filename='log_file_name.log',
     level=logging.INFO, 
     format= '[%(asctime)s] {%(pathname)s:%(lineno)d} %(levelname)s - %(message)s',
     datefmt='%H:%M:%S'
 )

# set up logging to console
console = logging.StreamHandler()
console.setLevel(logging.DEBUG)
# set a format which is simpler for console use
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger('').addHandler(console)

logger = logging.getLogger(__name__)

Solution 3

In the example below, you can specify the log destination based on its level. For example, the code below lets all logs over the INFO level go to the log file, and all above ERROR level goes to the console.

import logging
logging.root.handlers = []
logging.basicConfig(format='%(asctime)s : %(levelname)s : %(message)s', level=logging.INFO , filename='ex.log')

# set up logging to console
console = logging.StreamHandler()
console.setLevel(logging.ERROR)
# set a format which is simpler for console use
formatter = logging.Formatter('%(asctime)s : %(levelname)s : %(message)s')
console.setFormatter(formatter)
logging.getLogger("").addHandler(console)

logging.debug('debug')
logging.info('info')
logging.warning('warning')
logging.error('error')
logging.exception('exp')

Solution 4

Another technique using the basicConfig is to setup all your handlers in the statement and retrieve them after the fact, as in...

import logging

logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(levelname)s %(module)s %(funcName)s %(message)s',
                    handlers=[logging.FileHandler("my_log.log", mode='w'),
                              logging.StreamHandler()])
stream_handler = [h for h in logging.root.handlers if isinstance(h , logging.StreamHandler)][0]
stream_handler.setLevel(logging.INFO)

More sensibly though is to construct your stream handler instance outside and configure them as standalone objects that you pass to the handlers list as in...

import logging

stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.INFO)

logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(levelname)s %(module)s %(funcName)s %(message)s',
                    handlers=[logging.FileHandler("my_log.log", mode='w'),
                              stream_handler])

Solution 5

WOOAH!

I just spent about 20 minutes being baffled by this.

Eventually I worked out that the StreamHandler was outputting to stderr, not stdout (in a 'Doze DOS screen these have the same font colour!).

This resulted in me being able to run the code perfectly OK and get sensible results, but in a pytest function things going awry. Until I changed from this:

out, _ = capsys.readouterr()
assert 'test message check on console' in out, f'out was |{out}|'

to this:

_, err = capsys.readouterr()
assert 'test message check on console' in err, f'err was |{err}|'

NB the constructor of StreamHandler is

class logging.StreamHandler(stream=None)

and, as the docs say, "If stream is specified, the instance will use it for logging output; otherwise, sys.stderr will be used."

NB it seems that supplying the level keyword does not run setLevel on the handlers: you'd need to iterate on the resulting handlers and run setLevel on each, if it matters to you.

View more solutions

Comments

[Jovik]

You're right! However, shouldn't I get exception when using unsupported features? It's a shame to admit how much time I have wasted on this...

[jfs]

@Jovik: there is probably some logic behind though I don't see it at the moment. You could try to report it at bugs.python.org

[wjimenez5271]

@Jovik I think the lack of exception is by design, something unique to the logger library. See excerpt from 2x doc: "The logging package is designed to swallow exceptions which occur while logging in production. This is so that errors which occur while handling logging events - such as logging misconfiguration, network or other similar errors - do not cause the application using logging to terminate prematurely."

[jfs]

@wjimenez5271: it is not entirely correct. If you look at the initial patch that fixes the issue opened by @Jovik then you see that it raises ValueError if unknown keyword arguments such as handlers on Python 3.2 are given. The current code may also raise ValueError (though for other reasons).