Python Standard Logging Pattern

1. Introduction

The Python standard library provides a logging module as a de facto solution for libraries and applications to log their behavior. Logging is extensively used by Websauna, Pyramid, SQLAlchemy, and other Python packages.

• The Python logging subsystem can be configured using an external configuration file and the logging configuration format is specified in Python standard library.
• The Python loggers can be individually turned on or off, and their verbosity adjusted on a per-module basis. For example by default, the Websauna development server sets the SQLALchemy logging level to INFO instead of DEBUG to avoid flooding the console with verbose SQL logs. However, if you are debugging issues related to a database, you might want to set the SQLAlchemy logging back to INFO.
• Logging is the preferred diagnosing method over print statements cluttered around source code. Well-designed logging calls can be left in the source code and later turned back on if the problems must be diagnosed further.
• Python logging output can be directed to console, file, rotating file, syslog, remote server, email, etc.

2. Log Colorization

• Websauna uses rainbow_logging_handler, which colorizes the logs, making it easier to read them in the console of the development web server.

3. Standard Logging Pattern

A common logging pattern in Python is:

import logging

logger = logging.getLogger(__name__)

def my_view(request):
    logger.debug("my_view got request: %s", request)
    logger.info("my_view got request: %s", request)
    logger.error("my_view got request: %s and BAD STUFF HAPPENS", request)

    try:
        raise RuntimeError("OH NOES")
    except Exception as e:
        # Let's log full traceback even when we ignore this exception
        # and it's not risen again
        logger.exception(e)

• This names a logger based on a module so you can switch loggers on/off on a per-module basis.
• Pass logged objects to logging.Logger.debug() and co. as full, and let the logger handle the string formatting. This allows the intelligent display of logged objects when using non-console logging solutions like Sentry.
• Use logging.Logger.exception() to report exceptions. This will record the full traceback of the exception and not just the error message.

Please note that although this logging pattern is common, it’s not a universal solution. For example, if you are creating third-party APIs, you might want to pass the logger to a class instance of an API, so that the API consumer can take over the logger setup and there is no inversion of control.

4. Changing Logging Level Using INI Settings

Websauna defines development web server log levels in its core development.ini. Your Websauna application inherits settings from this file and can override them for each logger in the conf/development.ini file of your application.

For example, to set SQLAlchemy and transaction logging level to be more verbose, you can do:

[logger_sqlalchemy]
level = DEBUG

[logger_transaction]
level = DEBUG

Now console is flooded with very verbose logging:

[2016-05-22 20:39:55,429] [sqlalchemy.engine.base.Engine _begin_impl] BEGIN (implicit)
[2016-05-22 20:39:55,429] [txn.123145312813056 __init__] new transaction
[2016-05-22 20:39:55,429] [sqlalchemy.engine.base.Engine _execute_context] SELECT users.password AS users_password, users.id AS users_id, users.uuid AS users_uuid, users.username AS users_username, users.email AS users_email, users.created_at AS users_created_at, users.updated_at AS users_updated_at, users.activated_at AS users_activated_at, users.enabled AS users_enabled, users.last_login_at AS users_last_login_at, users.last_login_ip AS users_last_login_ip, users.user_data AS users_user_data, users.last_auth_sensitive_operation_at AS users_last_auth_sensitive_operation_at, users.activation_id AS users_activation_id

5. Initialization Loggers From INI File

If you need to initialize loggers in your own applications see websauna.system.devop.cmdline.setup_logging() for how Websauna picks up loggers from INI configuration file.

6. More Information

How Websauna logs username and email for every internal server error. It’s an impressive service if your DevOps team calls a customer the second an error happens and guide the customer around the error. As a bonus, if using Sentry, you will see the Gravatar profile image of the user when viewing the exception.

Logbook is an alternative for Python standard library logging if performance is critical or the application has more complex logging requirements .

Discussion about log message formatting and why we are still using old style string formatting.

structlog package – add context to your logged messages like user id or HTTP request URL.