logging module

Date: January 18th 2016
Last updated: January 18th 2016

The logging module is a large package of useful tools. The logging module lets a developer track important events. For basic usage see this how-to article. The logged output can be used in a similar way to using print to debug your code. But, provides a lot more control and adds flexibility to developing a program.

# if not installed
pip install logging

The basic functions of the logging module:

• logging.debug() --------> Level 10: detailed reporting
• logging.info() --------> Level 20: status reporting
• logging.warning() --------> Level 30: indicate future problems
• logging.error() --------> Level 40: function failure
• logging.critical() --------> Level 50: program failure

The numeric logging levels refer to severity (low 10 to high 50). The logging module acts according to these levels. The default level is WARNING (30); only events of this level or higher will be tracked. The severity levels are callable by DEBUG, INFO, WARNING, ERROR, CRITICAL.

To change the logging level:

# reduce default level to INFO (Level 20)
logging.getLogger().setLevel(logging.INFO)

Simple example switching between DEBUG and INFO:

# test_logging_module.py
import logging

# switch for changing logging level severity
# logging.basicConfig(level=logging.INFO) # <===== (A) INFO
logging.basicConfig(level=logging.DEBUG) # <===== (B) DEBUG

# instantiate logging module
logger = logging.getLogger(__name__)

# Logging level = INFO
logger.info('Read in datafile')
# <---- read data ---->

#Logging level = DEBUG
firstname = 'Ray'
logger.debug('First name: %s', firstname)


# Logging level = INFO
logger.info('Updating records ...')
# <---- update records here ---->

logger.info('Finished with datafile')

Output at INFO severity level:

INFO:__main__:Read in datafile
INFO:__main__:Update datafile ...
INFO:__main__:Finished with datafile

Output at DEBUG severity level:

# comment out line (A) INFO
# uncomment line (B) DEBUG

INFO:__main__:Read in datafile
DEBUG:__main__:First name: Ray  --------- DEBUG
INFO:__main__:Update datafile ...
INFO:__main__:Finished with datafile

Logging to file:

# modify logging.basicConfig() to include filename
logging.basicConfig(filename='example.log', level=logging.DEBUG) 

# output to console: Nothing
# output to example.log: as printed above

# Note: all lines written to filename are appended each 
# time the script is run.

Output written to example.log:

# read file to terminal
cat example.log

INFO:__main__:Read in datafile
DEBUG:__main__:First name: Ray
INFO:__main__:Update datafile ...
INFO:__main__:Finished with datafile

Add time stamps to each message:

# modify logging.basicConfig() to include timestamp
# The %(asctime)s is responsible for getting time
# The datefmt changes the timestamp to an easily read format
logging.basicConfig(filename='example.log', \
        format='%(asctime)s %(message)s', \
        datefmt='%m/%d/%Y %I:%M:%S %p', \
        level=logging.DEBUG) # ----------- DEBUG

# add time.sleep(10) prior to the last log
...
import time
time.sleep(10)
logger.info('Finished with datafile')

Output written to example.log:

01/18/2016 04:57:36 PM Read in datafile
01/18/2016 04:57:36 PM First name: Ray
01/18/2016 04:57:36 PM Update datafile ...
01/18/2016 04:57:46 PM Finished with datafile ---- 10 sec's later