Print implied output without --info/-v

There are persistent questions why output from options like --list
and --stats doesn't show up.  Also, borg currently isn't able to
show *just* the output for a given option (--list, --stats,
--show-rc, --show-version, or --progress), without other INFO level
messages.

The solution is to use more granular loggers, so that messages
specific to a given option goes to a logger designated for that
option.  That option-specific logger can then be configured
separately from the regular loggers.

Those option-specific loggers can also be used as a hook in a
BORG_LOGGING_CONF config file to log the --list output to a separate
file, or send --stats output to a network socket where some daemon
could analyze it.

Steps:
- create an option-specific logger for each of the implied output options
- modify the messages specific to each option to go to the correct logger
- if an implied output option is passed, change the option-specific
  logger (only) to log at INFO level
- test that root logger messages don't come through option-specific loggers

They shouldn't, per https://docs.python.org/3/howto/logging.html#logging-flow
but test just the same.  Particularly test a message that can come from
remote repositories.

Fixes #526, #573, #665, #824

borg/archiver.py

@@ -8,6 +8,7 @@ import functools
 import hashlib
 import inspect
 import io
+import logging
 import os
 import re
 import shlex
@@ -111,7 +112,7 @@ class Archiver:
 
     def print_file_status(self, status, path):
         if self.output_list and (self.output_filter is None or status in self.output_filter):
-            logger.info("%1s %s", status, remove_surrogates(path))
+            logging.getLogger('borg.output.list').info("%1s %s", status, remove_surrogates(path))
 
     @staticmethod
     def compare_chunk_contents(chunks1, chunks2):
@@ -277,7 +278,7 @@ class Archiver:
                               DASHES,
                               str(archive.stats),
                               str(cache),
-                              DASHES)
+                              DASHES, logger=logging.getLogger('borg.output.stats'))
 
         self.output_filter = args.output_filter
         self.output_list = args.output_list
@@ -416,7 +417,7 @@ class Archiver:
                 while dirs and not item[b'path'].startswith(dirs[-1][b'path']):
                     archive.extract_item(dirs.pop(-1), stdout=stdout)
             if output_list:
-                logger.info(remove_surrogates(orig_path))
+                logging.getLogger('borg.output.list').info(remove_surrogates(orig_path))
             try:
                 if dry_run:
                     archive.extract_item(item, dry_run=True)
@@ -673,7 +674,7 @@ class Archiver:
                     log_multi(DASHES,
                               stats.summary.format(label='Deleted data:', stats=stats),
                               str(cache),
-                              DASHES)
+                              DASHES, logger=logging.getLogger('borg.output.stats'))
         else:
             if not args.cache_only:
                 msg = []
@@ -820,18 +821,19 @@ class Archiver:
         to_delete = (set(archives) | checkpoints) - (set(keep) | set(keep_checkpoints))
         stats = Statistics()
         with Cache(repository, key, manifest, do_files=args.cache_files, lock_wait=self.lock_wait) as cache:
+            list_logger = logging.getLogger('borg.output.list')
             for archive in archives_checkpoints:
                 if archive in to_delete:
                     if args.dry_run:
                         if args.output_list:
-                            logger.info('Would prune:     %s' % format_archive(archive))
+                            list_logger.info('Would prune:     %s' % format_archive(archive))
                     else:
                         if args.output_list:
-                            logger.info('Pruning archive: %s' % format_archive(archive))
+                            list_logger.info('Pruning archive: %s' % format_archive(archive))
                         Archive(repository, key, manifest, archive.name, cache).delete(stats)
                 else:
                     if args.output_list:
-                        logger.info('Keeping archive: %s' % format_archive(archive))
+                        list_logger.info('Keeping archive: %s' % format_archive(archive))
             if to_delete and not args.dry_run:
                 manifest.write()
                 repository.commit(save_space=args.save_space)
@@ -840,7 +842,7 @@ class Archiver:
                 log_multi(DASHES,
                           stats.summary.format(label='Deleted data:', stats=stats),
                           str(cache),
-                          DASHES)
+                          DASHES, logger=logging.getLogger('borg.output.stats'))
         return self.exit_code
 
     def do_upgrade(self, args):
@@ -1299,6 +1301,9 @@ class Archiver:
                                help='only check last N archives (Default: all)')
         subparser.add_argument('-P', '--prefix', dest='prefix', type=str,
                                help='only consider archive names starting with this prefix')
+        subparser.add_argument('-p', '--progress', dest='progress',
+                               action='store_true', default=False,
+                               help="""show progress display while checking""")
 
         change_passphrase_epilog = textwrap.dedent("""
         The key files used for repository encryption are optionally passphrase
@@ -2065,12 +2070,27 @@ class Archiver:
         check_extension_modules()
         selftest(logger)
 
+    def _setup_implied_logging(self, args):
+        """ turn on INFO level logging for args that imply that they will produce output """
+        # map of option name to name of logger for that option
+        option_logger = {
+                'output_list': 'borg.output.list',
+                'show_version': 'borg.output.show-version',
+                'show_rc': 'borg.output.show-rc',
+                'stats': 'borg.output.stats',
+                'progress': 'borg.output.progress',
+                }
+        for option, logger_name in option_logger.items():
+            if args.get(option, False):
+                logging.getLogger(logger_name).setLevel('INFO')
+
     def run(self, args):
         os.umask(args.umask)  # early, before opening files
         self.lock_wait = args.lock_wait
         setup_logging(level=args.log_level, is_serve=args.func == self.do_serve)  # do not use loggers before this!
+        self._setup_implied_logging(vars(args))
         if args.show_version:
-            logger.info('borgbackup version %s' % __version__)
+            logging.getLogger('borg.output.show-version').info('borgbackup version %s' % __version__)
         self.prerun_checks(logger)
         if is_slow_msgpack():
             logger.warning("Using a pure-python msgpack! This will result in lower performance.")
@@ -2142,15 +2162,16 @@ def main():  # pragma: no cover
     if msg:
         logger.error(msg)
     if args.show_rc:
+        rc_logger = logging.getLogger('borg.output.show-rc')
         exit_msg = 'terminating with %s status, rc %d'
         if exit_code == EXIT_SUCCESS:
-            logger.info(exit_msg % ('success', exit_code))
+            rc_logger.info(exit_msg % ('success', exit_code))
         elif exit_code == EXIT_WARNING:
-            logger.warning(exit_msg % ('warning', exit_code))
+            rc_logger.warning(exit_msg % ('warning', exit_code))
         elif exit_code == EXIT_ERROR:
-            logger.error(exit_msg % ('error', exit_code))
+            rc_logger.error(exit_msg % ('error', exit_code))
         else:
-            logger.error(exit_msg % ('abnormal', exit_code or 666))
+            rc_logger.error(exit_msg % ('abnormal', exit_code or 666))
     sys.exit(exit_code)
 
 

borg/helpers.py

@@ -1037,7 +1037,7 @@ def yes(msg=None, false_msg=None, true_msg=None, default_msg=None,
 
 
 class ProgressIndicatorPercent:
-    def __init__(self, total, step=5, start=0, same_line=False, msg="%3.0f%%", file=None):
+    def __init__(self, total, step=5, start=0, same_line=False, msg="%3.0f%%"):
         """
         Percentage-based progress indicator
 
@@ -1046,17 +1046,33 @@ class ProgressIndicatorPercent:
         :param start: at which percent value to start
         :param same_line: if True, emit output always on same line
         :param msg: output message, must contain one %f placeholder for the percentage
-        :param file: output file, default: sys.stderr
         """
         self.counter = 0  # 0 .. (total-1)
         self.total = total
         self.trigger_at = start  # output next percentage value when reaching (at least) this
         self.step = step
-        if file is None:
-            file = sys.stderr
-        self.file = file
         self.msg = msg
         self.same_line = same_line
+        self.handler = None
+        self.logger = logging.getLogger('borg.output.progress')
+
+        # If there are no handlers, set one up explicitly because the
+        # terminator and propagation needs to be set.  If there are,
+        # they must have been set up by BORG_LOGGING_CONF: skip setup.
+        if not self.logger.handlers:
+            self.handler = logging.StreamHandler(stream=sys.stderr)
+            self.handler.setLevel(logging.INFO)
+            self.handler.terminator = '\r' if self.same_line else '\n'
+
+            self.logger.addHandler(self.handler)
+            if self.logger.level == logging.NOTSET:
+                self.logger.setLevel(logging.WARN)
+            self.logger.propagate = False
+
+    def __del__(self):
+        if self.handler is not None:
+            self.logger.removeHandler(self.handler)
+            self.handler.close()
 
     def progress(self, current=None):
         if current is not None:
@@ -1073,11 +1089,11 @@ class ProgressIndicatorPercent:
             return self.output(pct)
 
     def output(self, percent):
-        print(self.msg % percent, file=self.file, end='\r' if self.same_line else '\n', flush=True)
+        self.logger.info(self.msg % percent)
 
     def finish(self):
         if self.same_line:
-            print(" " * len(self.msg % 100.0), file=self.file, end='\r')
+            self.logger.info(" " * len(self.msg % 100.0))
 
 
 class ProgressIndicatorEndless:
@@ -1127,7 +1143,7 @@ def sysinfo():
     return '\n'.join(info)
 
 
-def log_multi(*msgs, level=logging.INFO):
+def log_multi(*msgs, level=logging.INFO, logger=logger):
     """
     log multiple lines of text, each line by a separate logging call for cosmetic reasons
 

borg/testsuite/archiver.py

@@ -3,6 +3,7 @@ import errno
 import os
 import inspect
 from io import StringIO
+import logging
 import random
 import stat
 import subprocess
@@ -297,9 +298,14 @@ class ArchiverTestCaseBase(BaseTestCase):
 class ArchiverTestCase(ArchiverTestCaseBase):
     def test_basic_functionality(self):
         have_root = self.create_test_files()
-        self.cmd('init', self.repository_location)
+        # fork required to test show-rc output
+        output = self.cmd('init', '--show-version', '--show-rc', self.repository_location, fork=True)
+        self.assert_in('borgbackup version', output)
+        self.assert_in('terminating with success status, rc 0', output)
         self.cmd('create', self.repository_location + '::test', 'input')
-        self.cmd('create', '--stats', self.repository_location + '::test.2', 'input')
+        output = self.cmd('create', '--stats', self.repository_location + '::test.2', 'input')
+        self.assert_in('Archive name: test.2', output)
+        self.assert_in('This archive: ', output)
         with changedir('output'):
             self.cmd('extract', self.repository_location + '::test')
         list_output = self.cmd('list', '--short', self.repository_location)
@@ -645,6 +651,31 @@ class ArchiverTestCase(ArchiverTestCaseBase):
             self.cmd("extract", self.repository_location + "::test", "fm:input/file1", "fm:*file33*", "input/file2")
         self.assert_equal(sorted(os.listdir("output/input")), ["file1", "file2", "file333"])
 
+    def test_extract_list_output(self):
+        self.cmd('init', self.repository_location)
+        self.create_regular_file('file', size=1024 * 80)
+
+        self.cmd('create', self.repository_location + '::test', 'input')
+
+        with changedir('output'):
+            output = self.cmd('extract', self.repository_location + '::test')
+        self.assert_not_in("input/file", output)
+        shutil.rmtree('output/input')
+
+        with changedir('output'):
+            output = self.cmd('extract', '--info', self.repository_location + '::test')
+        self.assert_not_in("input/file", output)
+        shutil.rmtree('output/input')
+
+        with changedir('output'):
+            output = self.cmd('extract', '--list', self.repository_location + '::test')
+        self.assert_in("input/file", output)
+        shutil.rmtree('output/input')
+
+        with changedir('output'):
+            output = self.cmd('extract', '--list', '--info', self.repository_location + '::test')
+        self.assert_in("input/file", output)
+
     def _create_test_caches(self):
         self.cmd('init', self.repository_location)
         self.create_regular_file('file1', size=1024 * 80)
@@ -857,7 +888,8 @@ class ArchiverTestCase(ArchiverTestCaseBase):
         self.cmd('extract', '--dry-run', self.repository_location + '::test.2')
         self.cmd('delete', self.repository_location + '::test')
         self.cmd('extract', '--dry-run', self.repository_location + '::test.2')
-        self.cmd('delete', '--stats', self.repository_location + '::test.2')
+        output = self.cmd('delete', '--stats', self.repository_location + '::test.2')
+        self.assert_in('Deleted data:', output)
         # Make sure all data except the manifest has been deleted
         with Repository(self.repository_path) as repository:
             self.assert_equal(len(repository), 1)
@@ -880,12 +912,16 @@ class ArchiverTestCase(ArchiverTestCaseBase):
         self.cmd('init', self.repository_location)
         self.create_src_archive('test')
         self.cmd('extract', '--dry-run', self.repository_location + '::test')
-        self.cmd('check', self.repository_location)
+        output = self.cmd('check', '--show-version', self.repository_location)
+        self.assert_in('borgbackup version', output)  # implied output even without --info given
+        self.assert_not_in('Starting repository check', output)  # --info not given for root logger
+
         name = sorted(os.listdir(os.path.join(self.tmpdir, 'repository', 'data', '0')), reverse=True)[0]
         with open(os.path.join(self.tmpdir, 'repository', 'data', '0', name), 'r+b') as fd:
             fd.seek(100)
             fd.write(b'XXXX')
-        self.cmd('check', self.repository_location, exit_code=1)
+        output = self.cmd('check', '--info', self.repository_location, exit_code=1)
+        self.assert_in('Starting repository check', output)  # --info given for root logger
 
     # we currently need to be able to create a lock directory inside the repo:
     @pytest.mark.xfail(reason="we need to be able to create the lock directory inside the repo")
@@ -933,11 +969,11 @@ 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', '-v', '--list', self.repository_location + '::test', 'input')
+        output = self.cmd('create', '--list', 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', '-v', '--list', self.repository_location + '::test1', 'input')
+        output = self.cmd('create', '--list', self.repository_location + '::test1', 'input')
         self.assert_in("U input/file1", output)
         # this is expected, although surprising, for why, see:
         # https://borgbackup.readthedocs.org/en/latest/faq.html#i-am-seeing-a-added-status-for-a-unchanged-file
@@ -951,11 +987,11 @@ 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', '-v', '--list', self.repository_location + '::test', 'input')
+        output = self.cmd('create', '--list', self.repository_location + '::test', 'input')
         self.assert_in("A input/file1", output)
         self.assert_in("A input/file2", output)
         # should find second file as excluded
-        output = self.cmd('create', '-v', '--list', self.repository_location + '::test1', 'input', '--exclude', '*/file2')
+        output = self.cmd('create', '--list', self.repository_location + '::test1', 'input', '--exclude', '*/file2')
         self.assert_in("U input/file1", output)
         self.assert_in("x input/file2", output)
 
@@ -972,15 +1008,15 @@ class ArchiverTestCase(ArchiverTestCaseBase):
         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', '--list', '--filter=U', self.repository_location + '::test1', 'input')
+        output = self.cmd('create', '--list', '--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')
+        output = self.cmd('create', '--list', '--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', '--list', '--filter=AM', self.repository_location + '::test3', 'input')
+        output = self.cmd('create', '--list', '--filter=AM', self.repository_location + '::test3', 'input')
         self.assert_in('file1', output)
 
     # def test_cmdline_compatibility(self):
@@ -998,7 +1034,8 @@ class ArchiverTestCase(ArchiverTestCaseBase):
         self.cmd('create', self.repository_location + '::test3.checkpoint', src_dir)
         self.cmd('create', self.repository_location + '::test3.checkpoint.1', src_dir)
         self.cmd('create', self.repository_location + '::test4.checkpoint', src_dir)
-        output = self.cmd('prune', '-v', '--list', '--dry-run', self.repository_location, '--keep-daily=2')
+        output = self.cmd('prune', '--list', '--dry-run', self.repository_location, '--keep-daily=2')
+        self.assert_in('Keeping archive: test2', output)
         self.assert_in('Would prune:     test1', output)
         # must keep the latest non-checkpoint archive:
         self.assert_in('Keeping archive: test2', output)
@@ -1032,9 +1069,10 @@ class ArchiverTestCase(ArchiverTestCaseBase):
         self.cmd('init', self.repository_location)
         self.cmd('create', self.repository_location + '::test1', src_dir)
         self.cmd('create', self.repository_location + '::test2', src_dir)
-        output = self.cmd('prune', '-v', '--list', '--dry-run', self.repository_location, '--keep-daily=2')
+        output = self.cmd('prune', '--list', '--stats', '--dry-run', self.repository_location, '--keep-daily=2')
         self.assert_in('Keeping archive: test2', output)
         self.assert_in('Would prune:     test1', output)
+        self.assert_in('Deleted data:', output)
         output = self.cmd('list', self.repository_location)
         self.assert_in('test1', output)
         self.assert_in('test2', output)
@@ -1049,7 +1087,7 @@ class ArchiverTestCase(ArchiverTestCaseBase):
         self.cmd('create', self.repository_location + '::foo-2015-08-12-20:00', src_dir)
         self.cmd('create', self.repository_location + '::bar-2015-08-12-10:00', src_dir)
         self.cmd('create', self.repository_location + '::bar-2015-08-12-20:00', src_dir)
-        output = self.cmd('prune', '-v', '--list', '--dry-run', self.repository_location, '--keep-daily=2', '--prefix=foo-')
+        output = self.cmd('prune', '--list', '--dry-run', self.repository_location, '--keep-daily=2', '--prefix=foo-')
         self.assert_in('Keeping archive: foo-2015-08-12-20:00', output)
         self.assert_in('Would prune:     foo-2015-08-12-10:00', output)
         output = self.cmd('list', self.repository_location)
@@ -1401,7 +1439,7 @@ class ArchiverTestCase(ArchiverTestCaseBase):
         if interrupt_early:
             process_files = 0
         with patch.object(ArchiveRecreater, 'process_item', self._recreate_interrupt_patch(process_files)):
-            self.cmd('recreate', '-sv', '--list', self.repository_location, 'input/dir2')
+            self.cmd('recreate', self.repository_location, 'input/dir2')
         assert 'test.recreate' in self.cmd('list', self.repository_location)
         if change_args:
             with patch.object(sys, 'argv', sys.argv + ['non-forking tests don\'t use sys.argv']):
@@ -1492,6 +1530,32 @@ class ArchiverTestCase(ArchiverTestCaseBase):
         cmd = 'python3', '-c', 'import os, sys; sys.exit(42 if os.path.exists("%s") else 23)' % lock_path
         self.cmd('with-lock', self.repository_location, *cmd, fork=True, exit_code=42)
 
+    def test_recreate_list_output(self):
+        self.cmd('init', self.repository_location)
+        self.create_regular_file('file1', size=0)
+        self.create_regular_file('file2', size=0)
+        self.create_regular_file('file3', size=0)
+        self.create_regular_file('file4', size=0)
+        self.create_regular_file('file5', size=0)
+
+        self.cmd('create', self.repository_location + '::test', 'input')
+
+        output = self.cmd('recreate', '--list', '--info', self.repository_location + '::test', '-e', 'input/file2')
+        self.assert_in("input/file1", output)
+        self.assert_in("x input/file2", output)
+
+        output = self.cmd('recreate', '--list', self.repository_location + '::test', '-e', 'input/file3')
+        self.assert_in("input/file1", output)
+        self.assert_in("x input/file3", output)
+
+        output = self.cmd('recreate', self.repository_location + '::test', '-e', 'input/file4')
+        self.assert_not_in("input/file1", output)
+        self.assert_not_in("x input/file4", output)
+
+        output = self.cmd('recreate', '--info', self.repository_location + '::test', '-e', 'input/file5')
+        self.assert_not_in("input/file1", output)
+        self.assert_not_in("x input/file5", output)
+
 
 @unittest.skipUnless('binary' in BORG_EXES, 'no borg.exe available')
 class ArchiverTestCaseBinary(ArchiverTestCase):
@@ -1532,12 +1596,16 @@ class ArchiverCheckTestCase(ArchiverTestCaseBase):
         return archive, repository
 
     def test_check_usage(self):
-        output = self.cmd('check', '-v', self.repository_location, exit_code=0)
+        output = self.cmd('check', '-v', '--progress', self.repository_location, exit_code=0)
         self.assert_in('Starting repository check', output)
         self.assert_in('Starting archive consistency check', output)
+        self.assert_in('Checking segments', output)
+        # reset logging to new process default to avoid need for fork=True on next check
+        logging.getLogger('borg.output.progress').setLevel(logging.NOTSET)
         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)
+        self.assert_not_in('Checking segments', output)
         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)

borg/testsuite/helpers.py

@@ -1,4 +1,6 @@
 import hashlib
+import io
+import logging
 from time import mktime, strptime
 from datetime import datetime, timezone, timedelta
 from io import StringIO
@@ -826,7 +828,7 @@ def test_yes_output(capfd):
 
 
 def test_progress_percentage_multiline(capfd):
-    pi = ProgressIndicatorPercent(1000, step=5, start=0, same_line=False, msg="%3.0f%%", file=sys.stderr)
+    pi = ProgressIndicatorPercent(1000, step=5, start=0, same_line=False, msg="%3.0f%%")
     pi.show(0)
     out, err = capfd.readouterr()
     assert err == '  0%\n'
@@ -842,13 +844,14 @@ def test_progress_percentage_multiline(capfd):
 
 
 def test_progress_percentage_sameline(capfd):
-    pi = ProgressIndicatorPercent(1000, step=5, start=0, same_line=True, msg="%3.0f%%", file=sys.stderr)
+    pi = ProgressIndicatorPercent(1000, step=5, start=0, same_line=True, msg="%3.0f%%")
     pi.show(0)
     out, err = capfd.readouterr()
     assert err == '  0%\r'
     pi.show(420)
+    pi.show(680)
     out, err = capfd.readouterr()
-    assert err == ' 42%\r'
+    assert err == ' 42%\r 68%\r'
     pi.show(1000)
     out, err = capfd.readouterr()
     assert err == '100%\r'
@@ -858,7 +861,7 @@ def test_progress_percentage_sameline(capfd):
 
 
 def test_progress_percentage_step(capfd):
-    pi = ProgressIndicatorPercent(100, step=2, start=0, same_line=False, msg="%3.0f%%", file=sys.stderr)
+    pi = ProgressIndicatorPercent(100, step=2, start=0, same_line=False, msg="%3.0f%%")
     pi.show()
     out, err = capfd.readouterr()
     assert err == '  0%\n'
@@ -870,6 +873,21 @@ def test_progress_percentage_step(capfd):
     assert err == '  2%\n'
 
 
+def test_progress_percentage_quiet(capfd):
+    logging.getLogger('borg.output.progress').setLevel(logging.WARN)
+
+    pi = ProgressIndicatorPercent(1000, step=5, start=0, same_line=False, msg="%3.0f%%")
+    pi.show(0)
+    out, err = capfd.readouterr()
+    assert err == ''
+    pi.show(1000)
+    out, err = capfd.readouterr()
+    assert err == ''
+    pi.finish()
+    out, err = capfd.readouterr()
+    assert err == ''
+
+
 def test_progress_endless(capfd):
     pi = ProgressIndicatorEndless(step=1, file=sys.stderr)
     pi.show()

docs/changes.rst

@@ -6,6 +6,10 @@ Version 1.1.0 (not released yet)
 
 New features:
 
+- borg check: will not produce the "Checking segments" output unless
+  new --progress option is passed, #824.
+- options that imply output (--show-rc, --show-version, --list, --stats, 
+  --progress) don't need -v/--info to have that output displayed, #865
 - borg recreate: re-create existing archives, #787 #686 #630 #70, also see
   #757, #770.
 
@@ -34,7 +38,7 @@ New features:
 - borg comment: add archive comments, #842
 - provide "borgfs" wrapper for borg mount, enables usage via fstab, #743
 - create: add 'x' status for excluded paths, #814
-- --show-version: shows/logs the borg version (use -v), #725
+- --show-version: shows/logs the borg version, #725
 - borg list/prune/delete: also output archive id, #731
 
 Bug fixes:

docs/development.rst

@@ -27,8 +27,10 @@ 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`` or ``--list``.
+To control the amount and kinds of messages output emitted at info level, use
+flags like ``--stats`` or ``--list``, then create a topic logger for messages
+controlled by that flag.  See ``_setup_implied_logging()`` in
+``borg/archiver.py`` for the entry point to topic logging.
 
 Building a development environment
 ----------------------------------

docs/quickstart.rst

@@ -46,7 +46,7 @@ A step by step example
 
 3. The next day create a new archive called *Tuesday*::
 
-    $ borg create -v --stats /path/to/repo::Tuesday ~/src ~/Documents
+    $ borg create --stats /path/to/repo::Tuesday ~/src ~/Documents
 
    This backup will be a lot quicker and a lot smaller since only new never
    before seen data is stored. The ``--stats`` option causes |project_name| to
@@ -93,9 +93,10 @@ A step by step example
 
 .. Note::
     Borg is quiet by default (it works on WARNING log level).
-    Add the ``-v`` (or ``--verbose`` or ``--info``) option to adjust the log
-    level to INFO and also use options like ``--progress`` or ``--list`` to
-    get progress reporting during command execution.
+    You can use options like ``--progress`` or ``--list`` to get specific
+    reports during command execution.  You can also add the ``-v`` (or
+    ``--verbose`` or ``--info``) option to adjust the log level to INFO to
+    get other informational messages.
 
 Automating backups
 ------------------
@@ -114,7 +115,7 @@ certain number of old archives::
     export BORG_PASSPHRASE=mysecret
 
     # Backup most important stuff:
-    borg create -v --stats -C lz4 ::`hostname`-`date +%Y-%m-%d` \
+    borg create --stats -C lz4 ::`hostname`-`date +%Y-%m-%d` \
         /etc                                                    \
         /home                                                   \
         /var                                                    \

docs/usage.rst

@@ -16,7 +16,8 @@ Type of log output
 
 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, errors and critical messages.
+warnings, errors and critical messages, unless output has been requested
+by supplying an option that implies output (eg, --list or --progress).
 
 Log levels: DEBUG < INFO < WARNING < ERROR < CRITICAL
 
@@ -41,10 +42,6 @@ give different output on different log levels - it's just a possibility.
 .. warning:: Options --critical and --error are provided for completeness,
              their usage is not recommended as you might miss important information.
 
-.. warning:: While some options (like ``--stats`` or ``--list``) will emit more
-             informational messages, you have to use INFO (or lower) log level to make
-             them show up in log output. Use ``-v`` or a logging configuration.
-
 Return codes
 ~~~~~~~~~~~~
 
@@ -245,8 +242,8 @@ Examples
     # Backup ~/Documents into an archive named "my-documents"
     $ borg create /path/to/repo::my-documents ~/Documents
 
-    # same, but verbosely list all files as we process them
-    $ borg create -v --list /path/to/repo::my-documents ~/Documents
+    # same, but list all files as we process them
+    $ borg create --list /path/to/repo::my-documents ~/Documents
 
     # Backup ~/Documents and ~/src but exclude pyc files
     $ borg create /path/to/repo::my-files \
@@ -301,7 +298,7 @@ Examples
     $ borg extract /path/to/repo::my-files
 
     # Extract entire archive and list files while processing
-    $ borg extract -v --list /path/to/repo::my-files
+    $ borg extract --list /path/to/repo::my-files
 
     # Verify whether an archive could be successfully extracted, but do not write files to disk
     $ borg extract --dry-run /path/to/repo::my-files
@@ -480,7 +477,7 @@ Examples
     Username: root
     Time (start): Mon, 2016-02-15 19:36:29
     Time (end):   Mon, 2016-02-15 19:39:26
-    Command line: /usr/local/bin/borg create -v --list -C zlib,6 /path/to/repo::root-2016-02-15 / --one-file-system
+    Command line: /usr/local/bin/borg create --list -C zlib,6 /path/to/repo::root-2016-02-15 / --one-file-system
     Number of files: 38100
 
                            Original size      Compressed size    Deduplicated size
@@ -655,7 +652,7 @@ Here are misc. notes about topics that are maybe not covered in enough detail in
 Item flags
 ~~~~~~~~~~
 
-``borg create -v --list`` outputs a verbose list of all files, directories and other
+``borg create --list`` outputs a list of all files, directories and other
 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.