Work around Python 3.6/3.7 inconsistency in treating unknown format directives

- Add unit tests for testing the formatting of `check_job_completion_time`.
- Minor refactoring in logging unit tests

Author: Vasileios Karakasis

reframe/core/logging.py

@@ -5,11 +5,11 @@
 import numbers
 import os
 import pprint
+import re
 import shutil
 import sys
 import socket
 import time
-from datetime import datetime
 
 import reframe
 import reframe.utility.color as color
@@ -136,7 +136,9 @@ def close(self):
 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)
+
+    # 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):
@@ -207,8 +209,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,

unittests/test_logging.py

@@ -4,18 +4,32 @@
 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()
@@ -34,7 +48,8 @@ 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)
@@ -66,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))
@@ -100,12 +115,15 @@ def test_logger_levels(self):
 
     def test_rfc3339_timezone_extension(self):
         self.formatter = rlog.RFC3339Formatter(
-            fmt='[%(asctime)s] %(levelname)s: %(check_name)s: %(message)s',
+            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'\[.+(\+|-)\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(
@@ -134,7 +152,7 @@ def setUp(self):
                 }
             ]
         }
-        self.check = RandomCheck()
+        self.check = _FakeCheck()
 
     def tearDown(self):
         if os.path.exists(self.logfile):
@@ -421,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]))