Python Logging Example

Sebastian Vinci

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:

Want to be a Python Ninja?
Subscribe to our newsletter and download the Python Programming Cookbook right now!
In order to get you prepared for your Python development needs, we have compiled numerous recipes to help you kick-start your projects. Besides reading them online you may download the eBook in PDF format!
I agree to the Terms and Privacy Policy
Sign up

Thank you!

We will contact you soon.

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:

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:

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:

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

3. Download the Code Project

This was an example on Python Logging.

Download
You can download the full source code of this example here: python-logging
Related Articles
↑
Exit mobile version