Navigation
Voterbox
Python Dual Output / Logging
Summary
This article talks about setting up the Python Logger to easily provide dual output logging to console and a log file. In many ways, this is very much like the Ruby Dual Output / Logging article I wrote not long ago.
Python logging is not a difficult process, however it did take some digging around to get it to work the way I really wanted it to.
The Python Logger module was not available in the standard library until version 2.3. Those using Python < 2.3 may be able to use the original source.
Logging to Console
The most general logging available is to console, or STDOUT/STDERR. You may say 'why not just print rather than go to the trouble of logging to console'. Well.. for a basic script, using a logging facility just for standard console output isn't really all that necessary. However there are a lot of things you can do such as add Formatter and Filter Objects amongst many other things.
The following is a basic setup of Logger just for console output.
test_logger.py:
#!/usr/bin/env python
import logging
log = logging.getLogger()
ch = logging.StreamHandler()
log.addHandler(ch)
log.debug('this is a debug message')
log.info('this is an informational message')
log.warning('this is a warning message')
log.error('this is an error message')
log.critical('this is a critical message')The 'ch' object is our 'console handler', and does nothing until we use the 'addHandler' method on our 'log' object. Running this code produces:
[wdierkes] $ python test_logger.py
this is a warning message
this is an error message
this is a critical messageNotice that we attempted to log to all of the default facilities [debug(), info(), warning(), error(), and critical()]. However logging only started at warning (the default). To alter our logging level we need to tell logger about it. I personally generally go with DEBUG or INFO. Adding just a tad of code can do this for us:
test_logger.py:
debug = True
if debug:
log.setLevel(logging.DEBUG)
else:
log.setLevel(logging.INFO)Now running our script (with debug enabled) we see all facilities in action:
[wdierkes] $ python test_logger.py
this is a debug message
this is an informational message
this is a warning message
this is an error message
this is a critical messageLogging to a File
Logging to console is awesome, and I'm real excited about it... but really having a log file is much more common. Therefore, we are going to extend this code to not only log to console for our user, but also to a log file. Notice that we are creating a new Handler called 'fh' ('file handler') and adding it to our Logger.
test_logger.py:
#!/usr/bin/env python
import logging
import sys, os
debug = None
log_file = './log/test_logger.log'
log = logging.getLogger()
ch = logging.StreamHandler()
if os.path.exists(os.path.dirname(log_file)):
fh = logging.FileHandler(log_file)
else:
raise "log directory does not exist (" + os.path.dirname(log_file) + ")"
sys.exit(1)
log.addHandler(ch)
log.addHandler(fh)
if debug:
log.setLevel(logging.DEBUG)
else:
log.setLevel(logging.INFO)
log.debug('this is a debug message')
log.info('this is an informational message')
log.warning('this is a warning message')
log.error('this is an error message')
log.critical('this is a critical message')Now, what we see at console is also logged to './log/test_logger.log' (I turned debug off by the way):
[wdierkes] $ python test_logger.py
this is an informational message
this is a warning message
this is an error message
this is a critical message
[wdierkes] $ cat log/test_logger.log
this is an informational message
this is a warning message
this is an error message
this is a critical messageLooking good... real solid!
Adding Formatter Objects
Alright, so everything is coming together, but I have to tell you ... your logging looks like absolute crap. So lets add some formatters to make this thang a little bit easier on the eyes.
The Formatter Objects allow you a lot of control over how your logger looks.
Formatters have the following attributes and methods. They are responsible for converting a LogRecord to (usually) a string which can be interpreted by either a human or an external system. The base Formatter allows a formatting string to be specified. If none is supplied, the default value of '%(message)s' is used.
In my own scripts, I like the console output to be very simple. At the most I will add the logging facility (INFO, DEBUG, ERROR... etc) to clarify what exactly is going on. However, in my logs I want a lot more information. I want to know who did what at what time... and all that jazz. Take a look at the modified script and how we add Formatter Objects:
test_logger.py
#!/usr/bin/env python
import logging
import sys, os
debug = None
log_file = './log/test_logger.log'
log = logging.getLogger()
ch = logging.StreamHandler()
if os.path.exists(os.path.dirname(log_file)):
fh = logging.FileHandler(log_file)
else:
raise "log directory does not exist (" + os.path.dirname(log_file) + ")"
sys.exit(1)
log.addHandler(ch)
log.addHandler(fh)
ch_fmt = logging.Formatter("%(levelname)s\t: %(message)s")
fh_fmt = logging.Formatter("%(asctime)s %(process)d (%(levelname)s)\t: %(message)s")
ch.setFormatter(ch_fmt)
fh.setFormatter(fh_fmt)
if debug:
log.setLevel(logging.DEBUG)
else:
log.setLevel(logging.INFO)
log.debug('this is a debug message')
log.info('this is an informational message')
log.warning('this is a warning message')
log.error('this is an error message')
log.critical('this is a critical message')And our output is going to come out as:
[wdierkes] $ python test_logger.py
INFO : this is an informational message
WARNING : this is a warning message
ERROR : this is an error message
CRITICAL : this is a critical message
[wdierkes] $ cat log/test_logger.log
2007-09-23 18:20:58,924 372 (INFO) : this is an informational message
2007-09-23 18:20:58,925 372 (WARNING) : this is a warning message
2007-09-23 18:20:58,925 372 (ERROR) : this is an error message
2007-09-23 18:20:58,926 372 (CRITICAL) : this is a critical messageNote the '\t' was added to create a 'tab' space in the output (I find that things that line up look much cleaner)... you may also find that this doesn't always give you the results you expected. Regardless, you get the idea how you can spice up the logger a bit. The Documentation on the Formatter Object gives more than enough to work with to make your's the way you want it.
Reference
Python Logger: http://docs.python.org/lib/module-logging.html