How to Property Set up Python Logging with a Command Line Program

Written by Jordan H.

Boy With Trumpet as Log.debug and stderr

I promise you that the above meme will make sense by the end of the article. Just bear with me.

While logging should not be used as a replacement for debugging or unit testing, it’s vital to incorporate logging to notify if something is going wrong.

Novice Python programmers (or veteran Python programmers) may be a bit frustrated configuring logging for a command line application. Unfortunately, while Python’s logging module is highly configuragle, this power comes at the cost of clarity.

In this article I describe how to properly set up logging in a Python command line interface (or CLI), so that we can set up a industry-ready command line program.


Examples used in this article can be seen here: https://gitlab.com/srcrr/python_logging_examples

A Command Line Argument Primer

This is the tl;dr portion for folks who are uninitiated in the ways of argparser. For those who are, feel free to skip to Adding Loging and Verbosity

For those not familiar, CLI is the term used for any program that is run in the non- graphical interface. If you’ve used ls or dir, congratulations, you’ve used a CLI program.

Python is often used as a scrpting language for command line utilities. The basic template for such a program looks like this:

def main():
    print("Hello World!")

if __name__ == '__main__':
    main()

The full source code can be seen here: https://gitlab.com/srcrr/python_logging_examples/-/blob/master/basic_setup/hello_world.py

The program is run like this:

$ python hello_world.py 
Hello World!

or like this:

$ python -m hello_world
Hello World!

Most veteran python programmers prefer the python -m approach, since it tries to treat everything as a module. I’ll use that form throughout.

Adding Arguments

Let’s add some spice to the program! If you’ve ever spent a day on the command line you’ve undoubtedly come across arguments and options. This is something like ps -aux for linux or dir /t for Windows. Python prefers the hyphenated syntax (.e.g. -v or --verbose).

For this we’ll use the argparse library. If you’re looking for more power, I’d suggest the Click package.

import argparse

parser = argparse.ArgumentParser()

parser.add_argument("name", nargs="?", default="World")


def main(args):
    print(f"Hello, {args.name}!")


if __name__ == "__main__":
    args = parser.parse_args()
    main(args)

The full source code can be seen here: https://gitlab.com/srcrr/python_logging_examples/-/blob/master/cli_add_argparse/hello.py

This program has an optional argument name, which will be printed in place of World, if given.

$ python -m hello
Hello, World!

$ python -m hello Jerry
Hello, Jerry!

Adding Logging and Verbosity

Let’s add a few more things to the program:

  1. Add logging so we know what’s going on.
  2. Add a flag to specify how verbose we want to be.

Since the example above is pretty basic (despite there not being a pumpkin spice latte in sight) let’s modify the program to do something more complex.

Let’s still greet the person, but check to see what time of day it is. Then we’ll greet the user accordingly. For added fun, let’s add an hour offset!

Here’s the code for the program:

import sys
from datetime import datetime, timedelta
import argparse
import logging

# Only used for type hinting.
import typing as T

parser = argparse.ArgumentParser()
parser.add_argument("name", nargs="?", default="World")
parser.add_argument("-o", "--offset", type=int, default=0)

# Create a new logger
log = logging.getLogger(__name__)

def say_hello(name : T.Any, hour_offset : int):
    # Boundary checking.
    # NOTE: typically we'd want to raise an exception here,
    # such as a RuntimeException. However, to demonstrate logging,
    # we'll just log an error, then exit gracefully.
    # NOTE: Actually, more than likely the proper way to do this
    # would be to do bounds checking via argparser.
    if abs(hour_offset) > 23:
        log.error("`hour_offset` must be less than 24!")
        sys.exit(1)
    curr_time = datetime.now()
    check_time = curr_time + timedelta(hours=hour_offset)
    log.debug("Current time: %s", curr_time.strftime("%c"))
    log.debug("Offset in hours: %s", hour_offset)
    log.debug("Time to check: %s", check_time)
    if check_time.hour > 16:
        print(f"Closing time, {name}. I'm done for the day.")
        return
    if check_time.hour > 12:
        print(f"Good afternoon, {name}. How was lunch?")
        return
    print(f"{name}, I need coffee.")
    return

def main(args):
    hour_offset = int(args.offset)
    name = args.name
    say_hello(name, hour_offset)

if __name__=='__main__':
    args = parser.parse_args()
    main(args)

The full source code can be seen here: https://gitlab.com/srcrr/python_logging_examples/-/blob/master/adding_complexity/hello_check.py

Excellent. Let’s try running the program!

$ python -m hello_check
World, I need coffee.
$ python -m hello_check -o 4 Susan
Good afternoon, Susan. How was lunch?
$ python -m hello_check -o 77 Sam
`hour_offset` must be less than 24!

So far so good. But notice anything?

Where are all the debugging messages?

Logging is obviously working, otherwise "'hour_offset' must be less than 24!" won’t be printed.

This is due to how Python logs…specifically logging levels

How Python Logging Works

I would highly recommend taking a look at the Python Logging Documentation. I’ll admit–It’s a lot to unpack, so I’ll put the simplistic explanation here:

  • Logging is done within a logger object
  • There are 5 levels of logging: DEBUG, INFO, WARNING, ERROR, and CRITICAL, DEBUG being the lowest level (just used for developers), and CRITICAL being the highest level.
  • If not configured, instantiating a logger object will configure it with default properties.
  • These default properties result in anything with level INFO and above to be written to stderr without any fancy formatting.
  • Here’s what’s important: all these defaults can be overridden.

Since (in the example above) we don’t configure the logger, Python just uses the default properties, meaning nothing below INFO will be printed.

With this we use the logging.basicConfig function:

# ...
import logging
# Only used for type hinting.
import typing as T

logging.basicConfig(level=logging.DEBUG)
# ...

And we run the program again:

$ python -m hello_check -o 77 Sam
ERROR:__main__:`hour_offset` must be less than 24!

$ python -m hello_check -o 3 Sam
DEBUG:__main__:Current time: Sun Jan 24 08:14:04 2021
DEBUG:__main__:Offset in hours: 3
DEBUG:__main__:Time to check: 2021-01-24 11:14:04.988934
Sam, I need coffee.

Notice 2 things:

  1. The formatting of the log messages changed. Now it’s printed as <Level>:<__name__>:<message>.
  2. Messages with level DEBUG are printed to the console.

Sweet! However, there is an issue. Typically with a program we don’t want to print out the debug messages EVERY TIME. Only for when a user wants to find out more detailed info on what happened or if we’re doing active development.

So most programs have a “debug” flag (sometimes it’s a “verbosity” flag), like this:

$ program -d
DEBUG: Here is a debug message
This is the output

$ program
This is the output

Let’s modify our program to include a debug flag.

Debug Flag

The following changes are made to our program:

import typing as T

# logging.basicConfig Is removed from here

parser = argparse.ArgumentParser()

# ...
parser.add_argument("-d", "--debug", action="store_true", default=False)

# Create a new logger
log = logging.getLogger(__name__)

# ...

We’ve added the flag. Cool. But how do we control the program flow to enable debugging messages?

While there may be a few options, I’d recommend putting it in main:

def main(args):
    if args.debug:
        logging.basicConfig(level=logging.DEBUG)
    else:
        logging.basicConfig(level=logging.INFO)
    hour_offset = int(args.offset)
    name = args.name
    say_hello(name, hour_offset)

The full source code can be seen here: https://gitlab.com/srcrr/python_logging_examples/-/blob/master/configure_level_debug/hello_check.py

And with that, we can run the program with debugging:

$ python -m hello_check
World, I need coffee.

$ python -m hello_check -d
DEBUG:__main__:Current time: Tue Jan 26 06:17:51 2021
DEBUG:__main__:Offset in hours: 0
DEBUG:__main__:Time to check: 2021-01-26 06:17:51.652623
World, I need coffee

First of all, yes, I know that’s early. I’m an early riser–what can I say!

Second of all, we have successfully added a -d/--debug flag to control debugging output–just like the pros do. 😎

Advanced Topic: DictConfig

For simple programs this is fine, but typically if you’re doing logging “right,” you’d use logging.config.dictConfig. This allows for finer-grained control over logging output.

But we want to control the flow of the debug output. How do we go about this?

There are 2 ways:

  1. Invoking dictConfig from a global context (e.g. near the imports), then iterating through each handler in main to set each one to DEBUG.
  2. Invoking dictConfig from main, based on the value of args.debug.

Option 1 does have it’s advantages, but for the sake of simplicity I’ll incorporate option 2.

Consider the following LOGGING dict:

{
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'simple': {
            'format': '{levelname} {message}',
            'style': '{',
        },
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'simple',
        },
    },
    'root': {
        'handlers': ['console'],
        'level': 'DEBUG',
    },
}

We’ll want to pass this in to logging.config.dictConfig but remember that we also want to set level dynamically, based on the value of args.debug.

We can use boolean comprehension for shorthand here, and return it as a value from a function.

def get_log_dict(args):
    return {
        'version': 1,
        'disable_existing_loggers': False,
        'formatters': {
            'simple': {
                'format': '{levelname} {message}',
                'style': '{',
            },
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'formatter': 'simple',
            },
        },
        'root': {
            'handlers': ['console'],
            'level': 'DEBUG' if args.debug else 'INFO',
        },
    }

That way we can simply call the function from main:

# In imports...
import os
import logging.config
# Later on in main ...
def main(args):
    logging.config.dictConfig(get_log_dict(args))
    hour_offset = int(args.offset)
    name = args.name
    say_hello(name, hour_offset)

The full source code can be seen here: https://gitlab.com/srcrr/python_logging_examples/-/blob/master/with_dictconfig/hello_check.py

Now we can have finer grained control over debug output.

python -m hello_check -d
DEBUG Current time: Tue Jan 26 06:41:52 2021
DEBUG Offset in hours: 0
DEBUG Time to check: 2021-01-26 06:41:52.706966
World, I need coffee.

Note that this will only control the logging for the current console. If you’re a Django enthusiast and really want Django in your program (and who doesn’t!), you can control that logging sepearately:

def get_log_dict(args):
    return {
        'version': 1,
        'disable_existing_loggers': False,
        'formatters': {
            'simple': {
                'format': '{levelname} {message}',
                'style': '{',
            },
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'formatter': 'simple',
            },
        },
        # Print `info` if `-d` flag passed...otherwise `warning`
        'django': {
            'handlers': ['console'],
            'level': 'INFO' if args.debug else 'WARNING',
        },
        'root': {
            'handlers': ['console'],
            'level': 'DEBUG' if args.debug else 'INFO',
        },
    }

Conclusion

In this tutorial we showed how to properly configure logging in Python. What Python lacks in clarity it makes up for in granularity. Python’s logging module is one of the most powerful out there, and there are many modules you can incorporate to add formatters, handlers, and more!

It can be confusing sometimes to add logging to command line interfaces programs, though. Above we showed how to do this.

Did you like this article?

Did you know I'm available for hire?

Send me an email here: hireme@jordanhewitt.pro

Or connect with me in Wire: @nswered