Python Logging Example

Sebastian VinciJanuary 11th, 2016Last Updated: January 9th, 2018

0 86 10 minutes read

Logging is a process through which an application pushes strings to a handler. That string should be a line containing information about the piece of code from which it was sent and the context in that moment.

It is a feature every application must have, and it’s as important as any other functionality you add to the application in question. It is the easiest way to know what your application is doing, how, how long does it take, etc.

Any application which is not logging, will be a real pain to maintain, for there is no easy way to tell if it’s working or not, and if it’s not, why.

Through the log, we should be able to know a lot of useful information about our application:

What is it doing?
How is it doing it?
How long does it take it?
Is it failing? Why?

1. The Theory

Python provides a module called logging which has some really useful tools and configurations. But before we jump into the code, let’s look around some concepts.

1.1. Log Levels

Log levels are the levels of severity of each log line. Is a good solution to differentiate errors from common information in our log files.

The logging module provides 5 levels of severity: DEBUG, INFO, WARNING, ERROR, CRITICAL. Python’s logging documentations defines each of them as:

DEBUG: Detailed information, typically of interest only when diagnosing problems.
INFO: Confirmation that things are working as expected.
WARNING: An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected.
ERROR: Due to a more serious problem, the software has not been able to perform some function.
CRITICAL: A serious error, indicating that the program itself may be unable to continue running.

Loggers can be configured to output only lines above a threshold, which is configured as the global log level of that logger.

1.2. Handlers

As we said, a logger is an object which outputs strings to a handler. The handler receives the record and processes it, which means, in some cases, output to a file, console or even by UDP.

The logging module provides some useful handlers, and of course you can extend them and create your own. A list with handlers provided by Python below:

StreamHandler: instances send messages to streams (file-like objects).
FileHandler: instances send messages to disk files.
BaseRotatingHandler: is the base class for handlers that rotate log files at a certain point. It is not meant to be instantiated directly. Instead, use RotatingFileHandler or TimedRotatingFileHandler.
RotatingFileHandler: instances send messages to disk files, with support for maximum log file sizes and log file rotation.
TimedRotatingFileHandler: instances send messages to disk files, rotating the log file at certain timed intervals.
SocketHandler: instances send messages to TCP/IP sockets. Since 3.4, Unix domain sockets are also supported.
DatagramHandler: instances send messages to UDP sockets. Since 3.4, Unix domain sockets are also supported.
SMTPHandler: instances send messages to a designated email address.
SysLogHandler: instances send messages to a Unix syslog daemon, possibly on a remote machine.
NTEventLogHandler: instances send messages to a Windows NT/2000/XP event log.
MemoryHandler: instances send messages to a buffer in memory, which is flushed whenever specific criteria are met.
HTTPHandler: instances send messages to an HTTP server using either GET or POST semantics.
WatchedFileHandler: instances watch the file they are logging to. If the file changes, it is closed and reopened using the file name. This handler is only useful on Unix-like systems; Windows does not support the underlying mechanism used.
QueueHandler: instances send messages to a queue, such as those implemented in the queue or multiprocessing modules.
NullHandler: instances do nothing with error messages. They are used by library developers who want to use logging, but want to avoid the ‘No handlers could be found for logger XXX’ message which can be displayed if the library user has not configured logging.

The NullHandler, StreamHandler and FileHandler classes are defined in the core logging package. The other handlers are defined in a sub-module, logging.handlers.

1.3. Format

There is some data that we want to be present in every line of log. Context information such as the thread name, time, severity, module and method. Python provides a way to format every message appending this information without explicitly having to add it to the message.

This is done by providing a format to the logger’s configuration. This format consists of attribute names that represent that context data. Below is the list of every available attribute:

args (You shouldn’t need to format this yourself): The tuple of arguments merged into msg to produce message, or a dict whose values are used for the merge (when there is only one argument, and it is a dictionary).
asctime (%(asctime)s): Human-readable time when the LogRecord was created. By default this is of the form ‘2003-07-08 16:49:45,896’ (the numbers after the comma are millisecond portion of the time).
created (%(created)f): Time when the LogRecord was created (as returned by time.time()).
exc_info (You shouldn’t need to format this yourself): Exception tuple or, if no exception has occurred, None.
filename (%(filename)s): Filename portion of pathname.
funcName (%(funcName)s): Name of function containing the logging call.
levelname (%(levelname)s): Text logging level for the message (‘DEBUG’, ‘INFO’, ‘WARNING’, ‘ERROR’, ‘CRITICAL’).
levelno (%(levelno)s): Numeric logging level for the message (DEBUG, INFO, WARNING, ERROR, CRITICAL).
lineno (%(lineno)d): Source line number where the logging call was issued (if available).
module (%(module)s): Module (name portion of filename).
msecs (%(msecs)d): Millisecond portion of the time when the LogRecord was created.
message (%(message)s): The logged message, computed as msg % args. This is set when Formatter.format() is invoked.
msg (You shouldn’t need to format this yourself): The format string passed in the original logging call. Merged with args to produce message, or an arbitrary object.
name (%(name)s): Name of the logger used to log the call.
pathname (%(pathname)s): Full pathname of the source file where the logging call was issued (if available).
process (%(process)d): Process ID (if available).
processName (%(processName)s): Process name (if available).
relativeCreated (%(relativeCreated)d): Time in milliseconds when the LogRecord was created, relative to the time the logging module was loaded.
stack_info (You shouldn’t need to format this yourself): Stack frame information (where available) from the bottom of the stack in the current thread, up to and including the stack frame of the logging call which resulted in the creation of this record.
thread (%(thread)d): Thread ID (if available).
threadName (%(threadName)s): Thread name (if available).

A pretty useful and common format would look like: '%(asctime)s - [%(levelname)s] [%(threadName)s] (%(module)s:%(lineno)d) %(message)s'.

2. The Practice

So, let’s experiment a little bit. Let’s create a file called basic.py and make a logging example in it.

Let’s start with checking the behavior of the default logger, without modifying any of its configuration.

basic.py

import logging

logging.debug('Some additional information')
logging.info('Working...')
logging.warning('Watch out!')
logging.error('Oh NO!')
logging.critical('x.x')

Here we are just importing logging, and logging a line for each severity, to see the format and the threshold. When we run it we see:

WARNING:root:Watch out!
ERROR:root:Oh NO!
CRITICAL:root:x.x

So, the default format would be something like '%(levelname)s:%(name)s:%(message)s'. And the threshold is warning, as our info and warn lines are not being logged. Let’s make it a little nicer:

basic.py

import logging

logging.basicConfig(level=logging.INFO,
                    format="%(asctime)s - [%(levelname)s] [%(threadName)s] (%(module)s:%(lineno)d) %(message)s", )

logging.debug('Some additional information')
logging.info('Working...')
logging.warning('Watch out!')
logging.error('Oh NO!')
logging.critical('x.x')

And the output:

2015-12-30 16:43:39,600 - [INFO] [MainThread] (basic:7) Working...
2015-12-30 16:43:39,600 - [WARNING] [MainThread] (basic:8) Watch out!
2015-12-30 16:43:39,600 - [ERROR] [MainThread] (basic:9) Oh NO!
2015-12-30 16:43:39,600 - [CRITICAL] [MainThread] (basic:10) x.x

We’ve declared a threshold of INFO and a format which gives a lot of useful information. We now have the time, the severity, the thread, the module and the line in every log record.

Let’s make a tiny application which would save a contact list to a CSV file and then retrieve them, and then let’s add some useful log to it:

contacts.py

import csv
import os.path


class Repository:
    def __init__(self, full_file_path):
        self.full_file_path = full_file_path

    def add(self, contact):
        headers = [h for h in contact]
        headers.sort()
        write_headers = not os.path.isfile(
            self.full_file_path)  # let's assume no one will go and erase the headers by hand
        with open(self.full_file_path, 'a+') as file:
            writer = csv.DictWriter(file, fieldnames=headers)
            if write_headers:
                writer.writeheader()
            writer.writerow(contact)

    def names(self):
        with open(self.full_file_path, 'r+') as file:
            names = list(map(lambda r: r['name'], csv.DictReader(file)))
            return names

    def full_contact(self, name):
        with open(self.full_file_path, 'r+') as file:
            for contact in list(csv.DictReader(file)):
                if contact['name'] == name:
                    return contact
            return


class Main:

    def __init__(self, contacts_file):
        self.repo = Repository(contacts_file)

    def create(self):
        name = input("name: ")
        number = input("number: ")
        contact = {"name": name, "number": number}
        self.repo.add(contact)
        print("----------------")

    def names(self):
        names = self.repo.names()
        if len(names) > 0:
            for n in names:
                print("- {}".format(n))
        else:
            print("no contacts were found")
        print("----------------")

    def full_contact(self):
        name = input("name: ")
        contact = self.repo.full_contact(name)
        if contact is not None:
            print("name: {}".format(contact["name"]))
            print("number: {}".format(contact["number"]))
        else:
            print("contact not found.")
        print("----------------")

    def menu(self):
        actions = {"1": self.create, "2": self.names, "3": self.full_contact}
        options = ["1) Create Contact", "2) All Contacts", "3) Detail of a contact", "0) Exit"]
        for o in options:
            print(o)
        selected = input("What do you want to do? ")
        if selected in actions:
            actions[selected]()
            self.menu()

Main("/tmp/contacts.csv").menu()

So now we run it and create two contacts: Michael and Sarah.

1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 1
name: Michael
number: 1234-5678
Done!
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 2
- Michael
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 1
name: Sarah
number: 9876-5432
Done!
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 2
- Michael
- Sarah
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 3
name: Sarah
name: Sarah
number: 9876-5432
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 0

What if we add some logging to know what’s going on there?

contacts.py

import csv
import os.path
import logging

logging.basicConfig(level=logging.INFO,
                    format="%(asctime)s - [%(levelname)s] [%(threadName)s] (%(module)s:%(lineno)d) %(message)s", )


class Repository:
    def __init__(self, full_file_path):
        logging.info("initializing contacts repository with file at: {}".format(full_file_path))
        self.full_file_path = full_file_path

    def add(self, contact):
        logging.info("creating contact: {}".format(contact))
        headers = [h for h in contact]
        headers.sort()
        write_headers = not os.path.isfile(
            self.full_file_path)  # let's assume no one will go and erase the headers by hand
        with open(self.full_file_path, 'a+') as file:
            writer = csv.DictWriter(file, fieldnames=headers)
            if write_headers:
                logging.debug("this is the first contact in the given file. writing headers.")
                writer.writeheader()
            writer.writerow(contact)

    def names(self):
        logging.info("retrieving all contact names")
        with open(self.full_file_path, 'r+') as file:
            names = list(map(lambda r: r['name'], csv.DictReader(file)))
            logging.debug("found {} contacts".format(len(names)))
            return names

    def full_contact(self, name):
        logging.info("retrieving full contact for name: {}".format(name))
        with open(self.full_file_path, 'r+') as file:
            for contact in list(csv.DictReader(file)):
                if contact['name'] == name:
                    logging.debug("contact was found")
                    return contact
            logging.warning("contact was not found for name: {}".format(name))
            return


class Main:

    def __init__(self, contacts_file):
        self.repo = Repository(contacts_file)

    def create(self):
        name = input("name: ")
        number = input("number: ")
        contact = {"name": name, "number": number}
        self.repo.add(contact)
        print("----------------")

    def names(self):
        names = self.repo.names()
        if len(names) > 0:
            for n in names:
                print("- {}".format(n))
        else:
            print("no contacts were found")
        print("----------------")

    def full_contact(self):
        name = input("name: ")
        contact = self.repo.full_contact(name)
        if contact is not None:
            print("name: {}".format(contact["name"]))
            print("number: {}".format(contact["number"]))
        else:
            print("contact not found.")
        print("----------------")

    def menu(self):
        actions = {"1": self.create, "2": self.names, "3": self.full_contact}
        options = ["1) Create Contact", "2) All Contacts", "3) Detail of a contact", "0) Exit"]
        for o in options:
            print(o)
        selected = input("What do you want to do? ")
        if selected in actions:
            actions[selected]()
            self.menu()

Main("/tmp/contacts.csv").menu()

So, now doing the exact same thing we’ll see:

2015-12-30 17:32:15,788 - [INFO] [MainThread] (contacts:11) initializing contacts repository with file at: /tmp/contacts.csv
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 1
name: Michael
number: 1234-5678
2015-12-30 17:32:33,732 - [INFO] [MainThread] (contacts:15) creating contact: {'number': '1234-5678', 'name': 'Michael'}
----------------
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 1
name: Sarah
number: 9876-5432
2015-12-30 17:32:41,828 - [INFO] [MainThread] (contacts:15) creating contact: {'number': '9876-5432', 'name': 'Sarah'}
----------------
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 2
2015-12-30 17:32:45,140 - [INFO] [MainThread] (contacts:28) retrieving all contact names
- Michael
- Sarah
----------------
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 3
name: Sarah
2015-12-30 17:32:48,532 - [INFO] [MainThread] (contacts:35) retrieving full contact for name: Sarah
name: Sarah
number: 9876-5432
----------------
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 0

Now, there is our logging, but there is also a new problem. The user of our script doesn’t care about our log lines, they actually bothers him. Let’s log to a file modifying only the configuration of the logger:

contacts.py

...
logging.basicConfig(level=logging.INFO,
                    format="%(asctime)s - [%(levelname)s] [%(threadName)s] (%(module)s:%(lineno)d) %(message)s",
                    filename="/tmp/contacts.log")
...

So, now in the output we see everything normal again:

1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 2
- Michael
- Sarah
----------------
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 3
name: Michael
name: Michael
number: 1234-5678
----------------
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 3
name: Qwerty
contact not found.
----------------
1) Create Contact
2) All Contacts
3) Detail of a contact
0) Exit
What do you want to do? 0

No log lines for the world to see. Not our script is actually usable again. So with a simple cat /tmp/contacts.log we can see what happened there:

2015-12-30 17:34:54,112 - [INFO] [MainThread] (contacts:12) initializing contacts repository with file at: /tmp/contacts.csv
2015-12-30 17:34:56,219 - [INFO] [MainThread] (contacts:29) retrieving all contact names
2015-12-30 17:35:01,819 - [INFO] [MainThread] (contacts:36) retrieving full contact for name: Michael
2015-12-30 17:35:06,827 - [INFO] [MainThread] (contacts:36) retrieving full contact for name: Qwerty
2015-12-30 17:35:06,827 - [WARNING] [MainThread] (contacts:42) contact was not found for name: Qwerty