Nested prefixes accross loggers in Python

Question

I'm currently working on a project where were use a single root logger. I understand from reading about logging that is a Bad Thing but am struggling to find a nice solution to a nice benefit this gives us.

Something we do (in part, to get around not having different loggers but in part gives us a nice feature) is to have a log_prefix decorator.

e.g.

@log_prefix("Download")
def download_file():
    logging.info("Downloading file..")
    connection = get_connection("127.0.0.1")
    //Do other stuff
    return file

@log_prefix("GetConnection")
def get_connection(url):
    logging.info("Making connection")
    //Do other stuff
    logging.info("Finished making connection")
    return connection

This gives us some nicely formatting logs that might look like:

Download:Downloading file..
Download:GetConnection:Making Connection
Download:GetConnection:Other stuff
Download:GetConnection:Finished making connection
Download:Other stuff

This also means that if we have

@log_prefix("StartTelnetSession")
logging.info("Starting telnet session..")
connection = get_connection("127.0.0.1")

We get the same prefix at the end:

StartTelnetSession:Starting telnet session..
StartTelnetSession:GetConnection:Making Connection
StartTelnetSession:GetConnection:Other stuff
StartTelnetSession:GetConnection:Finished making connection

This has proven to be quite useful for development and support.

I can see plenty of cases where actually just using a separate logger for the action would solve our problem but I can also see cases where throwing away the nesting we have will make things worse.

Are there any patterns or common uses out there for nesting loggers? i.e

logging.getLogger("Download").getLogger("MakingConnection")

Or am I missing something here?

Answer 1

Logger names are hierarchical.

logger = logging.getLogger("Download.MakingConnection")

This logger would inherit any configuration from logging.getLogger("Download").

Python 2.7 also added a convenience function for accessing descendants of an arbitrary logger.

logger = logging.getLogger("Download.MakingConnection")

parent_logger = logging.getLogger("Download")
child_logger = parent_logger.getChild("MakingConnection")

assert logger is child_logger

Answer 2

Here is an alternative which uses a logging.Filter to modify the record.msg. By modifying the message instead of adding an %(prefix)s field, the format does not need to change.

This will make it easier to mix loggers which make use of log_prefix and those that don't.

To get the prefix, the logger should be initialized with a call to add_prefix_filter:

logger = UL.add_prefix_filter(logging.getLogger(__name__))

To append labels to the prefix, the functions should be decorated with @log_prefix(label), as before.

---

utils_logging.py:

import functools
import logging

prefix = list()

def log_prefix(label):
    def decorator(func):
        @functools.wraps(func)
        def wrapper(*args, **kwargs):
            prefix.append(label)
            try:
                result = func(*args, **kwargs)
            finally:
                prefix.pop()
            return result
        return wrapper
    return decorator

class PrefixFilter(logging.Filter):
    def filter(self, record):
        if prefix:
            record.msg = '{}:{}'.format(':'.join(prefix), record.msg)
        return True

def add_prefix_filter(logger):
    logger.addFilter(PrefixFilter())
    return logger

main.py:

import logging
import bar
import utils_logging as UL

logger = UL.add_prefix_filter(logging.getLogger(__name__))

@UL.log_prefix("Download")
def download_file():
    logger.info("Downloading file..")
    connection = bar.get_connection("127.0.0.1")

if __name__ == '__main__':
    logging.basicConfig(
        level=logging.INFO,
        format='%(message)s')

    logger.info('Starting...')
    download_file()
    bar.get_connection('foo')

bar.py:

import logging
import utils_logging as UL

logger = UL.add_prefix_filter(logging.getLogger(__name__))

@UL.log_prefix("GetConnection")
def get_connection(url):
    logger.info("Making connection")
    logger.info("Finished making connection")

yields

Starting...
Download:Downloading file..
Download:GetConnection:Making connection
Download:GetConnection:Finished making connection
GetConnection:Making connection
GetConnection:Finished making connection

Answer 3

You could use a LoggerAdapter to add extra contextual information:

utils_logging.py:

import functools

def log_prefix(logger, label, prefix=list()):
    def decorator(func):
        @functools.wraps(func)
        def wrapper(*args, **kwargs):
            prefix.append(label)
            logger.extra['prefix'] = ':'.join(prefix)
            result = func(*args, **kwargs)
            prefix.pop()
            logger.extra['prefix'] = ':'.join(prefix)
            return result
        return wrapper
    return decorator

foo.py:

import logging
import utils_logging as UL
import bar

logger = logging.LoggerAdapter(logging.getLogger(__name__), {'prefix':''})
@UL.log_prefix(logger, "Download")
def download_file():
    logger.info("Downloading file..")
    connection = bar.get_connection("127.0.0.1")

if __name__ == '__main__':
    logging.basicConfig(
        level=logging.INFO,
        format='%(prefix)s %(name)s %(levelname)s %(message)s')

    download_file()
    bar.get_connection('foo')

bar.py:

import logging
import utils_logging as UL
logger = logging.LoggerAdapter(logging.getLogger(__name__), {'prefix':''})

@UL.log_prefix(logger, "GetConnection")
def get_connection(url):
    logger.info("Making connection")
    logger.info("Finished making connection")

yields

Download __main__ INFO Downloading file..
Download:GetConnection bar INFO Making connection
Download:GetConnection bar INFO Finished making connection
GetConnection bar INFO Making connection
GetConnection bar INFO Finished making connection

Note: I don't think it is a good idea to have a new Logger instance for each prefix because these instances are not garbage collected. All you need is for some prefix variable to take on a different value depending on context. You don't need a new Logger instance for that -- one LoggerAdapter will do.