From 586f4da95f364f10e45698534709e18347a8cb56 Mon Sep 17 00:00:00 2001 From: Victor Holanda Date: Thu, 17 Jan 2019 10:32:51 +0100 Subject: [PATCH 1/7] Add option to increase output verbosity level This PR adds the option to increase the verbosity level of the PrettyPrinter. However, there is only one call to printer.debug and there is on call to printer.verbose in the entire code. The former is related to a module not being properly loaded, which is difficult to reproduce, since we do have correct checks on ReFrame. I am not sure if it is part of the issue to also add the printer.debug and printer.verbose calls into the code. --- reframe/frontend/cli.py | 6 +++++- reframe/frontend/printer.py | 8 ++++++++ 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/reframe/frontend/cli.py b/reframe/frontend/cli.py index 97a44c2037..c7e3731e18 100644 --- a/reframe/frontend/cli.py +++ b/reframe/frontend/cli.py @@ -86,6 +86,9 @@ def main(): '--save-log-files', action='store_true', default=False, help='Copy the log file from the work dir to the output dir at the ' 'end of the program') + output_options.add_argument( + '--verbose', '-v', action='count', + help='Increase output verbosity level') # Check discovery options locate_options.add_argument( @@ -258,6 +261,7 @@ def main(): # Setup printer printer = PrettyPrinter() printer.colorize = options.colorize + printer.set_verbose_level(options.verbose) try: runtime.init_runtime(settings.site_configuration, options.system) @@ -452,7 +456,7 @@ def main(): rt.modules_system.load_module(m, force=True) raise EnvironError("test") except EnvironError as e: - printer.warning("could not load module '%s' correctly: " + printer.warning("could not load module '%s' correctly: " "Skipping..." % m) printer.debug(str(e)) diff --git a/reframe/frontend/printer.py b/reframe/frontend/printer.py index 0c2bed3689..f6c12254cd 100644 --- a/reframe/frontend/printer.py +++ b/reframe/frontend/printer.py @@ -61,6 +61,14 @@ def __init__(self): def __repr__(self): return debug.repr(self) + def set_verbose_level(self, number): + if not number: + self._logger.setLevel(logging.INFO) + elif number == 1: + self._logger.setLevel(logging.VERBOSE) + elif number >= 2: + self._logger.setLevel(logging.DEBUG) + def separator(self, linestyle, msg=''): if linestyle == 'short double line': line = self.status_width * '=' From 8022555b1750064d26a1b3f5d41e5e1734b4a209 Mon Sep 17 00:00:00 2001 From: Victor Holanda Date: Fri, 18 Jan 2019 13:46:42 +0100 Subject: [PATCH 2/7] Improve loglevel output implementation --- reframe/core/logging.py | 43 ++++++++++++++++++++++++++++++------- reframe/frontend/cli.py | 2 +- reframe/frontend/printer.py | 11 +++++----- 3 files changed, 41 insertions(+), 15 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index dfd9c9867e..968ff93030 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -23,12 +23,12 @@ # Reframe's log levels -CRITICAL = 50 -ERROR = 40 -WARNING = 30 -INFO = 20 -VERBOSE = 19 -DEBUG = 10 +CRITICAL = 6 +ERROR = 5 +WARNING = 4 +INFO = 3 +VERBOSE = 2 +DEBUG = 1 NOTSET = 0 @@ -131,6 +131,20 @@ def close(self): super().close() +class StreamHandler(logging.StreamHandler): + def __init__(self, stream=None): + super().__init__(stream=stream) + self.__log_level = 'INFO' + self.setLevel('INFO') + + def setLevel(self, level): + super().setLevel(level) + self.__log_level = level + + def loglevel(self): + return self.__log_level + + def load_from_dict(logging_config): if not isinstance(logging_config, collections.abc.Mapping): raise TypeError('logging configuration is not a dict') @@ -199,9 +213,9 @@ def _create_filelog_handler(handler_config): def _create_stream_handler(handler_config): stream = handler_config.get('name', 'stdout') if stream == 'stdout': - return logging.StreamHandler(stream=sys.stdout) + return StreamHandler(stream=sys.stdout) elif stream == 'stderr': - return logging.StreamHandler(stream=sys.stderr) + return StreamHandler(stream=sys.stderr) else: raise ConfigError('unknown stream: %s' % stream) @@ -284,6 +298,7 @@ def __init__(self, name, level=logging.NOTSET): # class' check super().__init__(name, logging.NOTSET) self.level = _check_level(level) + self._stream_handlers = [] def __repr__(self): return debug.repr(self) @@ -291,6 +306,14 @@ def __repr__(self): def setLevel(self, level): self.level = _check_level(level) + def addHandler(self, hdlr): + if isinstance(hdlr, StreamHandler): + self._stream_handlers.append(hdlr) + super().addHandler(hdlr) + + def stream_handlers(self): + return self._stream_handlers + def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None, sinfo=None): record = super().makeRecord(name, level, fn, lno, msg, args, exc_info, @@ -360,6 +383,10 @@ def setLevel(self, level): if self.logger: super().setLevel(level) + def stream_handlers(self): + if self.logger: + return self.logger._stream_handlers + def _update_check_extras(self): """Return a dictionary with all the check-specific information.""" if self.check is None: diff --git a/reframe/frontend/cli.py b/reframe/frontend/cli.py index c7e3731e18..62ff06336a 100644 --- a/reframe/frontend/cli.py +++ b/reframe/frontend/cli.py @@ -87,7 +87,7 @@ def main(): help='Copy the log file from the work dir to the output dir at the ' 'end of the program') output_options.add_argument( - '--verbose', '-v', action='count', + '--verbose', '-v', action='count', default=0, help='Increase output verbosity level') # Check discovery options diff --git a/reframe/frontend/printer.py b/reframe/frontend/printer.py index f6c12254cd..2309c7bfe9 100644 --- a/reframe/frontend/printer.py +++ b/reframe/frontend/printer.py @@ -62,12 +62,11 @@ def __repr__(self): return debug.repr(self) def set_verbose_level(self, number): - if not number: - self._logger.setLevel(logging.INFO) - elif number == 1: - self._logger.setLevel(logging.VERBOSE) - elif number >= 2: - self._logger.setLevel(logging.DEBUG) + if number: + for hdlr in self._logger.stream_handlers(): + loglevel = hdlr.loglevel() + new_level = max(loglevel - number, logging.DEBUG) + hdlr.setLevel(new_level) def separator(self, linestyle, msg=''): if linestyle == 'short double line': From 81e3b8f21f222dba3ebe5a3c6b53f091103aca72 Mon Sep 17 00:00:00 2001 From: Victor Holanda Date: Mon, 21 Jan 2019 09:25:23 +0100 Subject: [PATCH 3/7] Fix log level bug --- reframe/core/logging.py | 12 ++++++------ reframe/frontend/printer.py | 12 +++++++++--- 2 files changed, 15 insertions(+), 9 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 968ff93030..0e47f46b2f 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -23,12 +23,12 @@ # Reframe's log levels -CRITICAL = 6 -ERROR = 5 -WARNING = 4 -INFO = 3 -VERBOSE = 2 -DEBUG = 1 +CRITICAL = 50 +ERROR = 40 +WARNING = 30 +INFO = 20 +VERBOSE = 19 +DEBUG = 10 NOTSET = 0 diff --git a/reframe/frontend/printer.py b/reframe/frontend/printer.py index 2309c7bfe9..64f67d3d51 100644 --- a/reframe/frontend/printer.py +++ b/reframe/frontend/printer.py @@ -64,9 +64,15 @@ def __repr__(self): def set_verbose_level(self, number): if number: for hdlr in self._logger.stream_handlers(): - loglevel = hdlr.loglevel() - new_level = max(loglevel - number, logging.DEBUG) - hdlr.setLevel(new_level) + for l in range(0,number): + loglevel = hdlr.loglevel() + if loglevel == logging.INFO: + new_level = max(loglevel - 1, logging.DEBUG) + elif loglevel == logging.VERBOSE: + new_level = max(loglevel - 9, logging.DEBUG) + else: + new_level = max(loglevel - 10, logging.DEBUG) + hdlr.setLevel(new_level) def separator(self, linestyle, msg=''): if linestyle == 'short double line': From 79d9bc754dbe924038e5e816c24949f184053089 Mon Sep 17 00:00:00 2001 From: Victor Holanda Date: Tue, 22 Jan 2019 16:56:30 +0100 Subject: [PATCH 4/7] Simplify verbosity implementation --- reframe/core/logging.py | 34 ++++++++-------------------------- reframe/frontend/cli.py | 2 +- reframe/frontend/printer.py | 6 +++--- 3 files changed, 12 insertions(+), 30 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 474cba6d52..8f329f6640 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -132,20 +132,6 @@ def close(self): super().close() -class StreamHandler(logging.StreamHandler): - def __init__(self, stream=None): - super().__init__(stream=stream) - self.__log_level = 'INFO' - self.setLevel('INFO') - - def setLevel(self, level): - super().setLevel(level) - self.__log_level = level - - def loglevel(self): - return self.__log_level - - def load_from_dict(logging_config): if not isinstance(logging_config, collections.abc.Mapping): raise TypeError('logging configuration is not a dict') @@ -214,9 +200,9 @@ def _create_filelog_handler(handler_config): def _create_stream_handler(handler_config): stream = handler_config.get('name', 'stdout') if stream == 'stdout': - return StreamHandler(stream=sys.stdout) + return logging.StreamHandler(stream=sys.stdout) elif stream == 'stderr': - return StreamHandler(stream=sys.stderr) + return logging.StreamHandler(stream=sys.stderr) else: raise ConfigError('unknown stream: %s' % stream) @@ -299,7 +285,6 @@ def __init__(self, name, level=logging.NOTSET): # class' check super().__init__(name, logging.NOTSET) self.level = _check_level(level) - self._stream_handlers = [] def __repr__(self): return debug.repr(self) @@ -307,14 +292,6 @@ def __repr__(self): def setLevel(self, level): self.level = _check_level(level) - def addHandler(self, hdlr): - if isinstance(hdlr, StreamHandler): - self._stream_handlers.append(hdlr) - super().addHandler(hdlr) - - def stream_handlers(self): - return self._stream_handlers - def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None, sinfo=None): record = super().makeRecord(name, level, fn, lno, msg, args, exc_info, @@ -387,7 +364,12 @@ def setLevel(self, level): def stream_handlers(self): if self.logger: - return self.logger._stream_handlers + _stream_handlers = [] + for hdlr in self.logger.handlers: + if isinstance(hdlr, logging.StreamHandler) and not \ + isinstance(hdlr, logging.FileHandler): + _stream_handlers.append(hdlr) + return _stream_handlers def _update_check_extras(self): """Return a dictionary with all the check-specific information.""" diff --git a/reframe/frontend/cli.py b/reframe/frontend/cli.py index 3b36fcd522..fed1f14ac6 100644 --- a/reframe/frontend/cli.py +++ b/reframe/frontend/cli.py @@ -265,7 +265,7 @@ def main(): # Setup printer printer = PrettyPrinter() printer.colorize = options.colorize - printer.set_verbose_level(options.verbose) + printer.set_verbosity(options.verbose) try: runtime.init_runtime(settings.site_configuration, options.system) diff --git a/reframe/frontend/printer.py b/reframe/frontend/printer.py index 6e5403896d..4c3164767e 100644 --- a/reframe/frontend/printer.py +++ b/reframe/frontend/printer.py @@ -20,11 +20,11 @@ def __init__(self): self.line_width = 78 self.status_width = 10 - def set_verbose_level(self, number): + def set_verbosity(self, number): if number: - for hdlr in self._logger.stream_handlers(): + for hdlr in self.stream_handlers(): for l in range(0,number): - loglevel = hdlr.loglevel() + loglevel = hdlr.level if loglevel == logging.INFO: new_level = max(loglevel - 1, logging.DEBUG) elif loglevel == logging.VERBOSE: From 12fd82588fffd7578930484e97b0b1305ab0ae82 Mon Sep 17 00:00:00 2001 From: Victor Holanda Date: Wed, 23 Jan 2019 11:03:33 +0100 Subject: [PATCH 5/7] Address PR remarks --- reframe/core/logging.py | 11 +++++------ reframe/frontend/cli.py | 5 +++-- reframe/frontend/printer.py | 22 ++++++++++------------ 3 files changed, 18 insertions(+), 20 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 8f329f6640..545b6852a8 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -362,14 +362,13 @@ def setLevel(self, level): if self.logger: super().setLevel(level) + @property def stream_handlers(self): if self.logger: - _stream_handlers = [] - for hdlr in self.logger.handlers: - if isinstance(hdlr, logging.StreamHandler) and not \ - isinstance(hdlr, logging.FileHandler): - _stream_handlers.append(hdlr) - return _stream_handlers + return [h for h in self.logger.handlers + if (isinstance(h, logging.StreamHandler) and + not isinstance(h, logging.FileHandler))] + return [] def _update_check_extras(self): """Return a dictionary with all the check-specific information.""" diff --git a/reframe/frontend/cli.py b/reframe/frontend/cli.py index fed1f14ac6..77c09b4337 100644 --- a/reframe/frontend/cli.py +++ b/reframe/frontend/cli.py @@ -89,7 +89,7 @@ def main(): 'end of the program') output_options.add_argument( '--verbose', '-v', action='count', default=0, - help='Increase output verbosity level') + help='Increase verbosity level of output') # Check discovery options locate_options.add_argument( @@ -265,7 +265,8 @@ def main(): # Setup printer printer = PrettyPrinter() printer.colorize = options.colorize - printer.set_verbosity(options.verbose) + if options.verbose: + printer.inc_verbosity(options.verbose) try: runtime.init_runtime(settings.site_configuration, options.system) diff --git a/reframe/frontend/printer.py b/reframe/frontend/printer.py index 4c3164767e..fa098584ef 100644 --- a/reframe/frontend/printer.py +++ b/reframe/frontend/printer.py @@ -20,18 +20,16 @@ def __init__(self): self.line_width = 78 self.status_width = 10 - def set_verbosity(self, number): - if number: - for hdlr in self.stream_handlers(): - for l in range(0,number): - loglevel = hdlr.level - if loglevel == logging.INFO: - new_level = max(loglevel - 1, logging.DEBUG) - elif loglevel == logging.VERBOSE: - new_level = max(loglevel - 9, logging.DEBUG) - else: - new_level = max(loglevel - 10, logging.DEBUG) - hdlr.setLevel(new_level) + def inc_verbosity(self, num_steps): + log_levels = sorted(logging._log_level_names.keys())[1:] # [1:] to exclude level NOTSET + for h in self.stream_handlers: + level_idx = log_levels.index(h.level) + try: + new_level = log_levels[level_idx - num_steps] + except IndexError: + new_level = 0 + + h.setLevel(new_level) def separator(self, linestyle, msg=''): if linestyle == 'short double line': From f22549160316305c7120ea7b5f253c177c70b04a Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Wed, 23 Jan 2019 17:38:55 +0100 Subject: [PATCH 6/7] Fine tune implementation - `inc_verbosity()` moved to the LoggerAdapter - Fix a couple of bugs - Fix coding style issues --- reframe/core/logging.py | 20 ++++++++++++++++---- reframe/frontend/printer.py | 11 ----------- 2 files changed, 16 insertions(+), 15 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 545b6852a8..b36843c78f 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -363,12 +363,12 @@ def setLevel(self, level): super().setLevel(level) @property - def stream_handlers(self): + def std_stream_handlers(self): if self.logger: return [h for h in self.logger.handlers - if (isinstance(h, logging.StreamHandler) and - not isinstance(h, logging.FileHandler))] - return [] + if h.stream == sys.stdout or h.stream == sys.stderr] + else: + return [] def _update_check_extras(self): """Return a dictionary with all the check-specific information.""" @@ -439,6 +439,18 @@ def error(self, message, *args, **kwargs): super().error(message, *args, **kwargs) + def inc_verbosity(self, num_steps): + """Convenience function for increasing the verbosity + of the logger step-wise.""" + log_levels = sorted(_log_level_names.keys())[1:] + for h in self.std_stream_handlers: + level_idx = log_levels.index(h.level) + if level_idx - num_steps < 0: + new_level = log_levels[0] + else: + new_level = log_levels[level_idx - num_steps] + + h.setLevel(new_level) # A logger that doesn't log anything diff --git a/reframe/frontend/printer.py b/reframe/frontend/printer.py index fa098584ef..ab1f340f02 100644 --- a/reframe/frontend/printer.py +++ b/reframe/frontend/printer.py @@ -20,17 +20,6 @@ def __init__(self): self.line_width = 78 self.status_width = 10 - def inc_verbosity(self, num_steps): - log_levels = sorted(logging._log_level_names.keys())[1:] # [1:] to exclude level NOTSET - for h in self.stream_handlers: - level_idx = log_levels.index(h.level) - try: - new_level = log_levels[level_idx - num_steps] - except IndexError: - new_level = 0 - - h.setLevel(new_level) - def separator(self, linestyle, msg=''): if linestyle == 'short double line': line = self.status_width * '=' From 85a2b402f304565a5995a10d9dd6343683d434d8 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Thu, 24 Jan 2019 00:04:11 +0100 Subject: [PATCH 7/7] Add unit test for verbosity option --- unittests/test_cli.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/unittests/test_cli.py b/unittests/test_cli.py index 21f9bb8537..cb644160a5 100644 --- a/unittests/test_cli.py +++ b/unittests/test_cli.py @@ -387,3 +387,13 @@ def test_show_env_config_unknown_env(self): self.assertNotIn('Traceback', stdout) self.assertNotIn('Traceback', stderr) self.assertEqual(1, returncode) + + def test_verbosity(self): + self.more_options = ['-vvvvv'] + self.system = 'testsys' + self.action = 'list' + returncode, stdout, stderr = self._run_reframe() + self.assertNotEqual('', stdout) + self.assertNotIn('Traceback', stdout) + self.assertNotIn('Traceback', stderr) + self.assertEqual(0, returncode)