diff --git a/borg/archive.py b/borg/archive.py index d5b46792c..f4d98a3a7 100644 --- a/borg/archive.py +++ b/borg/archive.py @@ -3,7 +3,6 @@ from datetime import datetime from getpass import getuser from itertools import groupby import errno -import logging from .logger import create_logger logger = create_logger() @@ -663,20 +662,24 @@ class ArchiveChecker: self.possibly_superseded = set() def check(self, repository, repair=False, archive=None, last=None): - self.report_progress('Starting archive consistency check...') + logger.info('Starting archive consistency check...') self.check_all = archive is None and last is None self.repair = repair self.repository = repository self.init_chunks() self.key = self.identify_key(repository) if Manifest.MANIFEST_ID not in self.chunks: + logger.error("Repository manifest not found!") + self.error_found = True self.manifest = self.rebuild_manifest() else: self.manifest, _ = Manifest.load(repository, key=self.key) self.rebuild_refcounts(archive=archive, last=last) self.orphan_chunks_check() self.finish() - if not self.error_found: + if self.error_found: + logger.error('Archive consistency check complete, problems found.') + else: logger.info('Archive consistency check complete, no problems found.') return self.repair or not self.error_found @@ -696,11 +699,6 @@ class ArchiveChecker: for id_ in result: self.chunks[id_] = (0, 0, 0) - def report_progress(self, msg, error=False): - if error: - self.error_found = True - logger.log(logging.ERROR if error else logging.WARNING, msg) - def identify_key(self, repository): cdata = repository.get(next(self.chunks.iteritems())[0]) return key_factory(repository, cdata) @@ -710,7 +708,7 @@ class ArchiveChecker: Iterates through all objects in the repository looking for archive metadata blocks. """ - self.report_progress('Rebuilding missing manifest, this might take some time...', error=True) + logger.info('Rebuilding missing manifest, this might take some time...') manifest = Manifest(self.key, self.repository) for chunk_id, _ in self.chunks.iteritems(): cdata = self.repository.get(chunk_id) @@ -727,9 +725,9 @@ class ArchiveChecker: except (TypeError, ValueError, StopIteration): continue if isinstance(archive, dict) and b'items' in archive and b'cmdline' in archive: - self.report_progress('Found archive ' + archive[b'name'].decode('utf-8'), error=True) + logger.info('Found archive %s', archive[b'name'].decode('utf-8')) manifest.archives[archive[b'name'].decode('utf-8')] = {b'id': chunk_id, b'time': archive[b'time']} - self.report_progress('Manifest rebuild complete', error=True) + logger.info('Manifest rebuild complete.') return manifest def rebuild_refcounts(self, archive=None, last=None): @@ -771,7 +769,8 @@ class ArchiveChecker: for chunk_id, size, csize in item[b'chunks']: if chunk_id not in self.chunks: # If a file chunk is missing, create an all empty replacement chunk - self.report_progress('{}: Missing file chunk detected (Byte {}-{})'.format(item[b'path'].decode('utf-8', 'surrogateescape'), offset, offset + size), error=True) + logger.error('{}: Missing file chunk detected (Byte {}-{})'.format(item[b'path'].decode('utf-8', 'surrogateescape'), offset, offset + size)) + self.error_found = True data = bytes(size) chunk_id = self.key.id_hash(data) cdata = self.key.encrypt(data) @@ -800,7 +799,8 @@ class ArchiveChecker: def report(msg, chunk_id, chunk_no): cid = hexlify(chunk_id).decode('ascii') msg += ' [chunk: %06d_%s]' % (chunk_no, cid) # see debug-dump-archive-items - self.report_progress(msg, error=True) + self.error_found = True + logger.error(msg) i = 0 for state, items in groupby(archive[b'items'], missing_chunk_detector): @@ -841,7 +841,8 @@ class ArchiveChecker: logger.info('Analyzing archive {} ({}/{})'.format(name, num_archives - i, num_archives)) archive_id = info[b'id'] if archive_id not in self.chunks: - self.report_progress('Archive metadata block is missing', error=True) + logger.error('Archive metadata block is missing!') + self.error_found = True del self.manifest.archives[name] continue mark_as_possibly_superseded(archive_id) @@ -876,12 +877,13 @@ class ArchiveChecker: unused.add(id_) orphaned = unused - self.possibly_superseded if orphaned: - self.report_progress('{} orphaned objects found'.format(len(orphaned)), error=True) + logger.error('{} orphaned objects found!'.format(len(orphaned))) + self.error_found = True if self.repair: for id_ in unused: self.repository.delete(id_) else: - self.report_progress('Orphaned objects check skipped (needs all archives checked)') + logger.warning('Orphaned objects check skipped (needs all archives checked).') def finish(self): if self.repair: diff --git a/borg/archiver.py b/borg/archiver.py index 51801dd25..fcccaccf6 100644 --- a/borg/archiver.py +++ b/borg/archiver.py @@ -51,9 +51,8 @@ class ToggleAction(argparse.Action): class Archiver: - def __init__(self, verbose=False, lock_wait=None): + def __init__(self, lock_wait=None): self.exit_code = EXIT_SUCCESS - self.verbose = verbose self.lock_wait = lock_wait def open_repository(self, location, create=False, exclusive=False, lock=True): @@ -74,10 +73,9 @@ class Archiver: self.exit_code = EXIT_WARNING # we do not terminate here, so it is a warning logger.warning(msg) - def print_verbose(self, msg, *args): - if self.verbose: - msg = args and msg % args or msg - logger.info(msg) + def print_file_status(self, status, path): + if self.output_filter is None or status in self.output_filter: + logger.info("%1s %s", status, remove_surrogates(path)) def do_serve(self, args): """Start in server mode. This command is usually not used manually. @@ -123,6 +121,7 @@ class Archiver: def do_create(self, args): """Create new archive""" + self.output_filter = args.output_filter dry_run = args.dry_run t0 = datetime.now() if not dry_run: @@ -163,7 +162,7 @@ class Archiver: self.print_warning('%s: %s', path, e) else: status = '-' - self.print_verbose("%1s %s", status, remove_surrogates(path)) + self.print_file_status(status, path) continue path = os.path.normpath(path) if args.one_file_system: @@ -262,9 +261,7 @@ class Archiver: status = '?' # need to add a status code somewhere else: status = '-' # dry run, item was not backed up - # output ALL the stuff - it can be easily filtered using grep. - # even stuff considered unchanged might be interesting. - self.print_verbose("%1s %s", status, remove_surrogates(path)) + self.print_file_status(status, path) def do_extract(self, args): """Extract archive contents""" @@ -292,7 +289,7 @@ class Archiver: 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)) + logger.info(remove_surrogates(orig_path)) try: if dry_run: archive.extract_item(item, dry_run=True) @@ -378,7 +375,7 @@ class Archiver: else: archive = None operations = FuseOperations(key, repository, manifest, archive) - self.print_verbose("Mounting filesystem") + logger.info("Mounting filesystem") try: operations.mount(args.mountpoint, args.options, args.foreground) except RuntimeError: @@ -481,12 +478,12 @@ class Archiver: 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)) + logger.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)) + logger.info('Would prune: %s' % format_archive(archive)) else: - self.print_verbose('Pruning archive: %s' % format_archive(archive)) + logger.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() @@ -663,11 +660,12 @@ class Archiver: 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='store_true', default=False, - help='verbose output') - common_parser.add_argument('--log-level', dest='log_level', default='info', metavar='LEVEL', - choices=('debug', 'info', 'warning', 'error', 'critical'), - help='set the log level to LEVEL, default: %(default)s)') + common_parser.add_argument('-v', '--verbose', '--info', dest='log_level', + action='store_const', const='info', default='warning', + help='enable informative (verbose) output, work on log level INFO') + common_parser.add_argument('--debug', dest='log_level', + action='store_const', const='debug', default='warning', + help='enable debug output, work on log level DEBUG') common_parser.add_argument('--lock-wait', dest='lock_wait', type=int, metavar='N', default=1, help='wait for the lock, but max. N seconds (default: %(default)d).') common_parser.add_argument('--show-rc', dest='show_rc', action='store_true', default=False, @@ -802,6 +800,8 @@ class Archiver: help="""toggle progress display while creating the archive, showing Original, Compressed and Deduplicated sizes, followed by the Number of files seen and the path being processed, default: %(default)s""") + subparser.add_argument('--filter', dest='output_filter', metavar='STATUSCHARS', + help='only display items with the given status characters') subparser.add_argument('-e', '--exclude', dest='excludes', type=ExcludePattern, action='append', metavar="PATTERN", help='exclude paths matching PATTERN') @@ -1177,7 +1177,6 @@ class Archiver: def run(self, args): os.umask(args.umask) # early, before opening files - self.verbose = args.verbose self.lock_wait = args.lock_wait RemoteRepository.remote_path = args.remote_path RemoteRepository.umask = args.umask diff --git a/borg/repository.py b/borg/repository.py index 80c8ed789..3765d9c50 100644 --- a/borg/repository.py +++ b/borg/repository.py @@ -365,7 +365,7 @@ class Repository: if repair: logger.info('Completed repository check, errors found and repaired.') else: - logger.info('Completed repository check, errors found.') + logger.error('Completed repository check, errors found.') else: logger.info('Completed repository check, no problems found.') return not error_found or repair diff --git a/borg/testsuite/archiver.py b/borg/testsuite/archiver.py index 9d78988c6..0698befc5 100644 --- a/borg/testsuite/archiver.py +++ b/borg/testsuite/archiver.py @@ -713,16 +713,40 @@ class ArchiverTestCase(ArchiverTestCaseBase): os.utime('input/file1', (now - 5, now - 5)) # 5 seconds ago self.create_regular_file('file2', size=1024 * 80) self.cmd('init', self.repository_location) - output = self.cmd('create', '--verbose', self.repository_location + '::test', 'input') + output = self.cmd('create', '-v', self.repository_location + '::test', 'input') self.assert_in("A input/file1", output) self.assert_in("A input/file2", output) # should find first file as unmodified - output = self.cmd('create', '--verbose', self.repository_location + '::test1', 'input') + output = self.cmd('create', '-v', self.repository_location + '::test1', 'input') self.assert_in("U input/file1", output) # this is expected, although surprising, for why, see: # http://borgbackup.readthedocs.org/en/latest/faq.html#i-am-seeing-a-added-status-for-a-unchanged-file self.assert_in("A input/file2", output) + def test_create_topical(self): + now = time.time() + self.create_regular_file('file1', size=1024 * 80) + os.utime('input/file1', (now-5, now-5)) + self.create_regular_file('file2', size=1024 * 80) + self.cmd('init', self.repository_location) + # no listing by default + output = self.cmd('create', self.repository_location + '::test', 'input') + self.assert_not_in('file1', output) + # shouldn't be listed even if unchanged + output = self.cmd('create', self.repository_location + '::test0', 'input') + self.assert_not_in('file1', output) + # should list the file as unchanged + output = self.cmd('create', '-v', '--filter=U', self.repository_location + '::test1', 'input') + self.assert_in('file1', output) + # should *not* list the file as changed + output = self.cmd('create', '-v', '--filter=AM', self.repository_location + '::test2', 'input') + self.assert_not_in('file1', output) + # change the file + self.create_regular_file('file1', size=1024 * 100) + # should list the file as changed + output = self.cmd('create', '-v', '--filter=AM', self.repository_location + '::test3', 'input') + self.assert_in('file1', output) + def test_cmdline_compatibility(self): self.create_regular_file('file1', size=1024 * 80) self.cmd('init', self.repository_location) @@ -926,13 +950,13 @@ class ArchiverCheckTestCase(ArchiverTestCaseBase): return archive, repository def test_check_usage(self): - output = self.cmd('check', self.repository_location, exit_code=0) + output = self.cmd('check', '-v', self.repository_location, exit_code=0) self.assert_in('Starting repository check', output) self.assert_in('Starting archive consistency check', output) - output = self.cmd('check', '--repository-only', self.repository_location, exit_code=0) + output = self.cmd('check', '-v', '--repository-only', self.repository_location, exit_code=0) self.assert_in('Starting repository check', output) self.assert_not_in('Starting archive consistency check', output) - output = self.cmd('check', '--archives-only', self.repository_location, exit_code=0) + output = self.cmd('check', '-v', '--archives-only', self.repository_location, exit_code=0) self.assert_not_in('Starting repository check', output) self.assert_in('Starting archive consistency check', output) @@ -968,7 +992,7 @@ class ArchiverCheckTestCase(ArchiverTestCaseBase): repository.delete(Manifest.MANIFEST_ID) repository.commit() self.cmd('check', self.repository_location, exit_code=1) - output = self.cmd('check', '--repair', self.repository_location, exit_code=0) + output = self.cmd('check', '-v', '--repair', self.repository_location, exit_code=0) self.assert_in('archive1', output) self.assert_in('archive2', output) self.cmd('check', self.repository_location, exit_code=0) diff --git a/docs/changes.rst b/docs/changes.rst index d87dba7dd..712e89989 100644 --- a/docs/changes.rst +++ b/docs/changes.rst @@ -25,7 +25,9 @@ New features: - implement borg break-lock command, fixes #157 - include system info below traceback, fixes #324 - use ISO-8601 date and time format, fixes #375 -- add --log-level to set the level of the builtin logging configuration, fixes #426 +- add --debug and --info (same as --verbose) to set the log level of the + builtin logging configuration (which otherwise defaults to warning), + fixes #426 - configure logging via env var BORG_LOGGING_CONF - add a --no-progress flag to forcibly disable progress info diff --git a/docs/development.rst b/docs/development.rst index 753f3d554..0d75dfe4a 100644 --- a/docs/development.rst +++ b/docs/development.rst @@ -19,6 +19,18 @@ separate sections either. The `flake8 `_ commandline tool should be used to check for style errors before sending pull requests. +Output and Logging +------------------ +When writing logger calls, always use correct log level (debug only for +debugging, info for informative messages, warning for warnings, error for +errors, critical for critical errors/states). + +When directly talking to the user (e.g. Y/N questions), do not use logging, +but directly output to stderr (not: stdout, it could be connected to a pipe). + +To control the amount and kinds of messages output to stderr or emitted at +info level, use flags like --stats. + Building a development environment ---------------------------------- diff --git a/docs/usage.rst b/docs/usage.rst index 1db3bc594..1d31d6e5f 100644 --- a/docs/usage.rst +++ b/docs/usage.rst @@ -14,18 +14,20 @@ General Type of log output ~~~~~~~~~~~~~~~~~~ -You can set the log level of the builtin logging configuration using the ---log-level option. +The log level of the builtin logging configuration defaults to WARNING. +This is because we want |project_name| to be mostly silent and only output +warnings (plus errors and critical messages). -Supported levels: ``debug``, ``info``, ``warning``, ``error``, ``critical``. +Use --verbose or --info to set INFO (you will get informative output then +additionally to warnings, errors, critical messages). +Use --debug to set DEBUG to get output made for debugging. -All log messages created with at least the given level will be output. +All log messages created with at least the set level will be output. -Amount of informational output -~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Log levels: DEBUG < INFO < WARNING < ERROR < CRITICAL -For some subcommands, using the ``-v`` or ``--verbose`` option will give you -more informational output (at ``info`` level). +While you can set misc. log levels, do not expect that every command will +give different output on different log levels - it's just a possibility. Return codes ~~~~~~~~~~~~ @@ -436,8 +438,13 @@ Item flags ~~~~~~~~~~ `borg create -v` outputs a verbose list of all files, directories and other -file system items it considered. For each item, it prefixes a single-letter -flag that indicates type and/or status of the item. +file system items it considered (no matter whether they had content changes +or not). For each item, it prefixes a single-letter flag that indicates type +and/or status of the item. + +If you are interested only in a subset of that output, you can give e.g. +`--filter=AME` and it will only show regular files with A, M or E status (see +below). A uppercase character represents the status of a regular file relative to the "files" cache (not relative to the repo - this is an issue if the files cache