Dear list,
log records in the Python logging library always use timestamps provided
by `time.time()`, i.e. the usual system clock (UTC, CLOCK_REALTIME).
This time is used as absolute timestamp in log records and for
timestamps relative to the load of the library (Lib/logging/__init__.py:
`_startTime`).
I would like to receive feedback to and propose the attached (and
possibly incomplete) patch that allows the programmer to provide a
custom callable to get the time instead of `time.time()`.
For example, this could be:
clock = lambda: time.clock_gettime(time.CLOCK_TAI)
and the callable could be provided during initial logging setup
logging.basicConfig(clock=clock, ...)
There is a similar approach in log4j to specify a custom clock [0].
This change enables the use of non-UTC clocks, e.g. `CLOCK_TAI` or
`CLOCK_MONOTONIC`, which are unaffected by leap seconds and count SI
seconds. (In fact, logging's use of differences of UTC timestamps could
make users believe that the obtained duration reflects SI seconds, which
it doesn't in all cases.)
Combining a custom absolute clock such as `CLOCK_TAI` with custom log
formatters allows users to /store or transfer/ log records with TAI
timestamps, and /display/ them with UTC timestamps (e.g. properly
converted from TAI to UTC with a "60" second during active leap second).
This resolves the ambiguity when analysing and correlating logs from
different machines also during leap seconds.
Attached is a simple example showing the different timestamps based on
UTC and TAI (assuming the current offset of +37 seconds [1] is properly
configured on the host, e.g. through PTP or `adjtimex()` with `ADJ_TAI`).
$ export TZ=GMT
$ date --iso-8601=seconds && python3 example.py
2020-09-02T14:34:14+00:00
2020-09-02T14:34:51+0000 INFO message
According to the documentation `time.CLOCK_TAI` was introduced in Python
3.9 [2], but already today the system constant can be used (e.g. on
Debian Buster, Linux 4.19.0, Python 3.7.3 it is 11).
The two patches provided are for Python 3.7.3 (Debian Buster) and Python
3.8.5 (python.org). In the latter case, it may need to be considered how
changing the Python logging clock works: it probably should fail if
handlers are already configured, unless `force` is also provided and
handlers are reset.
Kind regards,
-- nicolas benes
[0] `log4j.Clock` in
https://logging.apache.org/log4j/log4j-2.8/manual/configuration.html
[1] https://www.timeanddate.com/worldclock/other/tai
[2] https://docs.python.org/dev/library/time.html#time.CLOCK_TAI
--------------------------------------------------------------
Nicolas Benes nbe...@eso.org
+ Software Engineer
+E S+ European Southern Observatory https://www.eso.org
O Karl-Schwarzschild-Strasse 2
+ D-85748 Garching b. Muenchen
Germany
--------------------------------------------------------------
>From e19413a025d7807f68fc83f17cbb5da147d869f5 Mon Sep 17 00:00:00 2001
From: Nicolas Benes <nbe...@eso.org>
Date: Tue, 1 Sep 2020 18:33:38 +0200
Subject: [PATCH] Logging with custom clock
---
Lib/logging/__init__.py | 20 ++++++++++++++++----
1 file changed, 16 insertions(+), 4 deletions(-)
diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py
index 2761509..54ccf9e 100644
--- a/Lib/logging/__init__.py
+++ b/Lib/logging/__init__.py
@@ -49,10 +49,15 @@ __date__ = "07 February 2010"
# Miscellaneous module data
#---------------------------------------------------------------------------
+#
+#_clock_gettime is a callable to get the current time in seconds
+#
+_clock_gettime = time.time
+
#
#_startTime is used as the base when calculating the relative time of events
#
-_startTime = time.time()
+_startTime = _clock_gettime()
#
#raiseExceptions is used to see if exceptions during handling should be
@@ -295,7 +300,7 @@ class LogRecord(object):
"""
Initialize a logging record with interesting information.
"""
- ct = time.time()
+ ct = _clock_gettime()
self.name = name
self.msg = msg
#
@@ -494,8 +499,8 @@ class Formatter(object):
%(lineno)d Source line number where the logging call was issued
(if available)
%(funcName)s Function name
- %(created)f Time when the LogRecord was created (time.time()
- return value)
+ %(created)f Time when the LogRecord was created (by default
+ time.time() return value)
%(asctime)s Textual time when the LogRecord was created
%(msecs)d Millisecond portion of the creation time
%(relativeCreated)d Time in milliseconds when the LogRecord was created,
@@ -1862,6 +1867,8 @@ def basicConfig(**kwargs):
handlers, which will be added to the root handler. Any handler
in the list which does not have a formatter assigned will be
assigned the formatter created in this function.
+ clock If specified, this should be a callable that returns the current
+ time since an epoch in seconds.
Note that you could specify a stream created using open(filename, mode)
rather than passing the filename and mode in. However, it should be
@@ -1884,6 +1891,11 @@ def basicConfig(**kwargs):
_acquireLock()
try:
if len(root.handlers) == 0:
+ clock = kwargs.pop("clock", None)
+ if clock is not None:
+ global _clock_gettime, _startTime
+ _clock_gettime = clock
+ _startTime = _clock_gettime()
handlers = kwargs.pop("handlers", None)
if handlers is None:
if "stream" in kwargs and "filename" in kwargs:
--
2.20.1
>From 09d1585704a75f54f0b60a560b1b87514739b1bd Mon Sep 17 00:00:00 2001
From: Nicolas Benes <nbe...@eso.org>
Date: Wed, 2 Sep 2020 15:51:48 +0200
Subject: [PATCH] Logging with custom clock
---
Lib/logging/__init__.py | 20 ++++++++++++++++----
1 file changed, 16 insertions(+), 4 deletions(-)
diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py
index 0cfaec8..b5b4195 100644
--- a/Lib/logging/__init__.py
+++ b/Lib/logging/__init__.py
@@ -51,10 +51,15 @@ __date__ = "07 February 2010"
# Miscellaneous module data
#---------------------------------------------------------------------------
+#
+#_clock_gettime is a callable to get the current time in seconds
+#
+_clock_gettime = time.time
+
#
#_startTime is used as the base when calculating the relative time of events
#
-_startTime = time.time()
+_startTime = _clock_gettime()
#
#raiseExceptions is used to see if exceptions during handling should be
@@ -286,7 +291,7 @@ class LogRecord(object):
"""
Initialize a logging record with interesting information.
"""
- ct = time.time()
+ ct = _clock_gettime()
self.name = name
self.msg = msg
#
@@ -536,8 +541,8 @@ class Formatter(object):
%(lineno)d Source line number where the logging call was issued
(if available)
%(funcName)s Function name
- %(created)f Time when the LogRecord was created (time.time()
- return value)
+ %(created)f Time when the LogRecord was created (by default
+ time.time() return value)
%(asctime)s Textual time when the LogRecord was created
%(msecs)d Millisecond portion of the creation time
%(relativeCreated)d Time in milliseconds when the LogRecord was created,
@@ -1931,6 +1936,8 @@ def basicConfig(**kwargs):
attached to the root logger are removed and closed, before
carrying out the configuration as specified by the other
arguments.
+ clock If specified, this should be a callable that returns the current
+ time since an epoch in seconds.
Note that you could specify a stream created using open(filename, mode)
rather than passing the filename and mode in. However, it should be
remembered that StreamHandler does not close its stream (since it may be
@@ -1960,6 +1967,11 @@ def basicConfig(**kwargs):
root.removeHandler(h)
h.close()
if len(root.handlers) == 0:
+ clock = kwargs.pop("clock", None)
+ if clock is not None:
+ global _clock_gettime, _startTime
+ _clock_gettime = clock
+ _startTime = _clock_gettime()
handlers = kwargs.pop("handlers", None)
if handlers is None:
if "stream" in kwargs and "filename" in kwargs:
--
2.20.1
import logging
import time
def main():
# Python 3.7 does not yet provide time.CLOCK_TAI
#clock = lambda: time.clock_gettime(11)
clock = lambda: time.clock_gettime(time.CLOCK_TAI)
logging.basicConfig(format="%(asctime)s %(levelname)s %(message)s",
datefmt="%Y-%m-%dT%H:%M:%S%z",
level=logging.DEBUG, clock=clock)
logging.info("message")
if __name__ == "__main__":
main()
_______________________________________________
Python-Dev mailing list -- python-dev@python.org
To unsubscribe send an email to python-dev-le...@python.org
https://mail.python.org/mailman3/lists/python-dev.python.org/
Message archived at
https://mail.python.org/archives/list/python-dev@python.org/message/6SFHYMKFQX2ZX5GSGVXYLWA43LLFTWRO/
Code of Conduct: http://python.org/psf/codeofconduct/
