how to replace print debug message with the logging module

Question

Up to now, I've been peppering my code with 'print debug message' and even 'if condition: print debug message'. But a number of people have told me that's not the best way to do it, and I really should learn how to use the logging module. After a quick read, it looks as though it does everything I could possibly want, and then some. It looks like a learning project in its own right, and I want to work on other projects now and simply use the minimum functionality to help me. If it makes any difference, I am on python 2.6 and will be for the forseeable future, due to library and legacy compatibilities.

All I want to do at the moment is pepper my code with messages that I can turn on and off section by section, as I manage to debug specific regions. As a 'hello_log_world', I tried this, and it doesn't do what I expected

import logging

# logging.basicConfig(level=logging.DEBUG)

logging.error('first error')
logging.debug('first debug')

logging.basicConfig(level=logging.DEBUG)

logging.error('second error')
logging.debug('second debug')

You'll notice I'm using the really basic config, using as many defaults as possible, to keep things simple. But appears that it's too simple, or that I don't understand the programming model behind logging.

I had expected that sys.stderr would end up with

ERROR:root:first error
ERROR:root:second error
DEBUG:root:second debug

... but only the two error messages appear. Setting level=DEBUG doesn't make the second one appear. If I uncomment the basicConfig call at the start of the program, all four get output.

Am I trying to run it at too simple a level?

What's the simplest thing I can add to what I've written there to get my expected behaviour?

RocketDonkey · Accepted Answer · 2012-10-29T07:23:45.160

Logging actually follows a particular hierarchy (DEBUG -> INFO -> WARNING -> ERROR -> CRITICAL), and the default level is WARNING. Therefore the reason you see the two ERROR messages is because it is ahead of WARNING on the hierarchy chain.

As for the odd commenting behavior, the explanation is found in the logging docs (which as you say are a task unto themselves :) ):

The call to basicConfig() should come before any calls to debug(), info() etc. As it’s intended as a one-off simple configuration facility, only the first call will actually do anything: subsequent calls are effectively no-ops.

However you can use the setLevel parameter to get what you desire:

import logging

logging.getLogger().setLevel(logging.ERROR)

logging.error('first error')
logging.debug('first debug')

logging.getLogger().setLevel(logging.DEBUG)

logging.error('second error')
logging.debug('second debug')

The lack of an argument to getLogger() means that the root logger is modified. This is essentially one step before @del's (good) answer, where you start getting into multiple loggers, each with their own specific properties/output levels/etc.

Thanks, that works as I'd like it to work. I hadn't clicked that the call to basicConfig() was a one-shot. However, I think it's more subtle than that. I suspect that on the first use of the logging module by my statement "logging.error('first error')", the module does an implicit call to basicConfig() with defaults, which means that the explicit call between the first and second errors is ineffective. This is sort of gateway code. Once I've been seduced by setting the levels, then formatting, I'll be into multiple loggers before too long. — Neil_UK, Oct 29 '12 at 19:56
@Neil_UK I think you're spot on :) Gateway code is a good term, you should trademark it. Definitely a useful feature to be able to handle logging with multiple loggers (that can write to `stdout`, a file, or both, etc.). One thing I have always found interesting (when it comes to logging in terms of debugging) is that Ken Thompson gets by with mostly `print` statements :) http://jmprog.blogspot.com/2009/11/ken-thompson-about-debugging-with.html — RocketDonkey, Oct 29 '12 at 20:00

score 1 · Answer 2 · answered Oct 29 '12 at 06:19

Rather than modifying the logging levels in your code to control the output, you should consider creating multiple loggers, and setting the logging level for each one individually. For example:

import logging

first_logger = logging.getLogger('first')
second_logger = logging.getLogger('second')

logging.basicConfig()
first_logger.setLevel(logging.ERROR)
second_logger.setLevel(logging.DEBUG)

first_logger.error('first error')
first_logger.debug('first debug')

second_logger.error('second error')
second_logger.debug('second debug')

This outputs:

ERROR:first:first error
ERROR:second:second error
DEBUG:second:second debug

how to replace print debug message with the logging module

2 Answers2