Subclassing logging.Formatter Changes Default Behavior of logging.Formatter

Question

I added two handlers with different formatters to my logger. The first one requires subclassing logging.Formatter to do custom formatting. The default formatter will suffice for the second handler.

Let's say the first formatter simply removes newline characters from the message. The following script illustrates what seems like strange behavior:

import logging

logger = logging.getLogger(__name__)

class CustomFormatter(logging.Formatter):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
    def format(self, record):
        record.msg = record.msg.strip().replace('\n', ' ')
        return super().format(record)

h1 = logging.StreamHandler()
formatter1 = CustomFormatter(fmt=None, datefmt=None)
h1.setFormatter(formatter1)
logger.addHandler(h1)

h2 = logging.StreamHandler()
formatter2 = logging.Formatter(fmt=None, datefmt=None)
h2.setFormatter(formatter2)
logger.addHandler(h2)

logger.warning('string with\nmultiple lines')

This outputs the following:

string with multiple lines
string with multiple lines

I expected this instead:

string with multiple lines
string with 
multiple lines

The second formatter should not implement the behavior of CustomFormatter, yet it does. When I reverse the order in which the handlers are added to the logger, this doesn't happen.

Unless I misunderstand subclassing, the behavior of the base class should not be altered by overriding a method in a subclass. This doesn't seem to be a problem when I override methods of classes other than logging.Formatter.

Is this a bug in the logging module, or am I missing something here?

Answer 1

This line was your down fall:

record.msg = record.msg.strip().replace('\n', ' ')

You reassigned the scrubbed string to the record which is used by all remaining handlers/formatters attached to the logger. Copy the record and it works:

import logging
from copy import copy

logger = logging.getLogger(__name__)

class CustomFormatter(logging.Formatter):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
    def format(self, record):
        record = copy(record)
        record.msg = record.msg.strip().replace('\n', ' ')
        return super().format(record)

h1 = logging.StreamHandler()
formatter1 = CustomFormatter(fmt=None, datefmt=None)
h1.setFormatter(formatter1)
logger.addHandler(h1)

h2 = logging.StreamHandler()
formatter2 = logging.Formatter(fmt=None, datefmt=None)
h2.setFormatter(formatter2)
logger.addHandler(h2)

logger.warning('string with\nmultiple lines')

Outputs

string with multiple lines
string with
multiple lines