Logging in Python Command Line Applications
Tags: python, logging, cli, tutorial
Published: 2022-04-03 20:24:58

## Introduction

Logging is a necessary part of any serious application. It allows you and your users to effectively debug issues. In this article, I will showcase a good way to configure logging for command-line python apps. You can see the finished product as a github gist [here](https://gist.github.com/eblocha/fba1c0e2b49333607c4a2d7492f7491c).

## Goal

The goal of our logger will have multiple parts:
1. Make the console output pretty and easy to read by a human
2. Save additional output to a log file that can be parsed by a computer
3. Save all traceback information for debugging later
4. Allow users to change the verbosity of the console and log file output

We are going to make the console output look like this:

![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/mpfi27fmzm2w7xc1as3y.jpg)

And the log file look like this:
```
DEBUG:2022-04-03 15:41:17,920:root:A debug message
INFO:2022-04-03 15:41:17,920:root:An info message
WARNING:2022-04-03 15:41:17,920:root:A warning message
ERROR:2022-04-03 15:41:17,920:root:An error message
CRITICAL:2022-04-03 15:41:17,920:root:A critical message from an exception
    Traceback (most recent call last):
        /home/eb/projects/py-scratch/color-log.py  <module>  327: raise ValueError("A critical message from an exception")
    ValueError: A critical message from an exception
```

We've got a few tricky things going on here.

1. We are using different colors and formats based on the log level
2. We are using different formats for the console and file output
3. We are changing the traceback format

## Formatter

The python logging formatter does not allow different format strings based on the log level, so we will need to implement our own formatter.

```py
import typing as t

class MultiFormatter(PrettyExceptionFormatter):
    """Format log messages differently for each log level"""

    def __init__(self, formats: t.Dict[int, str] = None, **kwargs):
        base_format = kwargs.pop("fmt", None)
        super().__init__(base_format, **kwargs)

        formats = formats or default_formats

        self.formatters = {
            level: PrettyExceptionFormatter(fmt, **kwargs)
            for level, fmt in formats.items()
        }

    def format(self, record: logging.LogRecord):
        formatter = self.formatters.get(record.levelno)

        if formatter is None:
            return super().format(record)

        return formatter.format(record)
```

In our `MultiFormatter` class, we take a mapping of log level to a format string, then create different formatters for each level. In `.format()`, we dispatch to the formatter for the level logged.

Now, what is `PrettyExceptionFormatter`? We also need to implement that. It will format the traceback and exception information when it is included in the log record.

```py
from textwrap import indent
from pretty_traceback.formatting import exc_to_traceback_str

class PrettyExceptionFormatter(logging.Formatter):
    """Uses pretty-traceback to format exceptions"""

    def __init__(self, *args, color=True, **kwargs) -> None:
        super().__init__(*args, **kwargs)
        self.color = color

    def formatException(self, ei):
        _, exc_value, traceback = ei
        return exc_to_traceback_str(exc_value, traceback, color=self.color)

    def format(self, record: logging.LogRecord):
        record.message = record.getMessage()

        if self.usesTime():
            record.asctime = self.formatTime(record, self.datefmt)

        s = self.formatMessage(record)

        if record.exc_info:
            # Don't assign to exc_text here, since we don't want to inject color all the time
            if s[-1:] != "\n":
                s += "\n"
            # Add indent to indicate the traceback is part of the previous message
            text = indent(self.formatException(record.exc_info), " " * 4)
            s += text

        return s
```

We're using the awesome [pretty-traceback](https://github.com/mbarkhau/pretty-traceback) package here. Since the default behavior of `logging.Formatter` is to modify the `record.exc_text` with the output of `.formatException()`, we need to override that behavior. This is because we are adding ANSI color, and don't want to see that in log files.

In the standard `logging.Formatter` implementation, the record is *modified* when formatting exceptions (as of python 3.10.2):
```py
def format(self, record):
    ...
    # exc_text is MODIFIED, which propagates to other formatters for other handlers
    record.exc_text = self.formatException(record.exc_info)
    ...
    return s
```

The `MultiFormatter` class takes an argument to change the format string per-level, with the default strings as follows:

```py
default_formats = {
    logging.DEBUG: style("DEBUG", fg="cyan") + " | " + style("%(message)s", fg="cyan"),
    logging.INFO: "%(message)s",
    logging.WARNING: style("WARN ", fg="yellow") + " | " + style("%(message)s", fg="yellow"),
    logging.ERROR: style("ERROR", fg="red") + " | " + style("%(message)s", fg="red"),
    logging.CRITICAL: style("FATAL", fg="white", bg="red", bold=True) + " | " + style("%(message)s", fg="red", bold=True),
}
```

This adds a vertical line between the level name and message, except for info messages, which are passed through as plain messages. The `style` function here is a direct copy of the [`click.style`](https://click.palletsprojects.com/en/8.1.x/utils/#ansi-colors) utility.

## Context Managers

The end goal here is to simply call `with cli_log_config():`, and get beautiful output. We will need some context managers. Starting with a logging context, straight from the [python docs](https://docs.python.org/3/howto/logging-cookbook.html#using-a-context-manager-for-selective-logging):

```py
class LoggingContext:
    def __init__(
        self,
        logger: logging.Logger = None,
        level: int = None,
        handler: logging.Handler = None,
        close: bool = True,
    ):
        self.logger = logger or logging.root
        self.level = level
        self.handler = handler
        self.close = close

    def __enter__(self):
        if self.level is not None:
            self.old_level = self.logger.level
            self.logger.setLevel(self.level)

        if self.handler:
            self.logger.addHandler(self.handler)

    def __exit__(self, *exc_info):
        if self.level is not None:
            self.logger.setLevel(self.old_level)

        if self.handler:
            self.logger.removeHandler(self.handler)

        if self.handler and self.close:
            self.handler.close()
```

Next, we create a special context manager to combine multiple context managers dynamically:

```py
class MultiContext:
    """Can be used to dynamically combine context managers"""

    def __init__(self, *contexts) -> None:
        self.contexts = contexts

    def __enter__(self):
        return tuple(ctx.__enter__() for ctx in self.contexts)

    def __exit__(self, *exc_info):
        for ctx in self.contexts:
            ctx.__exit__(*exc_info)
```

Finally, we can combine everything we've done so far into a single context manager:
```py
def cli_log_config(
    logger: logging.Logger = None,
    verbose: int = 2,
    filename: str = None,
    file_verbose: int = None,
):
    """
    Use a logging configuration for a CLI application.
    This will prettify log messages for the console, and show more info in a log file.

    Parameters
    ----------
    logger : logging.Logger, default None
        The logger to configure. If None, configures the root logger
    verbose : int from 0 to 3, default 2
        Sets the output verbosity.
        Verbosity 0 shows critical errors
        Verbosity 1 shows warnings and above
        Verbosity 2 shows info and above
        Verbosity 3 and above shows debug and above
    filename : str, default None
        The file name of the log file to log to. If None, no log file is generated.
    file_verbose : int from 0 to 3, default None
        Set a different verbosity for the log file. If None, is set to `verbose`.
        This has no effect if `filename` is None.

    Returns
    -------
    A context manager that will configure the logger, and reset to the previous configuration afterwards.
    """

    if file_verbose is None:
        file_verbose = verbose

    verbosities = {
        0: logging.CRITICAL,
        1: logging.WARNING,
        2: logging.INFO,
        3: logging.DEBUG,
    }

    console_level = verbosities.get(verbose, logging.DEBUG)
    file_level = verbosities.get(file_verbose, logging.DEBUG)

    # This configuration will print pretty tracebacks with color to the console,
    # and log pretty tracebacks without color to the log file.

    console_handler = logging.StreamHandler()
    console_handler.setFormatter(MultiFormatter())
    console_handler.setLevel(console_level)

    contexts = [
        LoggingContext(logger=logger, level=min(console_level, file_level)),
        LoggingContext(logger=logger, handler=console_handler, close=False),
    ]

    if filename:
        file_handler = logging.FileHandler(filename)
        file_handler.setFormatter(
            PrettyExceptionFormatter(
                "%(levelname)s:%(asctime)s:%(name)s:%(message)s", color=False
            )
        )
        file_handler.setLevel(file_level)
        contexts.append(LoggingContext(logger=logger, handler=file_handler))

    return MultiContext(*contexts)
```

We now have the option to specify a verbosity level, a log file, and a different verbosity for the file. Try out the example:

```py
with cli_log_config(verbose=3, filename="test.log"):
    try:
        logging.debug("A debug message")
        logging.info("An info message")
        logging.warning("A warning message")
        logging.error("An error message")
        raise ValueError("A critical message from an exception")
    except Exception as exc:
        logging.critical(str(exc), exc_info=True)
```

## Conculsion

In this article, we:
1. Implemented a custom logging formatter to dynamically format messages based on log level
2. Added color to console log output
3. Prettified exceptions in log messages
4. Wrapped everything into a reusable context manager

I hope you enjoyed, and drew some inspiration for making your CLI apps more user-friendly and robust!