Good logging practice in Python


Logging is important in our life. When you transfer money, there will be logs for the transaction. When an airplane is flying, the black box will record flight data. If something goes wrong, people can read the log and get a chance to figure out what happened. Likewise, logging is also essential for software development. When a program crashes, if there is no logging record, you have little chance to understand what happened. Now, let’s see an example in real life. The following screenshot is the log data from one of my running server:

Not only for the servers, but logging is also crucial for almost any kind of software systems. For instance, say you have a GUI app, and it keeps writing logging records in a text file. With that, when your program crashes on the customer’s PC, you can ask them to send the log file to you, then you might be able to figure out why. In the past, I build different apps, all with good logging practices, and this solves countless problems for me. Trust me, you will never know what kind of strange issues there will be in different environments. I once received an error log report like this:

2011-08-22 17:52:54,828 - root - ERROR - [Errno 10104] getaddrinfo failed
Traceback (most recent call last):
  File "<string>", line 124, in main
  File "<string>", line 20, in __init__
  File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/wx._core", line 7978, in __init__
  File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/wx._core", line 7552, in _BootstrapApp
  File "<string>", line 84, in OnInit
  File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet.wxreactor", line 175, in install
  File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet._threadedselect", line 106, in __init__
  File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet.base", line 488, in __init__
  File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet.posixbase", line 266, in installWaker
  File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet.posixbase", line 74, in __init__
  File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/socket", line 224, in meth
gaierror: [Errno 10104] getaddrinfo failed

And eventually, by looking into the log file, I figured out that the customer PC is infected by a virus which makes the gethostname function call failed. See, how can you even know that if there is no log to read?

Although logging is important, not all developers know how to do them correctly. Some people like to insert print statements while developing and remove those statements when they are not needed anymore. Their code may look like this:

print('Start reading database')
records = model.read_recrods()
print('# records', records)
print('Updating record ...')
model.update_records(records)
print('done')

It works fine when the program is a simple small script, but for a complex system, you better not to use this approach. First of all, you cannot display only the important messages in the log. You may see lots of garbage messages and can’t find anything useful. You also cannot control those print statements without modifying code, you may forget to remove those unused prints. And as all the printed messages go into stdout, which is terrible when you have data to output to stdout. Of course you can print messages to stderr instead, but still, it is not a good practice to use print for logging.

Use Python standard logging module

So, how do you do logging correctly? It’s easy, use the standard Python logging module. Thanks to the Python community, logging is a standard module, it was well designed to be easy-to-use and very flexible. You can use the logging system like this:

import logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

logger.info('Start reading database')
# read database here
records = {'john': 55, 'tom': 66}
logger.debug('Records: %s', records)
logger.info('Updating records ...')
# update records here
logger.info('Finish updating records')

You can run it and see

INFO:__main__:Start reading database
INFO:__main__:Updating records ...
INFO:__main__:Finish updating records

What’s different between the print approach you asked. Well, of course, there are benefits:

  • You can control message level and filter out not important ones
  • You can decide where and how to output later

There are different importance levels you can use, DEBUG, INFO, WARNING, ERROR, and CRITICAL. By giving different level to the logger and handler, you can write only error messages to a specific log file, or record debug details when debugging. Let’s change the logger level to DEBUG and see the output again

logging.basicConfig(level=logging.DEBUG)

The output:

INFO:__main__:Start reading database
DEBUG:__main__:Records: {'john': 55, 'tom': 66}
INFO:__main__:Updating records ...
INFO:__main__:Finish updating records

As you can see, the debugging records now appear in the output. Like we mentioned previously, besides changing the log level, you can also decide how to process these messages. For example, say you want to write the logs to a file, you can then use the FileHandler like this:

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

# create a file handler
handler = logging.FileHandler('hello.log')
handler.setLevel(logging.INFO)

# create a logging format
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

# add the file handler to the logger
logger.addHandler(handler)

logger.info('Hello baby')

The FileHandler is just one of many useful build-in handlers. In Python, there is even an SMTP log hander for sending records to your mailbox or one for sending the logs to an HTTP server. Cannot find a handler for your need? No worries, you can also write your own custom logging handler if you want. For more details, please reference official documents: Basic Tutorial, Advanced Tutorial and Logging Cookbook.

Write logging records everywhere with a proper level

With the flexibility of the logging module, it’s a good practice to write logging record everywhere with appropriate level and configure them later. What is the appropriate level to use, you may ask. Let me share my experience here.

In most cases, you don’t want to flood your log file with too many trivial information. And as the name implies, the DEBUG level is for debugging. Therefore, the DEBUG level should only be enabled when you are debugging. I use the DEBUG level only for logging verbose details. Especially when the data is huge, or the frequency is high, such as records of algorithm internal state changes in a for-loop.

def complex_algorithm(items):
    for i, item in enumerate(items):
        # do some complex algorithm computation
        logger.debug('%s iteration, item=%s', i, item)

I use INFO level for routines. For example, handling requests or server state changed.

def handle_request(request):
    logger.info('Handling request %s', request)
    # handle request here
    result = 'result'
    logger.info('Return result: %s', result)

def start_service():
    logger.info('Starting service at port %s ...', port)
    service.start()
    logger.info('Service is started')

I use WARNING when something needs your attention, but not an error. For example, when a user attempts to log in with a wrong password, or, the connection is slow.

def authenticate(user_name, password, ip_address):
    if user_name != USER_NAME and password != PASSWORD:
        logger.warning('Login attempt to %s from IP %s', user_name, ip_address)
        return False
    # do authentication here

I use ERROR level when something is wrong. For example, an exception is thrown, IO operation failure or connectivity issue.

def get_user_by_id(user_id):
    user = db.read_user(user_id)
    if user is None:
        logger.error('Cannot find user with user_id=%s', user_id)
        return user
    return user

I never use CRITICAL, you can use it when something horrible happens. For example, out of memory, the disk is full or a nuclear meltdown (Hopefully that will not actually happen 😅).

Use __name__ as the logger name

It is not a requirement to set the logger name as __name__, but by doing that, it brings us some benefits. In case if you don’t know, the variable __name__ is the current module name in Python. For example, you write this in a module foo.bar.my_module:

logger.getLogger(__name__)

It’s actually the same as this:

logger.getLogger("foo.bar.my_module")

Since the Python’s logging configuration system follows a hierarchy design, the levels in the hierarchy are separated by dots, just like Python’s package and module names. Given foo.bar.my_module as the logger name, the hierarchy will be:

+ foo
  + bar
    - my_module

Say we have many logger names like these

  • foo.bar.my_module
  • foo.bar.my_module2
  • foo.eggs.spam
  • foo.eggs.spam2

Then the corresponding hierarchy will be:

+ foo
  + bar
    - my_module
    - my_module2
  + eggs
    - spam
    - spam2

With that, say you want to configure the loggers for all modules under a package, it can be done easily by configuring the logger with the package as the name. For example, you notice that the log messages from the modules in the foo.eggs package are too verbose, you want to filter most of them out. With the configuration hierarchy, you can configure foo.eggs package to a higher logging level, say WARNING. In this way, for the logs messages from

  • foo.eggs.spam
  • foo.eggs.spam2

as long as their logging level is not equal or higher than WARNING, they will not be processed by the handler.

Besides you can control the logger for the whole package, by using __name__ as the logger name you can also configure the formatter to output the logger name. It’s very helpful to know which module is writing the log.

Capture exceptions with the traceback

While it’s a good practice to log a message when something goes wrong, but it won’t be helpful if there is no traceback. You should capture exceptions and record them with traceback. Following is an example:

try:
    open('/path/to/does/not/exist', 'rb')
except (SystemExit, KeyboardInterrupt):
    raise
except Exception as exception:
    logger.error('Failed to open file', exc_info=True)

By calling logger methods with exc_info=True parameter, the traceback will be dumped to the logger. As you can see the result

ERROR:__main__:Failed to open file
Traceback (most recent call last):
  File "example.py", line 6, in <module>
    open('/path/to/does/not/exist', 'rb')
IOError: [Errno 2] No such file or directory: '/path/to/does/not/exist'

Since Python 3.5, you can also pass the exception instance to exc_info parameter. Besides exc_info parameter, you can also call logger.exception(msg, *args), it is the same as calling to logger.error(msg, *args, exc_info=True).

Do not get logger at the module level unless disable_existing_loggers is False

You can see lots of examples out there are getting the loggers at the module level, including this article. I did it just for making the example simple. While this looks harmless, but in fact, there is a pitfall. The problem is, Python logging module by default respects all existing logger before you load the configuration from a file if you get logger at the module level like this

my_module.py:

import logging

logger = logging.getLogger(__name__)

def foo():
    logger.info('Hi, foo')

class Bar(object):
    def bar(self):
        logger.info('Hi, bar')

main.py

import logging

# load my module
import my_module

# load the logging configuration
logging.config.fileConfig('logging.ini')

my_module.foo()
bar = my_module.Bar()
bar.bar()

logging.ini

[loggers]
keys=root

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

And you expect to see the records appear in the log, but you will see nothing. Why? Because you create the logger at the module level, you then import the module before loading the logging configuration from a file. The logging.fileConfig and logging.dictConfig function’s default behavior is to disable existing loggers when they are called. So, those setting in the file will not be applied to your logger in my_module.py. It’s better to get the logger when you need it to avoid the pitfall. It’s cheap to create or get a logger. You can write the code like this:

import logging

def foo():
    logger = logging.getLogger(__name__)
    logger.info('Hi, foo')

class Bar(object):
    def __init__(self, logger=None):
        self.logger = logger or logging.getLogger(__name__)

    def bar(self):
        self.logger.info('Hi, bar')

By doing that, the loggers will be created after you load the configuration. Now the setting will be applied correctly.

Other than avoiding create logger at the module level, since Python 2.7, a new argument disable_existing_loggers was added to the logging.fileConfig function, and disable_existing_loggers key is also added in the schema forlogging.dictConfig function. By setting it to False, the problem mentioned above can be solved. For example:

import logging
import logging.config

logger = logging.getLogger(__name__)

# load config from file
# logging.config.fileConfig('logging.ini', disable_existing_loggers=False)
# or, for dictConfig
logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,  # this fixes the problem
    'formatters': {
        'standard': {
            'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
        },
    },
    'handlers': {
        'default': {
            'level':'INFO',
            'class':'logging.StreamHandler',
        },
    },
    'loggers': {
        '': {
            'handlers': ['default'],
            'level': 'INFO',
            'propagate': True
        }
    }
})

logger.info('It works!')

Use JSON or YAML logging configuration

You can configure your logging system in Python code, but then you need to modify your code whenever you want to change the log configuration. Another way to do it is to use a logging configuration file. After Python 2.7, you can load logging configuration from a dict. It means you can load the logging configuration from a JSON or YAML file. Although you can use the old .ini style logging configuration, it is difficult to read and write. Here let me show you the logging configuration examples in JSON and YAML

logging.json

{
  "version": 1,
  "disable_existing_loggers": false,
  "formatters": {
    "simple": {
      "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
    }
  },

  "handlers": {
    "console": {
      "class": "logging.StreamHandler",
      "level": "DEBUG",
      "formatter": "simple",
      "stream": "ext://sys.stdout"
    },

    "info_file_handler": {
      "class": "logging.handlers.RotatingFileHandler",
      "level": "INFO",
      "formatter": "simple",
      "filename": "info.log",
      "maxBytes": 10485760,
      "backupCount": 20,
      "encoding": "utf8"
    },

    "error_file_handler": {
      "class": "logging.handlers.RotatingFileHandler",
      "level": "ERROR",
      "formatter": "simple",
      "filename": "errors.log",
      "maxBytes": 10485760,
      "backupCount": 20,
      "encoding": "utf8"
    }
  },

  "loggers": {
    "my_module": {
      "level": "ERROR",
      "handlers": ["console"],
      "propagate": false
    }
  },

  "root": {
    "level": "INFO",
    "handlers": ["console", "info_file_handler", "error_file_handler"]
  }
}

logging.yaml

---
version: 1
disable_existing_loggers: False
formatters:
  simple:
    format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"

handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: simple
    stream: ext://sys.stdout

  info_file_handler:
    class: logging.handlers.RotatingFileHandler
    level: INFO
    formatter: simple
    filename: info.log
    maxBytes: 10485760 # 10MB
    backupCount: 20
    encoding: utf8

  error_file_handler:
    class: logging.handlers.RotatingFileHandler
    level: ERROR
    formatter: simple
    filename: errors.log
    maxBytes: 10485760 # 10MB
    backupCount: 20
    encoding: utf8

loggers:
  my_module:
    level: ERROR
    handlers: [console]
    propagate: no

root:
  level: INFO
  handlers: [console, info_file_handler, error_file_handler]

The following recipe shows you how to read logging configuration from a JSON file:

import os
import json
import logging.config

def setup_logging(
    default_path='logging.json',
    default_level=logging.INFO,
    env_key='LOG_CFG'
):
    """Setup logging configuration

    """
    path = default_path
    value = os.getenv(env_key, None)
    if value:
        path = value
    if os.path.exists(path):
        with open(path, 'rt') as f:
            config = json.load(f)
        logging.config.dictConfig(config)
    else:
        logging.basicConfig(level=default_level)

One advantage of using JSON configuration is that Python has json as a standard library, unlike YAML, you don’t need to install a third-party library. But personally, I prefer YAML. It’s clear to read and easier to write. You can install PyYAML and load the YAML configuration with the following recipe:

import os
import logging.config

import yaml

def setup_logging(
    default_path='logging.yaml',
    default_level=logging.INFO,
    env_key='LOG_CFG'
):
    """Setup logging configuration

    """
    path = default_path
    value = os.getenv(env_key, None)
    if value:
        path = value
    if os.path.exists(path):
        with open(path, 'rt') as f:
            config = yaml.safe_load(f.read())
        logging.config.dictConfig(config)
    else:
        logging.basicConfig(level=default_level)

Now, to setup logging, you can call setup_logging when starting your program. It reads logging.json or logging.yaml by default. You can also set LOG_CFG environment variable to load the logging configuration from a path. For example,

LOG_CFG=my_logging.json python my_server.py

or if you prefer YAML

LOG_CFG=my_logging.yaml python my_server.py

Use rotating file handler

If you use FileHandler for writing logs, the size of the log file will grow with time. Someday, it will occupy all of your disk space. To avoid that situation, you should use RotatingFileHandler instead of FileHandler in the production environment.

Setup a central log server when you have multiple servers

When you have multiple servers and different log files. You can set up a central log system to collect all vital log messages. Then you can monitor it easily and notice what’s wrong in your system.

Conclusions

Personally, I think the best part of Python’s logging library is that it is a standard library so that you don’t have to choose. Remember the Zen of Python?

There should be one– and preferably only one –obvious way to do it.

I’m also happy with its excellent design. It is flexible, you can write your own handlers and filters. There are also third-party handlers such as ZeroMQ logging handler provided by pyzmq, it allows you to send logging messages through a zmq socket.

Finally, if you didn’t know how to use the logging system correctly, hopefully, my article could be helpful. With proper logging practice, you can find issues in your system easier. It’s an excellent investment, don’t you buy it? 😎

Recent articles:

How I discovered a 9.8 critical security vulnerability in ZeroMQ with mostly pure luck and my two cents about xz backdoor
High-speed 10Gbps full-mesh network based on USB4 for just $47.98
Why I built a self-serving advertisement solution for myself