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 """"""""""""""""" diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 909bbd742b..6208809cfa 100644 --- a/reframe/core/logging.py +++ b/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, 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..4f11617c1c 100644 --- a/unittests/test_logging.py +++ b/unittests/test_logging.py @@ -2,19 +2,34 @@ 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() @@ -22,7 +37,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') @@ -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]))