Python Toolbox 1 : Logging

This is the first post in a series about internal and external Python modules. Today I am going to give a brief overview of the built in logging module.

The logging module is a core python module that was introduced in Python 2.3. There are 6 different logging levels (debug, info, warning, error, critical and fatal). You can also log an exception wich outputs a nice traceback. There are numerous output possibilities defined as handlers. The log information can for example be send to a file, an http server, the windows event log, an e-mail address, a stream and more. The logger can also be configured to log to a different output depending on the logging level. You could for example log to a file when the level is debug but you might want to receive an e-mail when a critical or fatal error occurs. In this post we will use a basic file logger and then create a rotating file logger. The rotating file logger will make a back-up of the logfile when it reaches a predefined maximum size.

As the following code shows, basic logging is easy to set up. In short it first imports the logging module. Then it intialize this module by calling the basicConfig method. According to the help the input parameters for this method are :

filename  Specifies that a FileHandler be created, using the specified filename,
          rather than a StreamHandler.
filemode  Specifies the mode to open the file, if filename is specified
          (if filemode is unspecified, it defaults to "a").
format    Use the specified format string for the handler.
datefmt   Use the specified date/time format.
level     Set the root logger level to the specified level.
stream    Use the specified stream to initialize the StreamHandler. Note that
          this argument is incompatible with 'filename' - if both are present,
          'stream' is ignored.

Then we test the different logging level and also deliberately throw an error to test the exception logging. At the end I added some clean up code because the logging module doesn't get unloaded between to test runs in some IDE's.

import logging

logging.basicConfig(filename='gissolved.log',
                    level=logging.DEBUG,
                    format='%(asctime)s %(levelname)s : %(message)s')

try:
    logging.debug('debug')
    logging.info('info')
    logging.warning('warning')
    logging.error('error')
    logging.critical('critical')
    logging.fatal('fatal')
    try:
        raise TypeError, 'Demo error'
    except TypeError:
        logging.exception('exception')
finally: ## close logger properly
    logging.shutdown()
    logging.getLogger(None).handlers = []

Ok now let's create a rotating file logger. To do this we not only import the logging module but also the sub module handlers and the class Formatter. Then we define the log path and create a logger object. Now its time to create the RotatingFileHandler that is defined in the handlers sub module. The parameters are the filename, the mode (defaults to 'a' which means append), maxBytes (max number of bytes before rollover occurs), backupCount (number of backup files that will be created as needed). Then we define a format for the handler and add it to the logger object. At last we set the logging level of our logger.

Now its time to test the logger. I've put the code in a loop in order to log more bytes then the predefined number of maximum bytes per logfile. Internally the rotating file logger first checks whether the max size will be reached by writing the current message to the logfile. If this is the case it closes the current file and adds a suffix to it, a new file with the message is then created. So in this case the first back-up file will be renamed to gissolved_rotate.log.1. The next back-up will then be named gissolved_rotate.log.2 and so on. Until the maximum number of back-up files is reached and the first back-up files gets overwritten. The file being written to is always the original gissolved_rotate.log. In the finally block the current handler is removed from our logger and the handler is closed. If you've defined multiple handlers for your logger you could loop over the logger.handlers and call their close method and then set the logger.handlers equal to an empty list like I did in the first example.

import logging
from logging import handlers, Formatter

try:
    log_path = 'gissolved_rotate.log'
    logger = logging.getLogger('gissolved')
    ## create a rotating file handler and add it to the logger
    handler = handlers.RotatingFileHandler(log_path,
                                           maxBytes=5000000,
                                           backupCount=4)
    log_format = Formatter("%(name)s %(asctime)s %(levelname)s : %(message)s")
    handler.setFormatter(log_format)
    logger.addHandler(handler)
    ## set the root logging level
    logger.setLevel(logging.DEBUG)
    
    for i in range(11000):
        ## write test logging
        logger.debug('debug')
        logger.info('info')
        logger.warning('warning')
        logger.critical('critical')
        logger.error('error')
        logger.fatal('fatal')
        
        try:
            raise TypeError, 'Demo error'
        except TypeError:
            logger.exception('exception')

        logger.info('next round ' + str(i))

finally: ## close logger properly
    logger.removeHandler(handler)
    handler.close()

If you've still have some questions, shoot and I'll try to answer them.