CODEWITHSUNDEEP
pythonloggingtimepython-logging
Jonathan Livni
Jonathan Livni

Reputation: 107062

Python logging: use milliseconds in time format

By default logging.Formatter('%(asctime)s') prints with the following format:

2011-06-09 10:54:40,638

where 638 is the millisecond. I need to change the comma to a dot:

2011-06-09 10:54:40.638

To format the time I can use:

logging.Formatter(fmt='%(asctime)s',datestr=date_format_str)

however the documentation doesn't specify how to format milliseconds. I've found this SO question which talks about microseconds, but a) I would prefer milliseconds and b) the following doesn't work on Python 2.6 (which I'm working on) due to the %f:

logging.Formatter(fmt='%(asctime)s',datefmt='%Y-%m-%d,%H:%M:%S.%f')

Upvotes: 293

Views: 194569

Answers (18)

David Gard
David Gard

Reputation: 12047

To allow users to specify a datefmt that contains %f, you could create a custom Formatter and override the formatTime() method.

Because the override is using super() to get the default formatted time, this code doesn't change the default behaviour of the formatTime() method.

Note that the code will truncate %f to milliseconds, as opposed to microseconds.

The code below does the following -

  1. Calls super() to get the formatted time.
  2. Creates the milliseconds (msecs) to use in the formatted time, using record.msecs as the base.
  3. Splits the formatted time using %f as the separator.
  4. Joins the split formatted time on msecs.
  5. Returns the formatted time (either original, or updated with milliseconds if appropriate).
import logging

class CustomFormatter(logging.Formatter):

    def formatTime(self, record: logging.LogRecord, datefmt: str|None=None) -> str:
        '''Allow `datafmt` to interpret `%f` as milliseconds.'''

        s = super().formatTime(record, datefmt)
        if '%f' in s:
            s_split = s.split('%f')
            msecs = '%03d' % record.msecs
            s = msecs.join(s_split)

        return s
        
fmt='%(asctime)s %(levelname)-8s => %(message)s'
datefmt='%Y-%m-%d %H:%M:%S.%f'

stdout_handler = logging.StreamHandler()
stdout_handler.setFormatter(CustomFormatter(fmt, datefmt))

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
logger.addHandler(stdout_handler)

logger.info('FooBar')

Upvotes: 0

RubenLaguna
RubenLaguna

Reputation: 24656

TLDR: Although it's not what the OP asked for, if you want to print all log timestamps as ISO8601 with milliseconds and UTC offset you can overwrite the default formatter formatTime like this:

import logging
from datetime import datetime

def formatTime(self, record, datefmt=None):
    return datetime.fromtimestamp(record.created).astimezone().isoformat(timespec='milliseconds')

logging.Formatter.formatTime = formatTime

produces logs like this

2024-01-15T19:23:01.371+01:00 INFO     __main__        test 1

The %(asctime)s is formatted through logging.Formatter.formatTime(self, record), the documentation states that formatTime will use time.strftime() which is not the same as datetime.strftime(). time.strftime has no way of printing milliseconds , datetime.strftime() on the other hand has %f. So you can't use %f on the datefmt.

If you only need to change the , (comma) to a . (dot) you have the simple options from other answers combining %(asctime)s, and %(msecs)03d like so (using logging.config.dictConfig() and a YAML file)

# log_config.yml
version: 1
formatters:
  default:
    format: "%(asctime)s.%(msecs)03d %(levelname)-8s %(name)-15s %(message)s"
    datefmt: "%Y-%m-%d %H:%M:%S"

But that will not work if you need to add the UTC offset /timezone after the milliseconds, for example.

In order to have a more sensible timestamp formatting you can implement your own formatter that subclasses logging.Formatter and just override formatTime. For example, the following formatter will produce logs with timestamps in ISO8601 including milliseconds and UTC offset by using datetime.isoformat():

# myformatter.py
import logging
from datetime import datetime

class CustomFormatter(logging.Formatter):
    def formatTime(self, record, datefmt=None):
        return datetime.fromtimestamp(record.created).astimezone().isoformat(timespec='milliseconds')

In the code above

# log_config.yml
version: 1
formatters:
  default:
    class: myformatter.CustomFormatter
    format: "%(asctime)s %(levelname)-8s %(name)-15s %(message)s"
handlers:
  console:
    class: logging.StreamHandler
    stream: ext://sys.stdout
    formatter: default
loggers:
  root:
    level: INFO
    handlers: [console]

The above configuration results in :

2024-01-15T18:40:42.006307+01:00 INFO     __main__        test 1

where %(asctime)s value comes from CustomFormatter.formatTime()

Ultimately you can replace the logging.Formatter.formatTime with your own implementation instead of creating a new formatter:

import logging
import logging.config
import yaml
from datetime import datetime

def formatTime(self, record, datefmt=None):
    return datetime.fromtimestamp(record.created).astimezone().isoformat(timespec='milliseconds')

logging.Formatter.formatTime = formatTime # no need for a custom formatter if we monkeypatch the default formatter

with open("log_config.yml", "rt") as f:
    logging.config.dictConfig(yaml.safe_load(f.read()))
    
logger = logging.getLogger(__name__) # __name__

myvar = 1
logger.info("test %s", myvar)

Upvotes: 11

seidnerj
seidnerj

Reputation: 431

My take on this is the following:

class MicrosecondsFormatter(logging.Formatter):
    def formatTime(self, record, datefmt=None):
        return super(MicroSecondsFormatter, self).formatTime(record, self.datefmt.replace('%f', str(datetime.fromtimestamp(record.created).microsecond).ljust(6, '0')))

logging.Formatter = MicrosecondsFormatter

The above adds support for "%f" in the date format, and so one can continue using the logging module as usual, for example:

log_format = f'%(asctime)s %(levelname)-8s %(message)s'
log_date_format = '%d/%m/%Y %H:%M:%S.%f %z'

logging.basicConfig(stream=sys.stdout,
                    format=log_format,
                    datefmt=log_date_format,
                    level=logging.INFO)

Upvotes: 1

Mark Lakata
Mark Lakata

Reputation: 20818

All I needed to do was set default_msec_format attribute before creating the formatter.

logging.Formatter.default_msec_format = '%s.%03d'                        # Just add this line
formatter = logging.Formatter('%(asctime)s %(levelname)s - %(message)s')

Upvotes: 4

unutbu
unutbu

Reputation: 879083

Please note Craig McDaniel's solution is preferable, unless you need support for all ISO 8601 format codes.

logging.Formatter's formatTime method looks like this:

def formatTime(self, record, datefmt=None):
    ct = self.converter(record.created)
    if datefmt:
        s = time.strftime(datefmt, ct)
    else:
        t = time.strftime("%Y-%m-%d %H:%M:%S", ct)
        s = "%s,%03d" % (t, record.msecs)
    return s

Notice the comma in "%s,%03d". This can not be fixed by specifying a datefmt because ct is a time.struct_time and these objects do not record milliseconds.

If we change the definition of ct to make it a datetime object instead of a struct_time, then (at least with modern versions of Python) we can call ct.strftime and then we can use %f to format microseconds:

import logging
import datetime as dt

class MyFormatter(logging.Formatter):
    converter=dt.datetime.fromtimestamp
    def formatTime(self, record, datefmt=None):
        ct = self.converter(record.created)
        if datefmt:
            s = ct.strftime(datefmt)
        else:
            t = ct.strftime("%Y-%m-%d %H:%M:%S")
            s = "%s,%03d" % (t, record.msecs)
        return s

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

console = logging.StreamHandler()
logger.addHandler(console)

formatter = MyFormatter(fmt='%(asctime)s %(message)s',datefmt='%Y-%m-%d,%H:%M:%S.%f')
console.setFormatter(formatter)

logger.debug('Jackdaws love my big sphinx of quartz.')
# 2011-06-09,07:12:36.553554 Jackdaws love my big sphinx of quartz.

Or, to get milliseconds, change the comma to a decimal point, and omit the datefmt argument:

class MyFormatter(logging.Formatter):
    converter=dt.datetime.fromtimestamp
    def formatTime(self, record, datefmt=None):
        ct = self.converter(record.created)
        if datefmt:
            s = ct.strftime(datefmt)
        else:
            t = ct.strftime("%Y-%m-%d %H:%M:%S")
            s = "%s.%03d" % (t, record.msecs)
        return s

...
formatter = MyFormatter(fmt='%(asctime)s %(message)s')
...
logger.debug('Jackdaws love my big sphinx of quartz.')
# 2011-06-09 08:14:38.343 Jackdaws love my big sphinx of quartz.

Upvotes: 95

anishtain4
anishtain4

Reputation: 2402

Using this smart answer for the timezone and the chosen answer, you can construct the millisecond and timezone with your desired format:

import logging
import time

if __name__ == "__main__":
    tz = time.strftime('%z')
    logging.basicConfig(
        format=(
            "%(asctime)s.%(msecs)03d" + tz + " %(levelname)s "
            "%(pathname)s:%(lineno)d[%(threadName)s]: %(message)s"
        ),
        level=logging.DEBUG,
        datefmt="%Y-%m-%dT%H:%M:%S",
    )
    logging.info("log example")

Personally, I like to keep all the logs in UTC but also have this explicitly in the log as a datetime without a timezone is meaningless in a multizone application:

    logging.Formatter.converter = time.gmtime
    logging.basicConfig(
        format=(
            "%(asctime)s.%(msecs)03d+0000 %(levelname)s "
            "%(pathname)s:%(lineno)d[%(threadName)s]: %(message)s"
        ),
        level=logging.DEBUG,
        datefmt="%Y-%m-%dT%H:%M:%S",
    )

Upvotes: 1

Master James
Master James

Reputation: 1777

Adding msecs was the better option, Thanks. Here is my amendment using this with Python 3.5.3 in Blender

import logging

logging.basicConfig(level=logging.DEBUG, 
    format='%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s',
    datefmt='%Y-%m-%d %H:%M:%S'
)
log = logging.getLogger(__name__)
log.info("Logging Info")
log.debug("Logging Debug")

Upvotes: 71

Craig McDaniel
Craig McDaniel

Reputation: 5700

This should work too:

logging.Formatter(
    fmt='%(asctime)s.%(msecs)03d',
    datefmt='%Y-%m-%d,%H:%M:%S'
)

Upvotes: 547

jrc
jrc

Reputation: 21881

I figured out a two-liner to get the Python logging module to output timestamps in RFC 3339 (ISO 1801 compliant) format, with both properly formatted milliseconds and timezone and without external dependencies:

import datetime
import logging

# Output timestamp, as the default format string does not include it
logging.basicConfig(format="%(asctime)s: level=%(levelname)s module=%(module)s msg=%(message)s")

# Produce RFC 3339 timestamps
logging.Formatter.formatTime = (lambda self, record, datefmt=None: datetime.datetime.fromtimestamp(record.created, datetime.timezone.utc).astimezone().isoformat())

Example:

>>> logging.getLogger().error("Hello, world!")
2021-06-03T13:20:49.417084+02:00: level=ERROR module=<stdin> msg=Hello, world!

Alternatively, that last line could be written out as follows:

def formatTime_RFC3339(self, record, datefmt=None):
    return (
        datetime.datetime.fromtimestamp(record.created, datetime.timezone.utc)
        .astimezone()
        .isoformat()
    )

logging.Formatter.formatTime = formatTime_RFC3339

That method could also be used on specific formatter instances, rather than overriding at the class level, in which case you will need to remove self from the method signature.

Upvotes: 15

Shahid Tariq
Shahid Tariq

Reputation: 931

After burning some of my precious time the below hack worked for me. I just updated my formatter in settings.py and added datefmt as %y/%b/%Y %H:%M:%S and appended the milliseconds to the asctime like this {asctime}.{msecs:0<3.0f}

E.G:

    'formatters': {
        'verbose': {
            'format': '[{asctime}.{msecs:0<3.0f}] {levelname} [{threadName:s}] {module} → {message}',
            'datefmt': "%y/%b/%Y %H:%M:%S",
            'style': '{',
        },
    }

Upvotes: 3

torrentails
torrentails

Reputation: 109

A simple expansion that doesn't require the datetime module and isn't handicapped like some other solutions is to use simple string replacement like so:

import logging
import time

class MyFormatter(logging.Formatter):
    def formatTime(self, record, datefmt=None):
        ct = self.converter(record.created)
        if datefmt:
            if "%F" in datefmt:
                msec = "%03d" % record.msecs
                datefmt = datefmt.replace("%F", msec)
            s = time.strftime(datefmt, ct)
        else:
            t = time.strftime("%Y-%m-%d %H:%M:%S", ct)
            s = "%s,%03d" % (t, record.msecs)
        return s

This way a date format can be written however you want, even allowing for region differences, by using %F for milliseconds. For example:

log = logging.getLogger(__name__)
log.setLevel(logging.INFO)

sh = logging.StreamHandler()
log.addHandler(sh)

fm = MyFormatter(fmt='%(asctime)s-%(levelname)s-%(message)s',datefmt='%H:%M:%S.%F')
sh.setFormatter(fm)

log.info("Foo, Bar, Baz")
# 03:26:33.757-INFO-Foo, Bar, Baz

Upvotes: 5

not2qubit
not2qubit

Reputation: 16912

Many outdated, over-complicated and weird answers here. The reason is that the documentation is inadequate and the simple solution is to just use basicConfig() and set it as follows:

logging.basicConfig(datefmt='%Y-%m-%d %H:%M:%S', format='{asctime}.{msecs:0<3.0f} {name} {threadName} {levelname}: {message}', style='{')

The trick here was that you have to also set the datefmt argument, as the default messes it up and is not what is (currently) shown in the how-to python docs. So rather look here.

An alternative and possibly cleaner way, would have been to override the default_msec_format variable with:

formatter = logging.Formatter('%(asctime)s')
formatter.default_msec_format = '%s.%03d'

However, that did not work for unknown reasons.

PS. I am using Python 3.8.

Upvotes: 9

Jeff Bryner
Jeff Bryner

Reputation: 129

tl;dr for folks looking here for an ISO formatted date:

instead of using something like '%Y-%m-%d %H:%M:%S.%03d%z', create your own class as @unutbu indicated. Here's one for iso date format:

import logging
from time import gmtime, strftime

class ISOFormatter(logging.Formatter):
    def formatTime(self, record, datefmt=None):
        t = strftime("%Y-%m-%dT%H:%M:%S", gmtime(record.created))
        z = strftime("%z",gmtime(record.created))
        s = "%s.%03d%s" % (t, record.msecs,z)        
        return s

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

console = logging.StreamHandler()
logger.addHandler(console)

formatter = ISOFormatter(fmt='%(asctime)s - %(module)s - %(levelname)s - %(message)s')
console.setFormatter(formatter)

logger.debug('Jackdaws love my big sphinx of quartz.')
#2020-10-23T17:25:48.310-0800 - <stdin> - DEBUG - Jackdaws love my big sphinx of quartz.

Upvotes: -2

chrisharrel
chrisharrel

Reputation: 336

If you prefer to use style='{', fmt="{asctime}.{msecs:0<3.0f}" will 0-pad your microseconds to three places for consistency.

Upvotes: 3

Pasindu Madushan
Pasindu Madushan

Reputation: 1

As of now the following works perfectly with python 3 .

         logging.basicConfig(level=logging.DEBUG,
                     format='%(asctime)s %(levelname)-8s %(message)s',
                     datefmt='%Y/%m/%d %H:%M:%S.%03d',
                     filename=self.log_filepath,
                     filemode='w')

gives the following output

2020/01/11 18:51:19.011 INFO

Upvotes: -4

Slapy
Slapy

Reputation: 373

If you are using arrow or if you don't mind using arrow. You can substitute python's time formatting for arrow's one.

import logging

from arrow.arrow import Arrow


class ArrowTimeFormatter(logging.Formatter):

    def formatTime(self, record, datefmt=None):
        arrow_time = Arrow.fromtimestamp(record.created)

        if datefmt:
            arrow_time = arrow_time.format(datefmt)

        return str(arrow_time)


logger = logging.getLogger(__name__)

default_handler = logging.StreamHandler()
default_handler.setFormatter(ArrowTimeFormatter(
    fmt='%(asctime)s',
    datefmt='YYYY-MM-DD HH:mm:ss.SSS'
))

logger.setLevel(logging.DEBUG)
logger.addHandler(default_handler)

Now you can use all of arrow's time formatting in datefmt attribute.

Upvotes: 3

Mickey B
Mickey B

Reputation: 441

The simplest way I found was to override default_msec_format:

formatter = logging.Formatter('%(asctime)s')
formatter.default_msec_format = '%s.%03d'

Upvotes: 34

Jonathan Livni
Jonathan Livni

Reputation: 107062

After instantiating a Formatter I usually set formatter.converter = gmtime. So in order for @unutbu's answer to work in this case you'll need:

class MyFormatter(logging.Formatter):
    def formatTime(self, record, datefmt=None):
        ct = self.converter(record.created)
        if datefmt:
            s = time.strftime(datefmt, ct)
        else:
            t = time.strftime("%Y-%m-%d %H:%M:%S", ct)
            s = "%s.%03d" % (t, record.msecs)
        return s

Upvotes: 4

Related Questions