feat: ISO8601 logging date format

Author: aldbr

src/DIRAC/FrameworkSystem/private/standardLogging/Formatter/BaseFormatter.py

@@ -2,7 +2,7 @@
 BaseFormatter
 """
 import logging
-import sys
+import time
 
 
 class BaseFormatter(logging.Formatter):
@@ -23,6 +23,9 @@ def __init__(self, fmt=None, datefmt=None):
         :param str fmt: log format: "%(asctime)s UTC %(name)s %(levelname)s: %(message)"
         :param str datefmt: date format: "%Y-%m-%d %H:%M:%S"
         """
+        # Initialization of the UTC time
+        # Actually, time.gmtime is equal to UTC time: it has its DST flag to 0 which means there is no clock advance
+        self.converter = time.gmtime
         super().__init__()
 
     def format(self, record):
@@ -43,7 +46,7 @@ def format(self, record):
 
         if record.headerIsShown:
             if record.timeStampIsShown:
-                timeStamp = "%(asctime)s UTC "
+                timeStamp = "%(asctime)s "
             if record.contextIsShown:
                 contextComponentList = ["%(componentname)s%(customname)s"]
 
@@ -63,5 +66,14 @@ def format(self, record):
         fmt += "%(message)s%(spacer)s%(varmessage)s"
 
         self._style._fmt = fmt  # pylint: disable=no-member
-        self.datefmt = "%Y-%m-%d %H:%M:%S"
         return super().format(record)
+
+    def formatTime(self, record, datefmt=None):
+        """:py:meth:`logging.Formatter.formatTime` with microsecond precision by default"""
+        ct = self.converter(record.created)
+        if datefmt:
+            s = time.strftime(datefmt, ct)
+        else:
+            t = time.strftime("%Y-%m-%dT%H:%M:%S", ct)
+            s = "%s,%06dZ" % (t, (record.created - int(record.created)) * 1e6)
+        return s

src/DIRAC/FrameworkSystem/private/standardLogging/Formatter/MicrosecondJsonFormatter.py

@@ -10,6 +10,10 @@ def __init__(self, *args, **kwargs):
         Add to the list of attributes we don't want to see
         all the DIRAC spefic log formating instructions
         """
+        # Initialization of the UTC time
+        # Actually, time.gmtime is equal to UTC time: it has its DST flag to 0 which means there is no clock advance
+        self.converter = time.gmtime
+
         if "reserved_attrs" not in kwargs:
             kwargs["reserved_attrs"] = RESERVED_ATTRS + (
                 "spacer",
@@ -27,6 +31,6 @@ def formatTime(self, record, datefmt=None):
         if datefmt:
             s = time.strftime(datefmt, ct)
         else:
-            t = time.strftime("%Y-%m-%d %H:%M:%S", ct)
-            s = "%s,%06d" % (t, (record.created - int(record.created)) * 1e6)
+            t = time.strftime("%Y-%m-%dT%H:%M:%S", ct)
+            s = "%s,%06dZ" % (t, (record.created - int(record.created)) * 1e6)
         return s

src/DIRAC/FrameworkSystem/private/standardLogging/LoggingRoot.py

@@ -55,10 +55,6 @@ def __init__(self):
         # root Logger level is set to INFO by default
         self._logger.setLevel(LogLevels.INFO)
 
-        # initialization of the UTC time
-        # Actually, time.gmtime is equal to UTC time: it has its DST flag to 0 which means there is no clock advance
-        logging.Formatter.converter = time.gmtime
-
         # initialization of the default backend
         # use the StdoutBackend directly to avoid dependancy loop with ObjectLoader
         self._addBackend(StdoutBackend)
@@ -295,8 +291,9 @@ def __enableLogsFromExternalLibs(isEnabled=True):
         if isEnabled:
             logging.basicConfig(
                 level=logging.DEBUG,
-                format="%(asctime)s UTC ExternalLibrary/%(name)s %(levelname)s: %(message)s",
-                datefmt="%Y-%m-%d %H:%M:%S",
+                format="%(asctime)s,%(msecs)03dZ ExternalLibrary/%(name)s %(levelname)s: %(message)s",
+                datefmt="%Y-%m-%dT%H:%M:%S",
             )
+            rootLogger.handlers[0].formatter.converter = time.gmtime
         else:
             rootLogger.addHandler(logging.NullHandler())

src/DIRAC/FrameworkSystem/private/standardLogging/test/TestLogUtilities.py

@@ -15,7 +15,7 @@ def cleaningLog(log):
     """
     Remove date and space from the log string
     """
-    log = log.split("UTC ")[-1]
+    log = log.split("Z ", 1)[-1]
     return log
 
 

src/DIRAC/FrameworkSystem/private/standardLogging/test/Test_Logging_FormatOptions.py

@@ -135,21 +135,21 @@ def test_showFormatOptionsgLogger(
     gLogger.notice(msg)
     logValue = capturedBackend.getvalue()
     # check that timestamp is available if it has to be available
-    assert ("UTC" in logValue) == isTimeStampAvailable
+    assert ("Z " in logValue) == isTimeStampAvailable
     logstring = cleaningLog(logValue)
     capturedBackend.truncate(0)
     capturedBackend.seek(0)
 
     log.notice(msg)
     logValue = capturedBackend.getvalue()
-    assert ("UTC" in logValue) == isTimeStampAvailable
+    assert ("Z " in logValue) == isTimeStampAvailable
     logstring += cleaningLog(logValue)
     capturedBackend.truncate(0)
     capturedBackend.seek(0)
 
     sublog.notice(msg)
     logValue = capturedBackend.getvalue()
-    assert ("UTC" in logValue) == isTimeStampAvailable
+    assert ("Z " in logValue) == isTimeStampAvailable
     logstring += cleaningLog(logValue)
     capturedBackend.truncate(0)
     capturedBackend.seek(0)

src/DIRAC/FrameworkSystem/private/standardLogging/test/Test_Logging_GetSubLogger.py

@@ -6,7 +6,7 @@
 from DIRAC.FrameworkSystem.private.standardLogging.LogLevels import LogLevels
 
 
-from DIRAC.FrameworkSystem.private.standardLogging.test.TestLogUtilities import gLogger, gLoggerReset
+from DIRAC.FrameworkSystem.private.standardLogging.test.TestLogUtilities import gLogger, gLoggerReset, cleaningLog
 
 
 def test_getSubLoggerLogRecord():
@@ -49,10 +49,6 @@ def test_getSubLoggerObject():
     assert log == anotherLog
 
 
-# Run the tests for all the log levels and exceptions
-# We may need to rerun the test if we are unlucky and the timestamps
-# don't match
-@flaky(max_runs=3)
 @pytest.mark.parametrize("logLevel", ["exception"] + [lvl.lower() for lvl in LogLevels.getLevelNames()])
 def test_localSubLoggerObject(logLevel):
     """
@@ -66,7 +62,7 @@ def test_localSubLoggerObject(logLevel):
     # Create a real subLogger and a localSubLogger
     # with the same "name"
     subLog = log.getSubLogger("child")
-    localSubLog = log.getSubLogger("child")
+    localSubLog = log.getLocalSubLogger("child")
 
     # Print and capture a message with the real sublogger
     capturedBackend.truncate(0)
@@ -81,4 +77,4 @@ def test_localSubLoggerObject(logLevel):
     locMsg = capturedBackend.getvalue()
 
     # Compare the output
-    assert subMsg == locMsg
+    assert cleaningLog(subMsg) == cleaningLog(locMsg)