Prevent rounding (or at least length overflow) when logging floats (specifically "msecs") using f-string style format specification

A bit of background:

The Python docs say:

In the case of {}-formatting, you can specify formatting flags by placing them after the attribute name, separated from it with a colon. For example: a placeholder of {msecs:03d} would format a millisecond value of 4 as 004.

However, this does not work, since the logging record's msecs value is actually a float:

>>> record.msecs
275.38108825683594

so trying to use the example {} formatting in the docs raises a ValueError:

>>> f'{record.msecs:03d}'
*** ValueError: Unknown format code 'd' for object of type 'float'

Old-style %-formating with 03d works fine for a float:

>>> '%03d' % record.msecs
'275'

Based on the above findings, I used a float format specification in my logging definition, like this:

logging.basicConfig(
    level=logging.INFO,
    format="{asctime}.{msecs:0>3.0f} [{levelname:.1s}] {message}",
    datefmt="%Y-%m-%d %H:%M:%S",
    style="{",
)

which seemed to be working well, until I noticed this log entry:

2021-03-25 22:37:18.993 [I] ...
2021-03-25 22:37:18.997 [I] ...
2021-03-25 22:37:18.1000 [I] ...
2021-03-25 22:37:19.002 [I] ...
2021-03-25 22:37:19.004 [I] ...

which happens when the logging record's msecs float value is >= 999.5:

>>> t1 = 999.499999
>>> t2 = 999.5
>>> print(f"{t1:0>3.0f} {t2:0>3.0f}")
999 1000

Obviously I'd prefer .1000 to be logged as .000 (rounding without overflowing the 3-digit length) if there was a way to also increment the {asctime} part of the timestamp by a second. But I'd be fine with just logging .999 (truncating to int instead of rounding) since this overflow only happens a very small percent of the time, and for my purposes this logging isn't that critical.

Any way to do this, other than going back to old-style %-based formatting?

Solution

You can override the default millisecond format:

logging.basicConfig(
    level=logging.INFO,
    format="{asctime} ...{msecs:3.1f} ...{msecs:3.0f} [{levelname:.1s}] {message}",
    # datefmt="%Y-%m-%d %H:%M:%S",
    style="{",
)
logging.Formatter.default_msec_format = '%s.%03d'

I think that achieves what you want the milliseconds are truncated to three digits. Unfortunately specifying datefmt messes that up and the milliseconds don't display.

Here are custom converter and formatTime functions that can be used to replace the default Formatter methods. These will allow you to specify the datefmt in the configuration. They work together so they both have to be used.

import logging

def converter(self,t):
    '''Returns a tuple (time.struct_time, int)
    '''

    # separate seconds from fractional seconds 
    # round the fraction,
    # adjust the seconds if needed
    # turn the fraction into an integer
    seconds = int(t)
    msec = round(t - seconds,3)
    if msec > .9995:
        msec = 0
        seconds += 1
    else:
        msec = int(1000 * msec)
    # parts = list(time.localtime(seconds))
    # parts[-2] = msec
    t = time.localtime(seconds)
    return t,msec

def formatTime(self, record, datefmt=None):
    """
    Return the creation time of the specified LogRecord as formatted text.
    This method should be called from format() by a formatter which
    wants to make use of a formatted time. This method expects the
    converter to return a (time.struct_time,int) tuple where the int is
    between 0 and 999.
    The int is the rounded msec of the record's creation time.
    """
    ct,msec = self.converter(record.created)
    if datefmt:
        s = time.strftime(datefmt, ct)
    else:
        s = time.strftime(self.default_time_format, ct)
    s = f'{s}.{msec:03d}'
    return s

logging.basicConfig(
    level=logging.INFO,
    format="{asctime} | {message}",
    datefmt="%Y-%m-%d %H:%M:%S",
    style="{",
)

logging.Formatter.converter = converter
logging.Formatter.formatTime = formatTime
logging.info('foo')

That log looks like:

2021-03-27 16:12:05.498 | foo

If the datefmt argument does not end with the seconds then tacking on the milliseconds would be silly so maybe that should be checked for.

def formatTime(self, record, datefmt=None):
    """
    Return the creation time of the specified LogRecord as formatted text.
    This method should be called from format() by a formatter which
    wants to make use of a formatted time. This method expects the
    converter to return a (time.struct_time,int) tuple where the int is
    between 0 and 999.
    The int is the rounded msec of the record's creation time.
    """
    ct,msec = self.converter(record.created)
    if datefmt:
        s = time.strftime(datefmt, ct)
    else:
        s = time.strftime(self.default_time_format, ct)
        # s = f'{s}.{msec:03d}'
        # if self.default_msec_format:
        #     s = self.default_msec_format % (s, record.msecs)
    if datefmt[-1] == 'S':
        s = f'{s}.{msec:03d}'
    return s