Add custom time zone support to twisted.log.FileLogObserver

[zseil]

This patch adds a new method getTimezoneInfo to twisted.log.FileLogObserver, which can be overwritten to write logs in arbitrary local time. It also converts all time manipulation in twisted.log.FileLogObserver to only use datetime objects. This also means that the "%f" format character can be used in FileLogObserver.timeFormat when running on Python 2.6 to gain microsecond resolution in log entries.

However, the patch does double the execution time of FileLogObserver.formatTime with the default format. I had great time writing it, but you decide if it is actually useful :).

[zseil]

add timezone info support to LogFileObservers

[exarkun]

Can you describe how this approach is preferable to setting TZ?

[zseil]

1. Setting TZ affects the entire process, and usually also its child processes. This only changes the behavior of a specific FileLogObserver.

2. Windows doesn't support TZ, and the appropriate API for changing the timezone requires special privileges and affects the entire system.

[exarkun]

(In [29677]) Branching to 'custom-timezone-3546'

[exarkun]

Thanks. Sorry for the lag in responding. Make sure to add the review keyword if you want attention. :)

Those sound like good reasons to do things this way. I have a couple comments about the approach taken in the patch:

1. _NameAndOffsetInfo looks like it's only used to represent the local timezone, and only for an instant (it'll be wrong if you try to keep instances around long enough for DST to change state). What if this were implemented as a _LocalTimezone instead, with the logic for DST in the dst method? This would result in a tzinfo object that is good indefinitely. This also leads into the next point...
2. It would be easier to use this functionality in the trivial case if FileLogObserver accepted a tzinfo object to __init__ and just used this. This removes the need to subclass and override, and the need to construct a new tzinfo for every log message (I'm not sure if that's will make a noticable performance difference or not, but doing something once instead of N times makes sense in general). If we have _LocalTimezone, then an instance of that can be the default value for the new timezone parameter to FileLogObserver.__init__.
3. In the tests, timezoneChangingTest can be eliminated by using TestCase.addCleanup in setTimezone instead.

Let me know if you're not interested in working on this anymore, please, and I'll try to take it over. I'm very interested in your thoughts about the above points, though. Timezones are complicated, and I know my intuition about how to deal with them isn't always correct. :)

If you do want to work on this some more, please make future patches against the branch. Thanks again.

[zseil]

Replying to exarkun:

Thanks. Sorry for the lag in responding. Make sure to add the review keyword if you want attention. :)

Ups, I completely forgot about this ticket, so I really don't mind the lag :). And it is not the only ticket that I left lingering with a reviewed patch, so I guess I should be the one apologizing.

Those sound like good reasons to do things this way. I have a couple comments about the approach taken in the patch:

1. _NameAndOffsetInfo looks like it's only used to represent the local timezone, and only for an instant (it'll be wrong if you try to keep instances around long enough for DST to change state). What if this were implemented as a _LocalTimezone instead, with the logic for DST in the dst method? This would result in a tzinfo object that is good indefinitely. This also leads into the next point...

I don't know how this could be done. The only way to get a reliable UTC offset for local timezone at a given time is to compute the difference between datetime.fromtimestamp() and datetime.utcfromtimestamp() for that exact timestamp (see #2404 and  http://bugs.python.org/issue1647654). tzinfo objects only have access to the UTC timestamp, (when datetime.fromtimestamp() calls their fromutc() method), which can't be converted to local timestamp without knowing the UTC offset beforehand.

2. It would be easier to use this functionality in the trivial case if FileLogObserver accepted a tzinfo object to __init__ and just used this. This removes the need to subclass and override, and the need to construct a new tzinfo for every log message (I'm not sure if that's will make a noticable performance difference or not, but doing something once instead of N times makes sense in general). If we have _LocalTimezone, then an instance of that can be the default value for the new timezone parameter to FileLogObserver.__init__.

We can still do this, and compute the _NameAndOffsetInfo in getTimezoneInfo only when self._tzinfo is None. Should the timeFormat string also become a parameter to the constructor?

3. In the tests, timezoneChangingTest can be eliminated by using TestCase.addCleanup in setTimezone instead.

I don't think addCleanup was available when this patch was written :). Should be easy to fix. timezoneChangingTest() also skips the test when time.tzset() is not available, any suggestions what to do with that?

Let me know if you're not interested in working on this anymore, please, and I'll try to take it over. I'm very interested in your thoughts about the above points, though. Timezones are complicated, and I know my intuition about how to deal with them isn't always correct. :)

I can try to work on this over the weekend, but if I don't make any progress or if you are in a hurry, feel free to take over, I'll be more than happy :)

If you do want to work on this some more, please make future patches against the branch. Thanks again.

Thank you for all the work that you put into Twisted!

[exarkun]

I don't know how this could be done. The only way to get a reliable UTC offset for local timezone at a given time is to compute the difference between datetime.fromtimestamp() and datetime.utcfromtimestamp() for that exact timestamp

Ugh. I hadn't thought about this. I'm probably being hopelessly naive, but fiddling around with the datetime and time... and calendar... modules for a little while minutes, I come up with this:

    def utcoffset(self, dt):
        """
        Return offset of local time from UTC, in minutes east of UTC.

        @rtype: C{datetime.timedelta}
        """
        now = dt.timetuple()
        local = time.mktime(now)
        gmt = calendar.timegm(now)
        return timedelta(seconds=gmt - local)

I'll not be surprised to learn there's something wrong with this, but I can't figure out what it is just now. The trick is really just convincing the underlying platform to reveal what it thinks the offset for the given time should be, right? It seems like time.mktime should be sufficient for that. It adds or subtracts whatever offset is necessary to get to UTC, because its input is supposed to be in local time. calendar.timegm, gross as it is, doesn't actually need to know anything, it just needs to reformat the data so we can do the subtraction. It makes the same conversion as mktime, but neither adds nor subtracts anything. The result is two floats which differ by the local timezone offset at the specified time.

The verbosity is mostly for my sake. I needed to convince myself that this does make sense (or find the hole). I didn't manage to find the hole, so... what'd I miss? :)

[zseil]

Patch against the equally named branch

[zseil]

That would work, however I was more concerned about the fromutc and dst methods. The default tzinfo.fromutc method calls utcoffset with a datetime in UTC timezone, which would lead to errors during DST changes. In addition, it requires a dst method that does not return None, and such methods break datetime.timetuple.

But your solution shows that converting from a UTC datetime to a POSIX timestamp isn't hard (calendar.timegm), so we can overwrite the fromutc and punt with the dst method, it is not used for formatting anyway. Would the new patch work or did I miss something?

The patch has revealed another problem (see the skipped test); previously it was possible to customize the logged timezone by overriding the FileLogObserver.getTimezoneOffset method. It looks like the main purpose of that method was easy testing, but it will probably need some backward compatibility shim now, do you have any ideas in this regard?

The tests will also need to be cleaned up, I can do that when the above issue is solved.

[exarkun]

(In [36641]) Apply custom-timezone-3546.patch

refs #3546

[exarkun]

(In [36642]) Branching to 'custom-timezone-3546-2'