How to change the format of logged messages temporarily, in Python?

Question

What is the simplest method for temporarily changing the logging message format, in Python (through the logging module)?

The goal is to have some standard message format, while being able to temporarily add information about some file being read (like its name); the message format should revert to its default when the file is not being read anymore. The program that produces the messages is not aware of what file is being read, so it would be nice if its message automatically included the relevant file name (the error message would be: "ERROR while reading file ***: …" instead of "ERROR: …").

Chretien

Answer 1

Here is a simple solution, that can be deduced from Vinay Sajip's own HOWTO; it basically updates the logging formatter with setFormatter():

import logging

logger = logging.getLogger()  # Logger
logger_handler = logging.StreamHandler()  # Handler for the logger
logger.addHandler(logger_handler)

# First, generic formatter:
logger_handler.setFormatter(logging.Formatter('%(message)s'))
logger.error('error message')  # Test

# New formatter for the handler:
logger_handler.setFormatter(logging.Formatter('PROCESSING FILE xxx - %(message)s'))
logger.error('error message')  # Test

This correctly produces:

error message
PROCESSING FILE xxx - error message

(where xxx can be set dynamically to the file being processed, as asked for in the question).

Chretien

Not sure why this is considered a solution. The handlers determine the log destination, the formatters determine the log format; these two can be considered orthogonal. If I want to temporarily change my log format for a specific logger (e.g. the logger package1.module2) to add some module-specific contextual information, I would want to do this for all the logger's handlers. Enumerating all the handlers which may well be used by all other loggers, temporarily changing the format, then changing it back so as not to break the other loggers is not a solution. – Paramagnetic

This is indeed what would have to be done in this more extreme situation, where one has little control over how handlers are distributed among logger. This is a specific and unfortunate case. Now, doing this can still be done as per this answer, so it looks fine to me (disclaimer: I both asked the question and provided this answer). What would be interesting would be to have a question specific to the case outline in the comment just above, along with the corresponding specific answer; this belongs to another StackOverflow entry. – Chretien

Is there a way to change the format of the logger itself and not just the handler? – Faceharden

Answer 2

There are several ways. Apart from the already documented ones (extra argument to logging calls, LoggerAdapter, Filter) , another way would be to specify a custom formatting class, whose instance you can keep informed about the file being processed. For example:

class FileProcessingFormatter(logging.Formatter):
    def __init__(self, fmt, datefmt=None, current_file=None):
        super(FileProcessingFormatter, self).__init__(fmt, datefmt)
        self.orig_fmt = fmt
        self.current_file = current_file

    def format(self, record):
        if self.current_file is None:
            self._fmt = self.orig_fmt.replace('__FILE_PLACEHOLDER__', '')
        else:
            self._fmt = self.orig_fmt.replace('__FILE_PLACEHOLDER__',
                            ' while processing %r' % self.current_file)
        return super(FileProcessingFormatter, self).format(record)

Instantiate the formatter ...

f = FileProcessingFormatter('%(levelname)s__FILE_PLACEHOLDER__ %(message)s')
for h in relevant_handlers:
    h.setFormatter(f)

Process files ...

f.current_file = fn
process_file(fn)
f.current_file = None

This is very simplistic - for example, not for use in threaded environments if file processing is done by different threads concurrently.

Update: Although the root logger's handlers are accessible via logging.getLogger().handlers, this is an implementation detail that could change. As your requirement is not that basic, you could perhaps use dictConfig() to configure your logging (available via the logutils project for older versions of Python).

Parve

Thanks. Can one get relevant_handlers for a handler defined only through logging.basicConfig()? if not, how can the relevant_handlers be defined? – Chretien

Thanks for the update. I need to read your Logging HOWTO–and maybe more–before I can implement any concrete solution… – Chretien

This didn't work for me in Python 3.8. I've checked that self has the correct _fmt attribute before return super(FileProcessingFormatter, self).format(record), but it will still format with the original self._fmt – Bugbear

Answer 3

I don't recommend this; but you can say assume the first root handler is the one that's screwed up and modify it directly

import logging
ROOT_LOGGER = logging.getLogger()
ROOT_LOGGER.handlers[0].setFormatter(logging.Formatter(
    '%(asctime)s:%(levelname)s:%(name)s:%(message)s\n'
))

if you are in any system with managed logging; this is probably going to shoot your foot; it really would be best to be able to determine an exact reference to the handler you want to modify and modify that;

but nobody cares how broken it is if it works right?/s

Monosome

This may be warranted as a quick and dirty fix for a temporary solution. People who care about code that may break in the future do care if code mostly works but is fundamentally broken, as this increases the risk that the code will fail later for some mysterious and costly reason. – Chretien

This helped me to get logging with timestamps working in a SikuliX script, where logging.basicConfig() doesn't work at all for some reason. – Pelias

Answer 4

To my knowledge dictConfig(), as mentioned in the update by @Vinay Sajip, is the best way to go.

Here is a working example in Python 3.8:

import logging
from logging.config import dictConfig    
FI_PATH_CONSUMERS_LOG = "/project/test_log.log"
LOG_FORMAT = "%(asctime)s %(levelname)-8s [%(name)s] %(message)s"
LOG_LEVEL = "INFO"
LOG_DATEFMT = "%Y-%m-%d %H:%M:%S"

logging.basicConfig(
    filename=FI_PATH_CONSUMERS_LOG,
    format=LOG_FORMAT,
    level=getattr(logging, LOG_LEVEL),
    datefmt=LOG_DATEFMT,
)

def create_new_format(format_additions: str=""):
    """
    This adjusts both loggers, but you can
    also make changes specific to each.
    """
    alt_new_formats = {
        "event_format": {
            "format": LOG_FORMAT + format_additions,
            "datefmt": LOG_DATEFMT,
        },
    }

    changed_setting = {
        "version": 1,
        "formatters": alt_new_formats,
        "handlers": {
            "to_file": {
                "class": "logging.FileHandler",
                "filename": FI_PATH_CONSUMERS_LOG,
                "formatter": "event_format",
                "level": LOG_LEVEL,
            },
        },
        "loggers": {
            "": {
                "handlers": ["to_file"],
            },
        },
        "disable_existing_loggers": False,
    }
    return changed_setting

Which you can run like so:

logger = logging.getLogger()  # root logger
logger_2 = logging.getLogger("logger 2")  # child logger with name "logger 2"
msg_test = "Testing message."

logger.info(msg_test)
logger_2.info(msg_test)

dictConfig(create_new_format(" [Adjust formatting]"))
logger.info(msg_test)
logger_2.info(msg_test)

dictConfig(create_new_format())
logger.info(msg_test)
logger_2.info(msg_test)

And which will give you the following output:

2021-09-16 14:47:48 INFO     [root] Testing message.
2021-09-16 14:47:48 INFO     [logger 2] Testing message.
2021-09-16 14:47:48 INFO     [root] Testing message. [Adjust formatting]
2021-09-16 14:47:48 INFO     [logger 2] Testing message. [Adjust formatting]
2021-09-16 14:47:48 INFO     [root] Testing message.
2021-09-16 14:47:48 INFO     [logger 2] Testing message.

Positively

Thanks. I updated the code so that it is more robust: changing the parameters in basicConfig() prevented the code from restoring the logging format correctly, at the end. – Chretien

Are you sure? Because the edit stopped the example code from running, making it not a working example anymore.. If I remember correctly I also tried initializing with the dictConfig instead of passing the variables to basicConfig, but it didn't work then either. I couldn't say why that is. Passing the variables to basicConfig does introduce a "repeating yourself" aspect, but working with constants, as was done in the example already, should alleviate that aspect. – Positively

Reverted the change to make the code work again, also refactored the code to make it easier to read. – Positively

yes, i agree, creating two separate loggers is the most robust way to go; it also allows easily duplicating messages both to log file and the console, either with same or separate formatters (logger parameter propagate) – Dramaturge

Answer 5

if you want to dynamic change format of log. it could be made like this.

logger = logging.getLogger()
# Change format of handler for the logger
logger.handlers[0].setFormatter(logging.Formatter('%(asctime)s,%(msecs)d %(name)s %(levelname)s %(message)s'))
# Print log
logging.info(log)
# return other format
logger.handlers[0].setFormatter(logging.Formatter('%(message)s'))

Cassirer

This doesn't return to the previous logging message format: instead it changes the format to some other format. Also, explaining why handlers[0] is appropriate would be interesting. – Chretien