Python logger, relative time (relativeCreated), can the reference be reset?

user_4002633 0
Viewed 430

I note with interest that Python logging class can emit a relative timestamp:

https://docs.python.org/3/library/logging.html#logrecord-attributes

It is provided with the attribute relativeCreated, but this is documented as:

Time in milliseconds when the LogRecord was created, relative to the time the logging module was loaded.

I'd wondering there is a way to reset this reference time (which by default is when the logging module was loaded).

I'd like to reset that reference time and see times relative to the point in time I did the reset.

logging python
2 Answers

Thanks to @Luv and some further reading this is now solved. In fact it turns out using a Filter rather than Formatter is better approach, but this provides me with a logger that can report relative times (and a newline wrapper I value):

'''
Logging utilities

To use, just import "log" from here and call log.debug(msg).
'''
from time import time
import re, logging
from re import RegexFlag as ref # Specifically to avoid a PyDev Error in the IDE.

log = logging.getLogger("my_logger")

class RelativeFilter(logging.Filter):
    '''
    Abuse of a logging filter to augment the logged record with some relative timing data.

    For a justification of this abuse see: 
        https://docs.python.org/3/howto/logging-cookbook.html#context-info

    The benefits are:

    1) Attached to logger and not to a handler 
        (solution customizing Formatter are attached to handlers)
        See: https://stackoverflow.com/questions/37900521/subclassing-logging-formatter-changes-default-behavior-of-logging-formatter

    2) Is called for every message that the logger processes. 
    '''
    time_reference = None
    time_last = None

    # A simple RE to suck out prefix and postfix newlines from the message and make them
    # separately available. The formatter can choose to render these or not as it sees fit
    # but a formatter like:
    #     '%(prefix)s other stuff %(message)s% other stuff (postfix)s'
    # will wrap the whole log message in the prefix/postfix pair. 
    RE = re.compile(r'^(?P<newlines1>\n*)(?P<message>.*?)(?P<newlines2>\n*)$', ref.DOTALL)

    def filter(self, record):
        now = time()

        if not self.time_reference:
            self.time_reference = now
        if not self.time_last:
            self.time_last = now

        matches = self.RE.match(record.msg).groupdict()

        record.relativeReference = now - self.time_reference
        record.relativeLast = now - self.time_last
        record.prefix = matches['newlines1']
        record.postfix = matches['newlines2']
        record.msg = matches['message']

        self.time_last = now 
        return True

relative_filter = RelativeFilter()

log.addFilter(relative_filter)

The reference time can easily be reset with:

relative_filter.time_reference = time()

for example.

user_40026330

A simple way to rest the time reference is to directly update the module data, which is a "private" logging._startTime variable shown in here in the source code. It can be modified like this:

import logging
import time

def reset_logging_time_reference():
    logging._startTime = time.time()

# As needed
reset_logging_time_reference()

Keep in mind that this is a private variable, which could change with future versions without warning.

user_3270260
Related