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)?

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

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.