Merge branch 'ThomasWaldmann-silent'

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:

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

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

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)

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
 

docs/development.rst

@@ -19,6 +19,18 @@ separate sections either. The `flake8
 <https://flake8.readthedocs.org/>`_ 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
 ----------------------------------
 

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