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

@@ -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)
 
 

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():

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

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