From bf3bbefb718c9ee292b49556abb0eba7370c5a5f Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Mon, 3 Feb 2020 16:13:14 +0200 Subject: [PATCH 1/5] Add full RFC3339 compliance to time format --- reframe/core/logging.py | 40 ++++++++++++++++++++++++----- reframe/core/schedulers/__init__.py | 8 +++--- reframe/core/schedulers/slurm.py | 8 ++---- unittests/test_logging.py | 26 ++++++++++++++++--- 4 files changed, 63 insertions(+), 19 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 909bbd742b..86075ce8ea 100644 --- a/reframe/core/logging.py +++ b/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, diff --git a/reframe/core/schedulers/__init__.py b/reframe/core/schedulers/__init__.py index 943e088deb..2e418f6e46 100644 --- a/reframe/core/schedulers/__init__.py +++ b/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 diff --git a/reframe/core/schedulers/slurm.py b/reframe/core/schedulers/slurm.py index 769048c393..183e713b2f 100644 --- a/reframe/core/schedulers/slurm.py +++ b/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): diff --git a/unittests/test_logging.py b/unittests/test_logging.py index 71cc97c674..78478ccec3 100644 --- a/unittests/test_logging.py +++ b/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): From 688155ba6623e613efcd23200722ca778382e01f Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 4 Feb 2020 00:17:47 +0100 Subject: [PATCH 2/5] Add full RFC3339 compliance to time format (fixes) --- reframe/core/logging.py | 28 +++++++++++++--------------- 1 file changed, 13 insertions(+), 15 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 86075ce8ea..6e8a790b21 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -136,18 +136,10 @@ 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) + 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: @@ -156,12 +148,18 @@ def formatTime(self, record, datefmt=None): 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 format(self, record): + datefmt = self.datefmt or self.default_time_format + try: + 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 + ) + except AttributeError: + pass + + return super().format(record) def load_from_dict(logging_config): From f8c3413f5081cf49552934a7f37137bb2cdd90b4 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 4 Feb 2020 13:10:47 +0100 Subject: [PATCH 3/5] 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 --- reframe/core/logging.py | 9 +++++---- unittests/test_logging.py | 32 +++++++++++++++++++++++++------- 2 files changed, 30 insertions(+), 11 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 6e8a790b21..84bcc63de0 100644 --- a/reframe/core/logging.py +++ b/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, diff --git a/unittests/test_logging.py b/unittests/test_logging.py index 78478ccec3..4f11617c1c 100644 --- a/unittests/test_logging.py +++ b/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])) From 1e6be589e670ba0cc5d3d227f740d761efe41de0 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 4 Feb 2020 14:35:29 +0200 Subject: [PATCH 4/5] Document support of the `%:z` time format directive --- docs/running.rst | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/docs/running.rst b/docs/running.rst index 7858bdc476..4ba8e2d452 100644 --- a/docs/running.rst +++ b/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 `__ from Python's logging library and provides the following additional ones: + ReFrame supports all the `log record 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,8 +877,8 @@ 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() `__ 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() `__ 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 @@ -886,6 +886,11 @@ All handlers accept the following set of attributes (keys) in their configuratio .. versionchanged:: 2.10 +.. note:: + Support for fully RFC3339 compliant time zone formatting. + + .. versionadded:: 3.0 + File log handlers """"""""""""""""" From cdf381c9642327d395cd2aeb087ff55095e64a64 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Wed, 5 Feb 2020 12:24:35 +0200 Subject: [PATCH 5/5] Remove unnecessary try/except block --- reframe/core/logging.py | 13 +++++-------- 1 file changed, 5 insertions(+), 8 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 84bcc63de0..6208809cfa 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -152,14 +152,11 @@ def formatTime(self, record, datefmt=None): def format(self, record): datefmt = self.datefmt or self.default_time_format - try: - 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 - ) - except AttributeError: - pass + 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)