Merge pull request #303 from anarcat/verbosity

Verbosity

borg/archive.py

@@ -201,14 +201,12 @@ class Archive:
         return format_timedelta(self.end-self.start)
 
     def __str__(self):
-        buf = '''Archive name: {0.name}
+        return '''Archive name: {0.name}
 Archive fingerprint: {0.fpr}
 Start time: {0.start:%c}
 End time: {0.end:%c}
 Duration: {0.duration}
-Number of files: {0.stats.nfiles}
-{0.cache}'''.format(self)
-        return buf
+Number of files: {0.stats.nfiles}'''.format(self)
 
     def __repr__(self):
         return 'Archive(%r)' % self.name
@@ -503,7 +501,10 @@ Number of files: {0.stats.nfiles}
             else:
                 self.hard_links[st.st_ino, st.st_dev] = safe_path
         path_hash = self.key.id_hash(os.path.join(self.cwd, path).encode('utf-8', 'surrogateescape'))
+        first_run = not cache.files
         ids = cache.file_known_and_unchanged(path_hash, st)
+        if first_run:
+            logger.info('processing files')
         chunks = None
         if ids is not None:
             # Make sure all ids are available

borg/archiver.py

@@ -56,6 +56,9 @@ class Archiver:
         msg = args and msg % args or msg
         logger.info(msg)
 
+    def print_status(self, status, path):
+        logger.info("%1s %s", status, remove_surrogates(path))
+
     def do_serve(self, args):
         """Start in server mode. This command is usually not used manually.
         """
@@ -143,7 +146,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""")
                         self.print_error('%s: %s', path, e)
                 else:
                     status = '-'
-                self.print_verbose("%1s %s", status, path)
+                self.print_status(status, path)
                 continue
             path = os.path.normpath(path)
             if args.one_file_system:
@@ -164,7 +167,9 @@ Type "Yes I am sure" if you understand this and want to continue.\n""")
                 archive.end = datetime.now()
                 print('-' * 78)
                 print(str(archive))
-                print(archive.stats.print_('This archive:', cache))
+                print()
+                print(str(archive.stats))
+                print(str(cache))
                 print('-' * 78)
         return self.exit_code
 
@@ -238,7 +243,7 @@ Type "Yes I am sure" if you understand this and want to continue.\n""")
                 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_status(status, path)
 
     def do_extract(self, args):
         """Extract archive contents"""
@@ -310,7 +315,8 @@ Type "Yes I am sure" if you understand this and want to continue.\n""")
             repository.commit()
             cache.commit()
             if args.stats:
-                logger.info(stats.print_('Deleted data:', cache))
+                logger.info(stats.summary.format(label='Deleted data:', stats=stats))
+                logger.info(str(cache))
         else:
             if not args.cache_only:
                 print("You requested to completely DELETE the repository *including* all archives it contains:", file=sys.stderr)
@@ -411,7 +417,9 @@ Type "Yes I am sure" if you understand this and want to continue.\n""")
         print('Time: %s' % to_localtime(archive.ts).strftime('%c'))
         print('Command line:', remove_surrogates(' '.join(archive.metadata[b'cmdline'])))
         print('Number of files: %d' % stats.nfiles)
-        print(stats.print_('This archive:', cache))
+        print()
+        print(str(stats))
+        print(str(cache))
         return self.exit_code
 
     def do_prune(self, args):
@@ -456,7 +464,8 @@ Type "Yes I am sure" if you understand this and want to continue.\n""")
             repository.commit()
             cache.commit()
         if args.stats:
-            logger.info(stats.print_('Deleted data:', cache))
+            logger.info(stats.summary.format(label='Deleted data:', stats=stats))
+            logger.info(str(cache))
         return self.exit_code
 
     def do_upgrade(self, args):
@@ -670,9 +679,11 @@ Type "Yes I am sure" if you understand this and want to continue.\n""")
         subparser.add_argument('-s', '--stats', dest='stats',
                                action='store_true', default=False,
                                help='print statistics for the created archive')
-        subparser.add_argument('-p', '--progress', dest='progress',
-                               action='store_true', default=False,
-                               help='print progress while creating the archive')
+        subparser.add_argument('-p', '--progress', dest='progress', const=not sys.stderr.isatty(),
+                               action='store_const', default=sys.stdin.isatty(),
+                               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('-e', '--exclude', dest='excludes',
                                type=ExcludePattern, action='append',
                                metavar="PATTERN", help='exclude paths matching PATTERN')

borg/cache.py

@@ -48,6 +48,7 @@ class Cache:
         self.manifest = manifest
         self.path = path or os.path.join(get_cache_dir(), hexlify(repository.id).decode('ascii'))
         self.do_files = do_files
+        logger.info('initializing cache')
         # Warn user before sending data to a never seen before unencrypted repository
         if not os.path.exists(self.path):
             if warn_if_unencrypted and isinstance(key, PlaintextKey):
@@ -69,6 +70,7 @@ class Cache:
             # Make sure an encrypted repository has not been swapped for an unencrypted repository
             if self.key_type is not None and self.key_type != str(key.TYPE):
                 raise self.EncryptionMethodMismatch()
+            logger.info('synchronizing cache')
             self.sync()
             self.commit()
 
@@ -76,20 +78,20 @@ class Cache:
         self.close()
 
     def __str__(self):
-        return format(self, """\
+        fmt = """\
 All archives:   {0.total_size:>20s} {0.total_csize:>20s} {0.unique_csize:>20s}
 
                        Unique chunks         Total chunks
-Chunk index:    {0.total_unique_chunks:20d} {0.total_chunks:20d}""")
+Chunk index:    {0.total_unique_chunks:20d} {0.total_chunks:20d}"""
+        return fmt.format(self.format_tuple())
 
-    def __format__(self, format_spec):
+    def format_tuple(self):
         # XXX: this should really be moved down to `hashindex.pyx`
         Summary = namedtuple('Summary', ['total_size', 'total_csize', 'unique_size', 'unique_csize', 'total_unique_chunks', 'total_chunks'])
         stats = Summary(*self.chunks.summarize())._asdict()
         for field in ['total_size', 'total_csize', 'unique_csize']:
             stats[field] = format_file_size(stats[field])
-        stats = Summary(**stats)
-        return format_spec.format(stats)
+        return Summary(**stats)
 
     def _confirm(self, message, env_var_override=None):
         print(message, file=sys.stderr)
@@ -163,6 +165,7 @@ Chunk index:    {0.total_unique_chunks:20d} {0.total_chunks:20d}""")
     def _read_files(self):
         self.files = {}
         self._newest_mtime = 0
+        logger.info('reading files cache')
         with open(os.path.join(self.path, 'files'), 'rb') as fd:
             u = msgpack.Unpacker(use_list=True)
             while True:

borg/helpers.py

@@ -8,6 +8,12 @@ import grp
 import os
 import pwd
 import re
+try:
+    from shutil import get_terminal_size
+except ImportError:
+    def get_terminal_size(fallback=(80, 24)):
+        TerminalSize = namedtuple('TerminalSize', ['columns', 'lines'])
+        return TerminalSize(int(os.environ.get('COLUMNS', fallback[0])), int(os.environ.get('LINES', fallback[1])))
 import sys
 import time
 import unicodedata
@@ -156,33 +162,40 @@ class Statistics:
         if unique:
             self.usize += csize
 
-    def print_(self, label, cache):
-        buf = str(self) % label
-        buf += "\n"
-        buf += str(cache)
-        return buf
-
-    def __str__(self):
-        return format(self, """\
+    summary = """\
                        Original size      Compressed size    Deduplicated size
-%-15s {0.osize:>20s} {0.csize:>20s} {0.usize:>20s}""")
+{label:15} {stats.osize_fmt:>20s} {stats.csize_fmt:>20s} {stats.usize_fmt:>20s}"""
+    def __str__(self):
+        return self.summary.format(stats=self, label='This archive:')
 
-    def __format__(self, format_spec):
-        fields = ['osize', 'csize', 'usize']
-        FormattedStats = namedtuple('FormattedStats', fields)
-        return format_spec.format(FormattedStats(*map(format_file_size, [ getattr(self, x) for x in fields ])))
+    def __repr__(self):
+        return "<{cls} object at {hash:#x} ({self.osize}, {self.csize}, {self.usize})>".format(cls=type(self).__name__, hash=id(self), self=self)
 
-    def show_progress(self, item=None, final=False):
+    @property
+    def osize_fmt(self):
+        return format_file_size(self.osize)
+
+    @property
+    def usize_fmt(self):
+        return format_file_size(self.usize)
+
+    @property
+    def csize_fmt(self):
+        return format_file_size(self.csize)
+
+    def show_progress(self, item=None, final=False, stream=None):
+        columns, lines = get_terminal_size()
         if not final:
+            msg = '{0.osize_fmt} O {0.csize_fmt} C {0.usize_fmt} D {0.nfiles} N '.format(self)
             path = remove_surrogates(item[b'path']) if item else ''
-            if len(path) > 43:
-                path = '%s...%s' % (path[:20], path[-20:])
-            msg = '%9s O %9s C %9s D %-43s' % (
-                format_file_size(self.osize), format_file_size(self.csize), format_file_size(self.usize), path)
+            space = columns - len(msg)
+            if space < len('...') + len(path):
+                path = '%s...%s' % (path[:(space//2)-len('...')], path[-space//2:])
+            msg += "{0:<{space}}".format(path, space=space)
         else:
-            msg = ' ' * 79
-        print(msg, file=sys.stderr, end='\r')
-        sys.stderr.flush()
+            msg = ' ' * columns
+        print(msg, file=stream or sys.stderr, end="\r")
+        (stream or sys.stderr).flush()
 
 
 def get_keys_dir():

borg/testsuite/helpers.py

@@ -1,6 +1,7 @@
 import hashlib
 from time import mktime, strptime
 from datetime import datetime, timezone, timedelta
+from io import StringIO
 import os
 
 import pytest
@@ -8,7 +9,7 @@ import sys
 import msgpack
 
 from ..helpers import adjust_patterns, exclude_path, Location, format_timedelta, IncludePattern, ExcludePattern, make_path_safe, \
-    prune_within, prune_split, get_cache_dir, \
+    prune_within, prune_split, get_cache_dir, Statistics, \
     StableDict, int_to_bigint, bigint_to_int, parse_timestamp, CompressionSpec, ChunkerParams
 from . import BaseTestCase
 
@@ -399,3 +400,46 @@ def test_get_cache_dir():
     # reset old env
     if old_env is not None:
         os.environ['BORG_CACHE_DIR'] = old_env
+
+@pytest.fixture()
+def stats():
+    stats = Statistics()
+    stats.update(20, 10, unique=True)
+    return stats
+
+def test_stats_basic(stats):
+    assert stats.osize == 20
+    assert stats.csize == stats.usize == 10
+    stats.update(20, 10, unique=False)
+    assert stats.osize == 40
+    assert stats.csize == 20
+    assert stats.usize == 10
+
+def tests_stats_progress(stats, columns=80):
+    os.environ['COLUMNS'] = str(columns)
+    out = StringIO()
+    stats.show_progress(stream=out)
+    s = '20 B O 10 B C 10 B D 0 N '
+    buf = ' ' * (columns - len(s))
+    assert out.getvalue() == s + buf + "\r"
+
+    out = StringIO()
+    stats.update(10**3, 0, unique=False)
+    stats.show_progress(item={b'path': 'foo'}, final=False, stream=out)
+    s = '1.02 kB O 10 B C 10 B D 0 N foo'
+    buf = ' ' * (columns - len(s))
+    assert out.getvalue() == s + buf + "\r"
+    out = StringIO()
+    stats.show_progress(item={b'path': 'foo'*40}, final=False, stream=out)
+    s = '1.02 kB O 10 B C 10 B D 0 N foofoofoofoofoofoofoofo...oofoofoofoofoofoofoofoofoo'
+    buf = ' ' * (columns - len(s))
+    assert out.getvalue() == s + buf + "\r"
+
+def test_stats_format(stats):
+    assert str(stats) == """\
+                       Original size      Compressed size    Deduplicated size
+This archive:                   20 B                 10 B                 10 B"""
+    s = "{0.osize_fmt}".format(stats)
+    assert s == "20 B"
+    # kind of redundant, but id is variable so we can't match reliably
+    assert repr(stats) == '<Statistics object at {:#x} (20, 10, 10)>'.format(id(stats))