Keep track of happenings with logging

Batteries included is a blog series about the Python Standard Library. Each day, I share insights, ideas and examples for different parts of the library. Blaugust is an annual blogging festival in August where the goal is to write a blog post every day of the month.

In software development, observability is the act of collecting data of software’s operations. One key part of it is logging and Python’s standard library’s logging module offers basic utilities to start logging.

To start logging, you import the module and create a logger:

import logging
logger = logging.getLogger(__name__)

This logger can then be configured with a few parameters

logging.basicConfig(filename='example.log', encoding='utf-8', level=logging.DEBUG)

where you define where the logs should be written, which level (DEBUG, INFO, WARNING, ERROR or CRITICAL) is the minimum that gets printed and a few other options you can find in the docs. One argument that you might want to look into is format that can be used to define what template the log outputs use. It’s nice to get that one correct before you start logging everything. For example, adding a timestamp is useful for exploring the log.

After this, you can then use the logger inside your code base when something logging-worthy happens:

logging.debug('A debug level message')
logging.info('Information about the execution')
logging.warning('Something fishy might be happening here')

Lazy rendering

One thing to note here is that it’s advisable to avoid using the regular string formatting methods (like f-strings or .format) and instead use logging’s own formatting.

Google’s Python style guide says

For logging functions that expect a pattern-string (with %-placeholders) as their first argument: Always call them with a string literal (not an f-string!) as their first argument with pattern-parameters as subsequent arguments. Some logging implementations collect the unexpanded pattern-string as a queryable field. It also prevents spending time rendering a message that no logger is configured to output.

The reason here is that if you have

logging.warning(f'Something went wrong: {message}')

the f-string rendering happens every time, regardless of if the message will actually be logged. It’s because that determination happens inside .warning method (for example if the logging level is set to such that warnings never are logged).

So rather than that, use

logging.warning('Something went wrong %s', message)

as there the string rendering only happens if it gets logged. You can configure which style of formatting you want to use in the basicConfig by providing it a style parameter.