Merge pull request #3570 from vkarak/enhancement/log-format-usecs

[feat] Support usecs (`%f` format) in `datefmt` for logging

Author: vkarak

docs/config_reference.rst

@@ -1338,6 +1338,8 @@ All logging handlers share the following set of common attributes:
 
 .. py:attribute:: logging.handlers.datefmt
 
+   :default: ``"%FT%T.%f"``
+
 .. object:: logging.handlers_perflog.datefmt
 
    :required: No
@@ -1347,6 +1349,13 @@ All logging handlers share the following set of common attributes:
    There are two timestamp fields available: ``%(asctime)s`` and ``%(check_job_completion_time)s``.
    In addition to the format directives supported by the standard library's `time.strftime() <https://docs.python.org/3.8/library/time.html#time.strftime>`__ function, ReFrame allows you to use the ``%:z`` directive -- a GNU ``date`` extension --  that will print the time zone difference in a RFC3339 compliant way, i.e., ``+/-HH:MM`` instead of ``+/-HHMM``.
 
+.. note::
+
+   The default format for non-perflog log handlers includes now the microseconds.
+   Note also that the ``%f`` format string is not supported in ``datefmt`` for versions < 4.9.
+
+   .. versionchanged:: 4.9
+
 
 .. _file-handler:
 

reframe/core/logging.py

@@ -17,6 +17,7 @@
 import sys
 import time
 import urllib
+from datetime import datetime
 
 import reframe.utility.color as color
 import reframe.utility.jsonext as jsonext
@@ -301,11 +302,18 @@ def close(self):
 
 
 def _format_time_rfc3339(timestamp, datefmt):
-    tz_suffix = time.strftime('%z', timestamp)
-    tz_rfc3339 = tz_suffix[:-2] + ':' + tz_suffix[-2:]
+    if timestamp is None:
+        timestamp = time.time()
 
-    # Python < 3.7 truncates the `%`, whereas later versions don't
-    return re.sub(r'(%)?\:z', tz_rfc3339, time.strftime(datefmt, timestamp))
+    date = datetime.fromtimestamp(timestamp).astimezone()
+    if r'%:z' in datefmt:
+        tz_suffix = date.strftime(r'%z')
+        tz_rfc3339 = tz_suffix[:-2] + ':' + tz_suffix[-2:]
+
+        # Python < 3.7 truncates the `%`, whereas later versions don't
+        return re.sub(r'(%)?\:z', tz_rfc3339, date.strftime(datefmt))
+
+    return date.strftime(datefmt)
 
 
 def _xfmt(val):
@@ -399,7 +407,7 @@ def formatMessage(self, record):
         ct = record.check_job_completion_time_unix
         if ct is not None:
             record_proxy['check_job_completion_time'] = _format_time_rfc3339(
-                time.localtime(ct), datefmt
+                ct, datefmt
             )
 
         try:
@@ -412,11 +420,7 @@ def formatMessage(self, record):
 class RFC3339Formatter(CheckFieldFormatter):
     def formatTime(self, record, datefmt=None):
         datefmt = datefmt or self.default_time_format
-        if '%:z' not in datefmt:
-            return super().formatTime(record, datefmt)
-        else:
-            timestamp = self.converter(record.created)
-            return _format_time_rfc3339(timestamp, datefmt)
+        return _format_time_rfc3339(record.created, datefmt)
 
 
 def _create_logger(site_config, *handlers_groups):
@@ -926,8 +930,7 @@ def _update_check_extras(self):
         # Add special extras
         self.extra['check_info'] = self.check.info()
         self.extra['check_job_completion_time'] = _format_time_rfc3339(
-            time.localtime(self.extra['check_job_completion_time_unix']),
-            '%FT%T%:z'
+            self.extra['check_job_completion_time_unix'], r'%FT%T%:z'
         )
 
     def log_performance(self, level, task, msg=None, multiline=False):

reframe/frontend/reporting/__init__.py

@@ -395,7 +395,7 @@ def update_run_stats(self, stats):
 
                 if entry['job_completion_time_unix']:
                     entry['job_completion_time'] = _format_time_rfc3339(
-                        time.localtime(entry['job_completion_time_unix']),
+                        entry['job_completion_time_unix'],
                         '%FT%T%:z'
                     )
 

reframe/schemas/config.json

@@ -627,13 +627,14 @@
         "logging/handlers*/*_level": "info",
         "logging/handlers*/*_format": "%(message)s",
         "logging/handlers*/*_format_perfvars": "",
-        "logging/handlers*/*_datefmt": "%FT%T",
         "logging/handlers*/file_append": false,
         "logging/handlers*/file_name": "",
         "logging/handlers*/file_timestamp": false,
         "logging/handlers*/stream_name": "stdout",
         "logging/handlers*/syslog_socktype": "udp",
         "logging/handlers*/syslog_facility": "user",
+        "logging/handlers/*_datefmt": "%FT%T.%f",
+        "logging/handlers_perflog/datefmt": "%FT%T",
         "logging/handlers_perflog/filelog_append": true,
         "logging/handlers_perflog/filelog_basedir": "./perflogs",
         "logging/handlers_perflog/filelog_ignore_keys": [],