Merge branch 'master' into bugfix/dom_static_linkage

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):

requirements.txt

@@ -1,3 +1,4 @@
+jsonschema
 pytest>=3.5.0
 coverage
 setuptools