Python logging module emits wrong timezone information

Question

I'm running into an issue with Python 2.7 logging module. My system is Ubuntu 14.04 64bit, and I live in Italy (currently UTC+1, no daylight saving); the system is properly configured as such.

I want to emit logging lines in the current timezone, complete of correct timezone offset information.

Consider the following snippet:

#!/usr/bin/env python
import sys
print sys.version_info
import commands
print "System time: %s" % commands.getoutput("date --rfc-3339=seconds")

import logging
import datetime
logging.basicConfig(level=logging.DEBUG, stream=sys.stdout, 
                        format="%(asctime)s:" + logging.BASIC_FORMAT,
                         datefmt="%Y-%m-%dT%H:%M:%S%z")

logger = logging.getLogger()
logger.info("Something happened")

Which yields this result:

sys.version_info(major=2, minor=7, micro=6, releaselevel='final', serial=0)
System time: 2015-01-09 11:21:44+01:00
2015-01-09T11:21:44+0000:INFO:root:Something happened

So, the system knows the proper time AND offset, while Python seems to get the time wrong.

In datetime docs, it is said that for %z in strftime the result is"UTC offset in the form +HHMM or -HHMM (empty string if the the object is naive)".

So, I would have expected either of the following results:

1. The logging module wants to log in UTC, so I would get something like 10:21.44 and a +0000 offset;
2. The logging module wants to log in local time, so I would get something like 11:21:44 and a +01000 offset;
3. The logging module offers naive datetime objects, and we get absolutely nothing as on offset.

On the contrary, here I seem to get an unpredictable - and plainly wrong - result. What's up? Is it possible to configure the logging module to do what I want WITHOUT overriding the converter function of logging.Formatter objects (where, of course, I can do whatever I like, but this looks plainly a bug to me)?

Yim

The Python date/time classes don't have timezones assigned at all, even if they have the capacity to handle it. You need to assign one explicitly. pytz is a good source, but I don't know if you can propagate that into logging. – Hypomania

Answer 1

logging uses time module that doesn't store timezone in a time tuple and time.strftime() unlike datetime.strftime() doesn't support %z on Python 2. You could override Formatter.formatTime() method to use timezone-aware datetime objects as @dmg suggested instead:

#!/usr/bin/env python
import logging
from datetime import datetime

import tzlocal # $ pip install tzlocal

def posix2local(timestamp, tz=tzlocal.get_localzone()):
    """Seconds since the epoch -> local time as an aware datetime object."""
    return datetime.fromtimestamp(timestamp, tz)

class Formatter(logging.Formatter):
    def converter(self, timestamp):
        return posix2local(timestamp)

    def formatTime(self, record, datefmt=None):
        dt = self.converter(record.created)
        if datefmt:
            s = dt.strftime(datefmt)
        else:
            t = dt.strftime(self.default_time_format)
            s = self.default_msec_format % (t, record.msecs)
        return s

logger = logging.getLogger(__name__)
handler = logging.StreamHandler()
handler.setFormatter(Formatter("%(asctime)s %(message)s", "%Y-%m-%dT%H:%M:%S%z"))
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)

logger.info('something happened')

Output

2015-01-09T18:30:54+0100 something happened

Inclinable

That seems the way to go... it's really a bug in the logging module. I'll try soon and let you know. – Yim

I used "%Y-%m-%dT%H:%M:%S%z" for my Formatter, and it fixed my issue with elasticsearch timestamp parsing, thanks! – Wore

Answer 2

EDIT:

You can set the time formatter by:

logging.Formatter.converter = time.localtime

to yield local time.

Or:

logging.Formatter.converter = time.gmtime

to get UTC.

As for local time + time zone, first of all, logging.Formatter uses time, which as you can see here does not really support TZ properly (look at the footnote).

The cleanest alternative would be to write your own formatter that uses datetime, which apparently has quite the stupid way of using TZ. Basically to make your object "aware", I would go with pytz.

Quake

I know that setting logging.Formatter.converter allows me to change the behaviour of formatter, but I want proper formatting of LOCAL time with current offset. Your first proposal is the default (which yields an incorrect offset), while the second proposal just "sort of work" by yielding an UTC time - which then gets the +0000 timestamp. – Yim

Good point, delved into logger.Formatter and it seems to me you'll have to make do with time.gmtime – Quake