From d8d3c8521b09c63dd53608aa02c9c89e5be7e87c Mon Sep 17 00:00:00 2001 From: Thomas Waldmann Date: Fri, 23 Oct 2015 02:29:41 +0200 Subject: [PATCH] fix logging levels All normal informational output is now logged at INFO level. To actually see normal output, the logger is configured to level INFO also. Log levels: WARNING is for warnings, ERROR is for (fatal) errors, DEBUG is for debugging. logging levels must only be used according to this semantics and must not be (ab)used to let something show up (although the logger would usually hide it) or hide something (although the logger would usually show it). Controlling the amount of output shown on INFO level: --verbose, --progress, --stats are currently used for this. more such flags might be added later as needed. if they are set, more output is logged (at INFO level). also: change strange setup_logging return value --- borg/archiver.py | 29 +++++++++++++++++------------ borg/logger.py | 24 +++++++++--------------- borg/testsuite/archiver.py | 17 ++++++++++++++--- borg/testsuite/logger.py | 5 +---- 4 files changed, 41 insertions(+), 34 deletions(-) diff --git a/borg/archiver.py b/borg/archiver.py index 4dcf38670..6bcba3dd2 100644 --- a/borg/archiver.py +++ b/borg/archiver.py @@ -37,8 +37,9 @@ has_lchflags = hasattr(os, 'lchflags') class Archiver: - def __init__(self): + def __init__(self, verbose=False): self.exit_code = EXIT_SUCCESS + self.verbose = verbose def open_repository(self, location, create=False, exclusive=False): if location.proto == 'ssh': @@ -53,12 +54,14 @@ class Archiver: self.exit_code = EXIT_WARNING # we do not terminate here, so it is a warning logger.error('borg: ' + msg) - def print_verbose(self, msg, *args, **kw): - msg = args and msg % args or msg - logger.info(msg) + def print_verbose(self, msg, *args): + if self.verbose: + msg = args and msg % args or msg + logger.info(msg) def print_status(self, status, path): - logger.info("%1s %s", status, remove_surrogates(path)) + if self.verbose: + logger.info("%1s %s", status, remove_surrogates(path)) def do_serve(self, args): """Start in server mode. This command is usually not used manually. @@ -89,7 +92,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") if input('Do you want to continue? ') == 'Yes I am sure': break if not args.archives_only: - logger.warning('Starting repository check...') + logger.info('Starting repository check...') if repository.check(repair=args.repair): logger.info('Repository check complete, no problems found.') else: @@ -556,8 +559,8 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") def build_parser(self, args=None, prog=None): common_parser = argparse.ArgumentParser(add_help=False, prog=prog) - common_parser.add_argument('-v', '--verbose', dest='verbose', action='count', - help='verbose output, defaults to warnings only') + common_parser.add_argument('-v', '--verbose', dest='verbose', action='store_true', default=False, + help='verbose output') common_parser.add_argument('--no-files-cache', dest='cache_files', action='store_false', help='do not load/update the file metadata cache used to detect unchanged files') common_parser.add_argument('--umask', dest='umask', type=lambda s: int(s, 8), default=RemoteRepository.umask, metavar='M', @@ -996,7 +999,8 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") parser = self.build_parser(args) args = parser.parse_args(args or ['-h']) - setup_logging(args) + self.verbose = args.verbose + setup_logging() os.umask(args.umask) RemoteRepository.remote_path = args.remote_path RemoteRepository.umask = args.umask @@ -1015,7 +1019,7 @@ def sig_info_handler(signum, stack): # pragma: no cover total = loc['st'].st_size except Exception: pos, total = 0, 0 - logger.warning("{0} {1}/{2}".format(path, format_file_size(pos), format_file_size(total))) + logger.info("{0} {1}/{2}".format(path, format_file_size(pos), format_file_size(total))) break if func in ('extract_item', ): # extract op path = loc['item'][b'path'] @@ -1023,7 +1027,7 @@ def sig_info_handler(signum, stack): # pragma: no cover pos = loc['fd'].tell() except Exception: pos = 0 - logger.warning("{0} {1}/???".format(path, format_file_size(pos))) + logger.info("{0} {1}/???".format(path, format_file_size(pos))) break @@ -1069,7 +1073,8 @@ def main(): # pragma: no cover elif exit_code == EXIT_ERROR: logger.error(exit_msg % ('error', exit_code)) else: - logger.error(exit_msg % ('abnormal', exit_code)) + # if you see 666 in output, it usually means exit_code was None + logger.error(exit_msg % ('abnormal', exit_code or 666)) sys.exit(exit_code) diff --git a/borg/logger.py b/borg/logger.py index 2b4ad23ba..69f2a3c22 100644 --- a/borg/logger.py +++ b/borg/logger.py @@ -10,9 +10,9 @@ The way to use this is as follows: * then each module uses logger.info/warning/debug/etc according to the level it believes is appropriate: - logger.debug('some intricate details you usually do not care about') - logger.info('verbose progress information') - logger.warning('some non-error condition that must always be reported') + logger.debug('debugging info for developers or power users') + logger.info('normal, informational output') + logger.warning('warn about a non-fatal error or sth else') logger.error('a fatal error') ... and so on. see the `logging documentation @@ -26,9 +26,8 @@ The way to use this is as follows: stream it is using, unfortunately. we assume that it won't clutter stdout, because interaction would be broken then anyways -* advanced verbosity filters, based on what i described in - https://github.com/borgbackup/borg/pull/233#issuecomment-145100222 - may eventually be implemented +* what is output on INFO level is additionally controlled by commandline + flags """ import inspect @@ -36,11 +35,11 @@ import logging import sys -def setup_logging(args, stream=None): +def setup_logging(stream=None): """setup logging module according to the arguments provided this sets up a stream handler logger on stderr (by default, if no - stream is provided) and verbosity levels. + stream is provided). """ logging.raiseExceptions = False l = logging.getLogger('') @@ -50,13 +49,8 @@ def setup_logging(args, stream=None): # example: # sh.setFormatter(logging.Formatter('%(name)s: %(message)s')) l.addHandler(sh) - levels = {None: logging.WARNING, - 0: logging.WARNING, - 1: logging.INFO, - 2: logging.DEBUG} - # default to WARNING, -v goes to INFO and -vv to DEBUG - l.setLevel(levels[args.verbose]) - return sh, + l.setLevel(logging.INFO) + return sh def find_parent_module(): diff --git a/borg/testsuite/archiver.py b/borg/testsuite/archiver.py index f0adf2cba..850955259 100644 --- a/borg/testsuite/archiver.py +++ b/borg/testsuite/archiver.py @@ -282,9 +282,20 @@ class ArchiverTestCase(ArchiverTestCaseBase): shutil.rmtree(self.cache_path) with environment_variable(BORG_UNKNOWN_UNENCRYPTED_REPO_ACCESS_IS_OK='1'): info_output2 = self.cmd('info', self.repository_location + '::test') - # info_output2 starts with some "initializing cache" text but should - # end the same way as info_output - assert info_output2.endswith(info_output) + + def filter(output): + # filter for interesting "info" output, ignore cache rebuilding related stuff + prefixes = ['Name:', 'Fingerprint:', 'Number of files:', 'This archive:', + 'All archives:', 'Chunk index:', ] + result = [] + for line in output.splitlines(): + for prefix in prefixes: + if line.startswith(prefix): + result.append(line) + return '\n'.join(result) + + # the interesting parts of info_output2 and info_output should be same + self.assert_equal(filter(info_output), filter(info_output2)) def _extract_repository_id(self, path): return Repository(self.repository_path).id diff --git a/borg/testsuite/logger.py b/borg/testsuite/logger.py index f6382513a..1db72bf2e 100644 --- a/borg/testsuite/logger.py +++ b/borg/testsuite/logger.py @@ -11,10 +11,7 @@ logger = create_logger() @pytest.fixture() def io_logger(): io = StringIO() - args = Mock() - args.verbose = 2 - assert args.verbose == 2 - handler, = setup_logging(args, io) + handler = setup_logging(io) handler.setFormatter(logging.Formatter('%(name)s: %(message)s')) logger.setLevel(logging.DEBUG) return io