LogRecord does not have expected fields

Question

In Python using the "logging" module, the documentation promises that LogRecord instances will have a number of attributes, which are explicitly listed in the documentation.

However, it appears that this is not always true. When I do not use the logging module's 'basicConfig()' method, the program below shows that the attributes 'asctime' and 'message' are not present in the LogRecords that are passed to the LogHandler's 'emit' method.

import logging

class LoggingHandler(logging.Handler):
    def __init__(self):
        logging.Handler.__init__(self)
    def emit(self, record):
        assert isinstance(record, logging.LogRecord)
        print("LoggingHandler received LogRecord: {}".format(record))

        # List of LogRecord attributes expected when reading the
        # documentation of the logging module:

        expected_attributes = \
            "args,asctime,created,exc_info,filename,funcName,levelname," \
            "levelno,lineno,module,msecs,message,msg,name,pathname," \
            "process,processName,relativeCreated,stack_info,thread,threadName"

        for ea in expected_attributes.split(","):
            if not hasattr(record, ea):
                print("UNEXPECTED: LogRecord does not have the '{}' field!".format(ea))


loggingHandler = LoggingHandler()
rootLogger = logging.getLogger()
rootLogger.addHandler(loggingHandler)

# emit an WARNING message
logging.warning("WARNING MESSAGE")

Running this on Python 3 gives:

$python3 test_logging.py
LoggingHandler received LogRecord: <LogRecord: root, 30, test_logging.py, 28, "WARNING MESSAGE">
UNEXPECTED: LogRecord does not have the 'asctime' field!
UNEXPECTED: LogRecord does not have the 'message' field!

What is going on here? Did I misunderstand the documentation? What needs to be done to make sure that the LogRecord instances have the 'asctime' and 'message' attributes as promised?

Answer 1

It is responsibility of the Formatter to set asctime and message so prior to calling self.format(record), those attributes are undefined. From the doc of the format method:

The record’s attribute dictionary is used as the operand to a string formatting operation. Returns the resulting string. Before formatting the dictionary, a couple of preparatory steps are carried out. The message attribute of the record is computed using msg % args. If the formatting string contains '(asctime)', formatTime() is called to format the event time.

Since your example code does not call self.format(record) it is therefore expected behaviour that those attributes are undefined.

To have message and asctime set, you must first call self.format(record) inside the emit method. Please try

import logging

class LoggingHandler(logging.Handler):
    def emit(self, record):
        assert isinstance(record, logging.LogRecord)
        print("LoggingHandler received LogRecord: {}".format(record))

        self.format(record)

        # List of LogRecord attributes expected when reading the
        # documentation of the logging module:

        expected_attributes = \
            "args,asctime,created,exc_info,filename,funcName,levelname," \
            "levelno,lineno,module,msecs,message,msg,name,pathname," \
            "process,processName,relativeCreated,stack_info,thread,threadName"

        for ea in expected_attributes.split(","):
            if not hasattr(record, ea):
                print("UNEXPECTED: LogRecord does not have the '{}' field!".format(ea))


formatter = logging.Formatter("%(asctime)s")
loggingHandler = LoggingHandler()
loggingHandler.setFormatter(formatter)
rootLogger = logging.getLogger()
rootLogger.addHandler(loggingHandler)

# emit an WARNING message
logging.warning("WARNING MESSAGE")