TimedRotatingFileHandler can clobber files when set_datetime_format != utc

[aczapszys]

In our local app we're using localtime cem/utilities/logger.py: logbook.set_datetime_format('local')

But in TimedRotatingFileHandler, the default "now" is utcnow. So, TimedRotatingFileHandler.init computes

utcnow = 2018-12-04 00:00:01
timestamp = '2018-12-04'
logger.info calls emit with Message.time = local time 2018-12-03 16:00:01
new_timestamp = '2018-12-03'
if new_timestamp != timestamp:
    open new file in overwrite mode

After calling logbook.set_datetime_format('local'), here's what the factories look like.

(Pdb) import logbook.handlers
(Pdb) logbook.handlers._datetime_factory
<built-in method utcnow of type object at 0x7f984b42eda0>

(Pdb) import logbook.base
(Pdb) logbook.base._datetime_factory
<built-in method now of type object at 0x7f984b42eda0>

Here's a possible approach to make this work as expected:

diff --git a/logbook/base.py b/logbook/base.py
index 9ad10b4..c10958f 100644
--- a/logbook/base.py
+++ b/logbook/base.py
@@ -31,6 +31,8 @@ except ImportError:
         _missing, group_reflected_property, ContextStackManager, StackedObject)

 _datetime_factory = datetime.utcnow
+def datetime_factory:
+    _datetime_factory()

 def set_datetime_format(datetime_format):
@@ -440,7 +442,7 @@ class LogRecord(object):
         assert not self.late, 'heavy init is no longer possible'
         self.heavy_initialized = True
         self.process = os.getpid()
-        self.time = _datetime_factory()
+        self.time = datetime_factory()
         if self.frame is None and Flags.get_flag('introspection', True):
             self.frame = sys._getframe(1)
         if self.exc_info is True:
diff --git a/logbook/handlers.py b/logbook/handlers.py
index b06f966..3c6d1d8 100644
--- a/logbook/handlers.py
+++ b/logbook/handlers.py
@@ -30,7 +30,7 @@ from textwrap import dedent
 from logbook.base import (
     CRITICAL, ERROR, WARNING, NOTICE, INFO, DEBUG, TRACE, NOTSET, level_name_property,
     _missing, lookup_level, Flags, ContextObject, ContextStackManager,
-    _datetime_factory)
+    datetime_factory)
 from logbook.helpers import (
     rename, b, _is_text_stream, is_unicode, PY2, zip, xrange, string_types,
     integer_types, reraise, u, with_metaclass)
@@ -900,7 +900,7 @@ class TimedRotatingFileHandler(FileHandler):
         self.basename, self.ext = os.path.splitext(os.path.abspath(filename))
         self.timed_filename_for_current = timed_filename_for_current

-        self._timestamp = self._get_timestamp(_datetime_factory())
+        self._timestamp = self._get_timestamp(datetime_factory())
         timed_filename = self.generate_timed_filename(self._timestamp)

         if self.timed_filename_for_current:

[vmalloc]

Thanks for reporting! If you can come up with an example test that demonstrates the bug and a PR for fixing it, I'll gladly review and merge it.

[plzak]

I have also encountered a similar problem with TimedRotatingFileHandler. It occurs only when logbook.set_datetime_format("local") is used. According to the description of this bug, the cause might be the same. My problem can be reproduced like this (for timezone ahead of UTC): 1/ Wait until local time rolls over midnight, so now the date is different in UTC zone (e.g. 01.11.2018) and local zone (e.g. 02.11.2018). 2/ Run the application. It creates a new logfile named after the local date (e.g. app-2018-11-02.log). The file contains correct logging data. 3/ Run the application again. The current logfile (app-2018-11-02.log) is rewritten, data are not appended. The file contains only data from the second run. -> BUG The previous logfile (app-2018-11-01.log) is not touched. If the local time and UTC time have the same date, the logfile is appended correctly.