Add full RFC3339 compliance to time format

Author: Vasileios Karakasis

reframe/core/logging.py

@@ -8,6 +8,7 @@
 import shutil
 import sys
 import socket
+import time
 from datetime import datetime
 
 import reframe
@@ -132,6 +133,37 @@ 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:]
+    return time.strftime(datefmt, timestamp).replace(':z', tz_rfc3339)
+
+
+class RFC3339Formatter(logging.Formatter):
+    def __init__(self, fmt=None, datefmt=None, style='%'):
+        super().__init__(fmt, datefmt, style)
+
+        # Formatter objects store fmt in `_fmt`, but we use our own variable
+        # here just to stay on the safe side if Formatter's implementation
+        # changes
+        self.__fmt = fmt
+
+    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 usesTime(self):
+        # Extend usesTime() so as to trigger time formatting for our own
+        # custom time formats
+        return (super().usesTime() or
+                '%(check_job_completion_time)' in self.__fmt or
+                '{check_job_completion_time}' in self.__fmt)
+
+
 def load_from_dict(logging_config):
     if not isinstance(logging_config, collections.abc.Mapping):
         raise TypeError('logging configuration is not a dict')
@@ -305,7 +337,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 +460,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,6 +2,7 @@
 import logging.handlers
 import os
 import sys
+import re
 import tempfile
 import unittest
 from datetime import datetime
@@ -22,7 +23,7 @@ def setUp(self):
 
         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')
 
@@ -38,10 +39,10 @@ def setUp(self):
     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
 
@@ -97,6 +98,23 @@ 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: %(message)s',
+            datefmt='%FT%T%:z')
+        self.handler.setFormatter(self.formatter)
+        self.logger_without_check.info('foo')
+        assert not self.found_in_logfile(r'%%:z')
+        assert self.found_in_logfile(r'(\+|-)\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):