This is a guide on the logging module

logging.md

Introduction

The logging module can make your life easier especially when writing a multi-threaded program. It will help generate a .log file so you can make ex-post controls. You can also use it for debugging.

Example

script.py :

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging
import threading
 
def get_logger():
    logger = logging.getLogger("threading_example")
    logger.setLevel(logging.DEBUG)

    fh = logging.FileHandler("threading.log")
    fmt = '%(asctime)s - %(threadName)s - %(levelname)s - %(message)s'
    formatter = logging.Formatter(fmt)
    fh.setFormatter(formatter)

    logger.addHandler(fh)
    return logger


def doubler(number, logger):
    """
    A function that can be used by a thread
    """
    logger.debug('doubler function executing')

    result = number * 2
    logger.debug('doubler function ended with: {}'.format(result))

 
if __name__ == '__main__':
    logger = get_logger()
    thread_names = ['Mike', 'George', 'Wanda', 'Dingbat', 'Nina']
    for i in range(5):
        my_thread = threading.Thread(target=doubler, name=thread_names[i], args=(i,logger))
        my_thread.start()

In the above example, the script launches five threads. It will perform instructions contained in the doubler function.

These lines will define threads :

for i in range(5):
	my_thread = threading.Thread(target=doubler, name=thread_names[i], args=(i,logger))
	my_thread.start()

As you can read, not only do we target a function using target=doubler but we pass a logger object within arguments args=(i,logger). The logger object is created with logger = get_logger() where get_logger() is a custom function where we define the behaviour and the format of the logger.

If we analyse get_logger() :

def get_logger():
    logger = logging.getLogger("threading_example")
    logger.setLevel(logging.DEBUG)

    fh = logging.FileHandler("threading.log")
    fmt = '%(asctime)s - %(threadName)s - %(levelname)s - %(message)s'
    formatter = logging.Formatter(fmt)
    fh.setFormatter(formatter)

    logger.addHandler(fh)
    return logger

It is worth noting the logger's level is set at DEBUG so it writes everything. In the following line, we define the format. %(message)s will contain messages sent by threads. Finally, this function returns the logger object.

The doubler function is the threads' target :

def doubler(number, logger):
    """
    A function that can be used by a thread
    """
    logger.debug('doubler function executing')

    result = number * 2
    logger.debug('doubler function ended with: {}'.format(result))

The code is neat. logger.debug() is in charge of intercepting messages in behalf of get_logger().

threading.log :

2016-10-26 14:36:00,916 - Mike - DEBUG - doubler function executing
2016-10-26 14:36:00,916 - Mike - DEBUG - doubler function ended with: 0
2016-10-26 14:36:00,916 - George - DEBUG - doubler function executing
2016-10-26 14:36:00,917 - George - DEBUG - doubler function ended with: 2
2016-10-26 14:36:00,917 - Wanda - DEBUG - doubler function executing
2016-10-26 14:36:00,917 - Wanda - DEBUG - doubler function ended with: 4
2016-10-26 14:36:00,917 - Dingbat - DEBUG - doubler function executing
2016-10-26 14:36:00,917 - Dingbat - DEBUG - doubler function ended with: 6
2016-10-26 14:36:00,917 - Nina - DEBUG - doubler function executing
2016-10-26 14:36:00,917 - Nina - DEBUG - doubler function ended with: 8

As you can read, everything is executed in parralel at 14:36:00,917 !

Perhaps you prefer installing a logging system in class-based program :

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging
import threading

class MyThread(threading.Thread):
 
    def __init__(self, number, logger):
        threading.Thread.__init__(self)
        self.number = number
        self.logger = logger
 
    def run(self):
        """
        Run the thread
        """

        logger.debug('Calling doubler')
        doubler(self.number, self.logger)
        
 
 
def get_logger():
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.DEBUG)

    fh = logging.FileHandler("threading_class.log")
    fmt = '%(asctime)s : %(threadName)s : %(levelname)s : %(message)s'
    formatter = logging.Formatter(fmt)
    fh.setFormatter(formatter)
    logger.addHandler(fh)
    return logger
 
 
def doubler(number, logger):
    """
    A function that can be used by a thread
    """
    logger.info('doubler function executing')
    result = number * 2

    logger.debug('doubler function ended with: {}'.format(result))
    
 
if __name__ == '__main__':
    logger = get_logger()
    thread_names = ['Mike', 'George', 'Wanda', 'Dingbat', 'Nina']
    for i in range(5):
        thread = MyThread(i, logger)
        thread.setName(thread_names[i])
        thread.start()

Note that we can use the .setName() method.

A good convention to use when naming loggers is to use a module-level logger, in each module which uses logging, named as follows:

logger = logging.getLogger(__name__)

This means that logger names track the package/module hierarchy, and it’s intuitively obvious where events are logged just from the logger name.

Source : Michael Driscoll. « Python 201. »