From d8d3c8521b09c63dd53608aa02c9c89e5be7e87c Mon Sep 17 00:00:00 2001 From: Thomas Waldmann Date: Fri, 23 Oct 2015 02:29:41 +0200 Subject: [PATCH 1/3] 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 From 7b73abdcdac22c8730a0468efa7a27bb5808d136 Mon Sep 17 00:00:00 2001 From: Thomas Waldmann Date: Sun, 25 Oct 2015 02:35:42 +0200 Subject: [PATCH 2/3] archiver: rename print_x methods so they correspond to log levels also: remove some "Warning: " msg prefixes - if we emit at WARNING level, it is obviously a warning. remove some "borg: " msg prefixes. --- borg/archiver.py | 46 +++++++++++++++++++++++++--------------------- 1 file changed, 25 insertions(+), 21 deletions(-) diff --git a/borg/archiver.py b/borg/archiver.py index 6bcba3dd2..d3033b0d1 100644 --- a/borg/archiver.py +++ b/borg/archiver.py @@ -51,17 +51,21 @@ class Archiver: def print_error(self, msg, *args): msg = args and msg % args or msg - self.exit_code = EXIT_WARNING # we do not terminate here, so it is a warning - logger.error('borg: ' + msg) + self.exit_code = EXIT_ERROR + logger.error(msg) - def print_verbose(self, msg, *args): + def print_warning(self, msg, *args): + msg = args and msg % args or msg + self.exit_code = EXIT_WARNING # we do not terminate here, so it is a warning + logger.warning(msg) + + def print_info(self, msg, *args): if self.verbose: msg = args and msg % args or msg logger.info(msg) def print_status(self, status, path): - if self.verbose: - logger.info("%1s %s", status, remove_surrogates(path)) + self.print_info("%1s %s", status, remove_surrogates(path)) def do_serve(self, args): """Start in server mode. This command is usually not used manually. @@ -85,7 +89,7 @@ class Archiver: repository = self.open_repository(args.repository, exclusive=args.repair) if args.repair: while not os.environ.get('BORG_CHECK_I_KNOW_WHAT_I_AM_DOING'): - self.print_error("""Warning: 'check --repair' is an experimental feature that might result + self.print_warning("""'check --repair' is an experimental feature that might result in data loss. Type "Yes I am sure" if you understand this and want to continue.\n""") @@ -147,7 +151,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: status = archive.process_stdin(path, cache) except IOError as e: - self.print_error('%s: %s', path, e) + self.print_warning('%s: %s', path, e) else: status = '-' self.print_status(status, path) @@ -157,7 +161,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: restrict_dev = os.lstat(path).st_dev except OSError as e: - self.print_error('%s: %s', path, e) + self.print_warning('%s: %s', path, e) continue else: restrict_dev = None @@ -184,7 +188,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: st = os.lstat(path) except OSError as e: - self.print_error('%s: %s', path, e) + self.print_warning('%s: %s', path, e) return if (st.st_ino, st.st_dev) in skip_inodes: return @@ -201,7 +205,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: status = archive.process_file(path, st, cache) except IOError as e: - self.print_error('%s: %s', path, e) + self.print_warning('%s: %s', path, e) elif stat.S_ISDIR(st.st_mode): if exclude_caches and is_cachedir(path): return @@ -210,7 +214,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: entries = os.listdir(path) except OSError as e: - self.print_error('%s: %s', path, e) + self.print_warning('%s: %s', path, e) else: for filename in sorted(entries): entry_path = os.path.normpath(os.path.join(path, filename)) @@ -230,7 +234,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") # Ignore unix sockets return else: - self.print_error('Unknown file type: %s', path) + self.print_warning('Unknown file type: %s', path) return # Status output # A lowercase character means a file type other than a regular file, @@ -273,7 +277,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") if not args.dry_run: while dirs and not item[b'path'].startswith(dirs[-1][b'path']): archive.extract_item(dirs.pop(-1), stdout=stdout) - self.print_verbose(remove_surrogates(orig_path)) + self.print_info(remove_surrogates(orig_path)) try: if dry_run: archive.extract_item(item, dry_run=True) @@ -284,14 +288,14 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") else: archive.extract_item(item, stdout=stdout, sparse=sparse) except IOError as e: - self.print_error('%s: %s', remove_surrogates(orig_path), e) + self.print_warning('%s: %s', remove_surrogates(orig_path), e) if not args.dry_run: while dirs: archive.extract_item(dirs.pop(-1)) for pattern in (patterns or []): if isinstance(pattern, IncludePattern) and pattern.match_count == 0: - self.print_error("Warning: Include pattern '%s' never matched.", pattern) + self.print_warning("Include pattern '%s' never matched.", pattern) return self.exit_code def do_rename(self, args): @@ -343,7 +347,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: from .fuse import FuseOperations except ImportError as e: - self.print_error('loading fuse support failed [ImportError: %s]' % str(e)) + self.print_error('Loading fuse support failed [ImportError: %s]' % str(e)) return self.exit_code if not os.path.isdir(args.mountpoint) or not os.access(args.mountpoint, os.R_OK | os.W_OK | os.X_OK): @@ -357,7 +361,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") else: archive = None operations = FuseOperations(key, repository, manifest, archive) - self.print_verbose("Mounting filesystem") + self.print_info("Mounting filesystem") try: operations.mount(args.mountpoint, args.options, args.foreground) except RuntimeError: @@ -435,7 +439,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") if args.hourly + args.daily + args.weekly + args.monthly + args.yearly == 0 and args.within is None: self.print_error('At least one of the "within", "keep-hourly", "keep-daily", "keep-weekly", ' '"keep-monthly" or "keep-yearly" settings must be specified') - return EXIT_ERROR + return self.exit_code if args.prefix: archives = [archive for archive in archives if archive.name.startswith(args.prefix)] keep = [] @@ -456,12 +460,12 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") to_delete = [a for a in archives if a not in keep] stats = Statistics() for archive in keep: - self.print_verbose('Keeping archive: %s' % format_archive(archive)) + self.print_info('Keeping archive: %s' % format_archive(archive)) for archive in to_delete: if args.dry_run: - self.print_verbose('Would prune: %s' % format_archive(archive)) + self.print_info('Would prune: %s' % format_archive(archive)) else: - self.print_verbose('Pruning archive: %s' % format_archive(archive)) + self.print_info('Pruning archive: %s' % format_archive(archive)) Archive(repository, key, manifest, archive.name, cache).delete(stats) if to_delete and not args.dry_run: manifest.write() From f285e90912bb6fd5fdcbeae1b0e4edc5a05f18b3 Mon Sep 17 00:00:00 2001 From: Thomas Waldmann Date: Sun, 25 Oct 2015 02:53:36 +0200 Subject: [PATCH 3/3] archiver: add E status as error indication E means that an error occured when processing this (single) item --- borg/archiver.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/borg/archiver.py b/borg/archiver.py index d3033b0d1..c0f5b21a5 100644 --- a/borg/archiver.py +++ b/borg/archiver.py @@ -151,6 +151,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: status = archive.process_stdin(path, cache) except IOError as e: + status = 'E' self.print_warning('%s: %s', path, e) else: status = '-' @@ -205,6 +206,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: status = archive.process_file(path, st, cache) except IOError as e: + status = 'E' self.print_warning('%s: %s', path, e) elif stat.S_ISDIR(st.st_mode): if exclude_caches and is_cachedir(path): @@ -214,6 +216,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""") try: entries = os.listdir(path) except OSError as e: + status = 'E' self.print_warning('%s: %s', path, e) else: for filename in sorted(entries):