Merge pull request #1150 from vkarak/feat/log-format-rfc3339

[feat] Support RFC3339 compliant time zone formatting when logging time fields

Author: Vasileios Karakasis

docs/running.rst

@@ -849,7 +849,7 @@ All handlers accept the following set of attributes (keys) in their configuratio
 
 * ``level``: (default: ``DEBUG``) The lowest level of log records that this handler can process.
 * ``format`` (default: ``'%(message)s'``): Format string for the printout of the log record.
-  ReFrame supports all the `format strings <https://docs.python.org/3.6/library/logging.html#logrecord-attributes>`__ from Python's logging library and provides the following additional ones:
+  ReFrame supports all the `log record attributes <https://docs.python.org/3.6/library/logging.html#logrecord-attributes>`__ from Python's logging library and provides the following additional ones:
 
   - ``check_environ``: The programming environment a test is currently executing for.
   - ``check_info``: Print live information of the currently executing check.
@@ -877,15 +877,20 @@ All handlers accept the following set of attributes (keys) in their configuratio
   - ``osgroup``: The group name of the OS user running ReFrame.
   - ``version``: The ReFrame version.
 
-* ``datefmt`` (default: ``'%FT%T'``) The format that will be used for outputting timestamps (i.e., the ``%(asctime)s`` field).
-  Acceptable formats must conform to standard library's `time.strftime() <https://docs.python.org/3.6/library/time.html#time.strftime>`__ function.
+* ``datefmt`` (default: ``'%FT%T'``) The format that will be used for outputting timestamps (i.e., the ``%(asctime)s`` and the ``%(check_job_completion_time)s`` fields).
+  In addition to the format directives supported by the standard library's `time.strftime() <https://docs.python.org/3.6/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``.
 
 .. caution::
    The ``testcase_name`` logging attribute is replaced with the ``check_info``, which is now also configurable
 
    .. versionchanged:: 2.10
 
 
+.. note::
+   Support for fully RFC3339 compliant time zone formatting.
+
+   .. versionadded:: 3.0
+
 
 File log handlers
 """""""""""""""""

reframe/core/logging.py

@@ -5,10 +5,11 @@
 import numbers
 import os
 import pprint
+import re
 import shutil
 import sys
 import socket
-from datetime import datetime
+import time
 
 import reframe
 import reframe.utility.color as color
@@ -132,6 +133,34 @@ def close(self):
             super().close()
 
 
+def _format_time_rfc3339(timestamp, datefmt):
+    tz_suffix = time.strftime('%z', timestamp)
+    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, time.strftime(datefmt, timestamp))
+
+
+class RFC3339Formatter(logging.Formatter):
+    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)
+
+    def format(self, record):
+        datefmt = self.datefmt or self.default_time_format
+        if record.check_job_completion_time is not None:
+            ct = self.converter(record.check_job_completion_time)
+            record.check_job_completion_time = _format_time_rfc3339(
+                ct, datefmt
+            )
+
+        return super().format(record)
+
+
 def load_from_dict(logging_config):
     if not isinstance(logging_config, collections.abc.Mapping):
         raise TypeError('logging configuration is not a dict')
@@ -177,8 +206,7 @@ def _create_file_handler(handler_config):
     timestamp = handler_config.get('timestamp', None)
     if timestamp:
         basename, ext = os.path.splitext(filename)
-        filename = '%s_%s%s' % (basename,
-                                datetime.now().strftime(timestamp), ext)
+        filename = '%s_%s%s' % (basename, time.strftime(timestamp), ext)
 
     append = handler_config.get('append', False)
     return logging.handlers.RotatingFileHandler(filename,
@@ -305,7 +333,7 @@ def _extract_handlers(handlers_list):
         level = handler_config.get('level', 'debug').lower()
         fmt = handler_config.get('format', '%(message)s')
         datefmt = handler_config.get('datefmt', '%FT%T')
-        hdlr.setFormatter(logging.Formatter(fmt=fmt, datefmt=datefmt))
+        hdlr.setFormatter(RFC3339Formatter(fmt=fmt, datefmt=datefmt))
         hdlr.setLevel(_check_level(level))
         handlers.append(hdlr)
 
@@ -428,11 +456,7 @@ def _update_check_extras(self):
         if self.check.job:
             self.extra['check_jobid'] = self.check.job.jobid
             if self.check.job.completion_time:
-                # Use the logging handlers' date format to format
-                # completion_time
-                # NOTE: All handlers use the same date format
-                fmt = self.logger.handlers[0].formatter.datefmt
-                ct = self.check.job.completion_time.strftime(fmt)
+                ct = self.check.job.completion_time
                 self.extra['check_job_completion_time'] = ct
 
     def log_performance(self, level, tag, value, ref,

reframe/core/schedulers/__init__.py

@@ -3,7 +3,7 @@
 #
 
 import abc
-from datetime import datetime
+import time
 
 import reframe.core.environments as env
 import reframe.core.fields as fields
@@ -17,6 +17,8 @@
 class JobScheduler(abc.ABC):
     @abc.abstractmethod
     def completion_time(self, job):
+        '''The completion time of this job expressed in seconds from the Epoch.
+        '''
         pass
 
     @abc.abstractmethod
@@ -332,7 +334,7 @@ def wait(self):
             raise JobNotStartedError('cannot wait an unstarted job')
 
         self.scheduler.wait(self)
-        self._completion_time = self._completion_time or datetime.now()
+        self._completion_time = self._completion_time or time.time()
 
     def cancel(self):
         if self.jobid is None:
@@ -346,7 +348,7 @@ def finished(self):
 
         done = self.scheduler.finished(self)
         if done:
-            self._completion_time = self._completion_time or datetime.now()
+            self._completion_time = self._completion_time or time.time()
 
         return done
 

reframe/core/schedulers/slurm.py

@@ -103,7 +103,7 @@ def completion_time(self, job):
             not slurm_state_completed(job.state)):
             return self._completion_time
 
-        with env.temp_environment(variables={'SLURM_TIME_FORMAT': 'standard'}):
+        with env.temp_environment(variables={'SLURM_TIME_FORMAT': '%s'}):
             completed = os_ext.run_command(
                 'sacct -S %s -P -j %s -o jobid,end' %
                 (datetime.now().strftime('%F'), job.jobid),
@@ -116,11 +116,7 @@ def completion_time(self, job):
         if not state_match:
             return None
 
-        self._completion_time = max(
-            datetime.strptime(s.group('end'), '%Y-%m-%dT%H:%M:%S')
-            for s in state_match
-        )
-
+        self._completion_time = max(float(s.group('end')) for s in state_match)
         return self._completion_time
 
     def _format_option(self, var, option):

unittests/test_logging.py

@@ -2,27 +2,42 @@
 import logging.handlers
 import os
 import sys
+import re
 import tempfile
+import time
 import unittest
 from datetime import datetime
 
 import reframe as rfm
 import reframe.core.logging as rlog
 from reframe.core.exceptions import ConfigError, ReframeError
+from reframe.core.launchers.registry import getlauncher
+from reframe.core.schedulers import Job
+from reframe.core.schedulers.registry import getscheduler
 
 
-class RandomCheck(rfm.RegressionTest):
+class _FakeCheck(rfm.RegressionTest):
     pass
 
 
+def _setup_fake_check():
+    # A bit hacky, but we don't want to run a full test every time
+    test = _FakeCheck()
+    test._job = Job.create(getscheduler('local')(),
+                           getlauncher('local')(),
+                           'fakejob')
+    test.job._completion_time = time.time()
+    return test
+
+
 class TestLogger(unittest.TestCase):
     def setUp(self):
         tmpfd, self.logfile = tempfile.mkstemp()
         os.close(tmpfd)
 
         self.logger  = rlog.Logger('reframe')
         self.handler = logging.handlers.RotatingFileHandler(self.logfile)
-        self.formatter = logging.Formatter(
+        self.formatter = rlog.RFC3339Formatter(
             fmt='[%(asctime)s] %(levelname)s: %(check_name)s: %(message)s',
             datefmt='%FT%T')
 
@@ -33,15 +48,16 @@ def setUp(self):
         self.logger_without_check = rlog.LoggerAdapter(self.logger)
 
         # Logger adapter with an associated check
-        self.logger_with_check = rlog.LoggerAdapter(self.logger, RandomCheck())
+        self.logger_with_check = rlog.LoggerAdapter(self.logger,
+                                                    _setup_fake_check())
 
     def tearDown(self):
         os.remove(self.logfile)
 
-    def found_in_logfile(self, string):
+    def found_in_logfile(self, pattern):
         found = False
-        with open(self.logfile, 'rt') as f:
-            found = string in f.read()
+        with open(self.logfile, 'rt') as fp:
+            found = re.search(pattern, fp.read()) is not None
 
         return found
 
@@ -65,7 +81,7 @@ def test_check_logger(self):
         self.assertTrue(os.path.exists(self.logfile))
         self.assertTrue(self.found_in_logfile('info'))
         self.assertTrue(self.found_in_logfile('verbose'))
-        self.assertTrue(self.found_in_logfile('RandomCheck'))
+        self.assertTrue(self.found_in_logfile('_FakeCheck'))
 
     def test_handler_types(self):
         self.assertTrue(issubclass(logging.Handler, rlog.Handler))
@@ -97,6 +113,26 @@ def test_logger_levels(self):
         self.assertFalse(self.found_in_logfile('bar'))
         self.assertTrue(self.found_in_logfile('foo'))
 
+    def test_rfc3339_timezone_extension(self):
+        self.formatter = rlog.RFC3339Formatter(
+            fmt=('[%(asctime)s] %(levelname)s: %(check_name)s: '
+                 'ct:%(check_job_completion_time)s: %(message)s'),
+            datefmt='%FT%T%:z')
+        self.handler.setFormatter(self.formatter)
+        self.logger_with_check.info('foo')
+        self.logger_without_check.info('foo')
+        assert not self.found_in_logfile(r'%%:z')
+        assert self.found_in_logfile(r'\[.+(\+|-)\d\d:\d\d\]')
+        assert self.found_in_logfile(r'ct:.+(\+|-)\d\d:\d\d')
+
+    def test_rfc3339_timezone_wrong_directive(self):
+        self.formatter = rlog.RFC3339Formatter(
+            fmt='[%(asctime)s] %(levelname)s: %(check_name)s: %(message)s',
+            datefmt='%FT%T:z')
+        self.handler.setFormatter(self.formatter)
+        self.logger_without_check.info('foo')
+        assert self.found_in_logfile(':z')
+
 
 class TestLoggingConfiguration(unittest.TestCase):
     def setUp(self):
@@ -116,7 +152,7 @@ def setUp(self):
                 }
             ]
         }
-        self.check = RandomCheck()
+        self.check = _FakeCheck()
 
     def tearDown(self):
         if os.path.exists(self.logfile):
@@ -403,7 +439,7 @@ def test_logging_context_check(self):
 
         rlog.getlogger().error('error outside context')
         self.assertTrue(self.found_in_logfile(
-            'RandomCheck: %s: error from context' % sys.argv[0]))
+            '_FakeCheck: %s: error from context' % sys.argv[0]))
         self.assertTrue(self.found_in_logfile(
             'reframe: %s: error outside context' % sys.argv[0]))