Dynamically adjust logging format

Question

I want to create a logger for a python program which changes its format during the program run. This necessary as I want the logger to show an information about the part of the program which is currently running in addition to the log message. What I want is something like this (Different parts of the Program - First Part, Second Part should be logged):

2016-11-15 21:09:07,042 - MyProgram - INFO - First Part - One log message
2016-11-15 21:09:07,042 - MyProgram - INFO - Second Part - Another log message

I tried the following code:

import logging

#Set up logger
logfile = str('example.log')
logger = logging.getLogger('MyProgram')
logger.setLevel(logging.DEBUG)
fh = logging.FileHandler(logfile)
fh.setLevel(logging.INFO)

ch = logging.StreamHandler()
ch.setLevel(logging.INFO)

log_status = 'First Part'
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - {0} - %(message)s'.format(log_status))

fh.setFormatter(formatter)
ch.setFormatter(formatter)


logger.addHandler(fh)
logger.addHandler(ch)

#First part of the program
logger.info("One log message")

#Second part of the program
log_status = 'Second Part'

logger.info("Another log message")

What I get, though is the following:

2016-11-15 21:09:07,042 - MyProgram - INFO - First Part - One log message
2016-11-15 21:09:07,042 - MyProgram - INFO - First Part - Another log message

How can I solve this - at best elegantly? Do not hesitate to give advices to the rest of my code as well.

Answer 1

Your solution doesn't work, because when you call '%(asctime)s - %(name)s - %(levelname)s - {0} - %(message)s'.format(log_status), a new string is created and passed to the Formatter and log_status is never used again. You would need a custom Formatter that creates the format string dynamically.

But see how is this problem solved in Python official docs: Logging Cookbook: Adding contextual information to your logging output - see the example with custom logging.Filter.

import logging
from random import choice

class ContextFilter(logging.Filter):
    """
    This is a filter which injects contextual information into the log.

    Rather than use actual contextual information, we just use random
    data in this demo.
    """

    USERS = ['jim', 'fred', 'sheila']
    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']

    def filter(self, record):

        record.ip = choice(ContextFilter.IPS)
        record.user = choice(ContextFilter.USERS)
        return True

if __name__ == '__main__':
    levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
    logging.basicConfig(level=logging.DEBUG,
                        format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
    a1 = logging.getLogger('a.b.c')
    a2 = logging.getLogger('d.e.f')

    f = ContextFilter()
    a1.addFilter(f)
    a2.addFilter(f)
    a1.debug('A debug message')
    a1.info('An info message with %s', 'some parameters')
    for x in range(10):
        lvl = choice(levels)
        lvlname = logging.getLevelName(lvl)
        a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

Output:

2010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message
2010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters
...

Answer 2

Extending Messa's answer, you can change properties of the ContextFilter class instance, and that change will affect the output. For your example code will be the following:

import logging


class ContextFilter(logging.Filter):
    def __init__(self):
        super().__init__()

        self._log_status = ""

    def set_status(self, status: str):
        self._log_status = status

    def filter(self, record: logging.LogRecord) -> bool:
        record.log_status = self._log_status
        return True


# Set up logger
logfile = str('example.log')
logger = logging.getLogger('MyProgram')
logger.setLevel(logging.DEBUG)
fh = logging.FileHandler(logfile)
fh.setLevel(logging.INFO)

ch = logging.StreamHandler()
ch.setLevel(logging.INFO)

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(log_status)s - %(message)s')

fh.setFormatter(formatter)
ch.setFormatter(formatter)

# Now we need to add filters to handlers
f = ContextFilter()
f.set_status("First Part")
fh.addFilter(f)
ch.addFilter(f)

logger.addHandler(fh)
logger.addHandler(ch)

# First part of the program
logger.info("One log message")

# Second part of the program
f.set_status("Second Part")

logger.info("Another log message")

And this code gives the exact output you want:

2021-01-16 20:49:18,848 - MyProgram - INFO - First Part - One log message
2021-01-16 20:49:18,848 - MyProgram - INFO - Second Part - Another log message