Python logging time since start in seconds

Question

I would like to add the number of seconds my program is up to my logging output.

I've found relativeCreated here but it will give me the milliseconds, e.g. this:

logging.basicConfig(format='{relativeCreated:8.0f}ms {levelname:s} {message:s}', style="{")

Results in

4081ms INFO my message
6012ms INFO another message

But as I expect the running times to be in the hours, I would prefer.

4s INFO my message
6s INFO another message

I tried

logging.basicConfig(format='{relativeCreated / 1000:4.0f}s {levelname:s} {message:s}', style="{")

but this results in

KeyError: 'relativeCreated / 1000'

Answer 1

You can subclass logging.Formatter to modify relativeCreated:

import logging
import time

class RelativeSeconds(logging.Formatter):
    def format(self, record):
        record.relativeCreated = record.relativeCreated // 1000
        return super().format(record)

formatter = RelativeSeconds("%(relativeCreated)ds %(levelname)s %(message)s")

logging.basicConfig()
logging.root.handlers[0].setFormatter(formatter)

logging.error("Test 1")
time.sleep(2)
logging.error("Test 2")

Prints:

0s ERROR Test 1
2s ERROR Test 2

Answer 2

You can use logging.getLogRecordFactory() to add attributes to all LogRecord.

In the code below, a new attribute called uptime is added to each LogRecord. uptime is just relativeCreated divided by 1000:

old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.uptime = record.relativeCreated/1000
    return record

logging.setLogRecordFactory(record_factory)

Then you can use that attribute in your formatter as

%(uptime)d %(levelname)s %(message)s

A complete example here:

import logging.config
import time
import random


logging.config.dictConfig(
    {
        "version": 1,
        "formatters": {
            "default": {
                "format": "%(uptime)07.3f %(uptime)03d %(levelname)-8s %(name)-15s %(message)s",
            }
        },
        "handlers": {
            "console": {
                "class": "logging.StreamHandler",
                "level": "DEBUG",
                "formatter": "default",
                "stream": "ext://sys.stdout",
            }
        },
        'root': {
            "handlers": ["console"],
            "level": "DEBUG",
        },
    }
)


old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.uptime = record.relativeCreated/1000
    return record

logging.setLogRecordFactory(record_factory)

log = logging.getLogger(__name__)


for i in range(10):
    time.sleep(random.uniform(0.5, 2.5))
    log.debug('iteration %d', i)

which will produce

002.308 002 DEBUG    __main__        iteration 0
003.089 003 DEBUG    __main__        iteration 1
005.393 005 DEBUG    __main__        iteration 2