Merge pull request #455 from ThomasWaldmann/add-progress-indication

Add progress indication, fixes #394

borg/archiver.py

@@ -107,10 +107,7 @@ class Archiver:
                        env_var_override='BORG_CHECK_I_KNOW_WHAT_I_AM_DOING', truish=('YES', )):
                 return EXIT_ERROR
         if not args.archives_only:
-            logger.info('Starting repository check...')
-            if repository.check(repair=args.repair):
-                logger.info('Repository check complete, no problems found.')
-            else:
+            if not repository.check(repair=args.repair):
                 return EXIT_WARNING
         if not args.repo_only and not ArchiveChecker().check(
                 repository, repair=args.repair, archive=args.repository.archive, last=args.last):

borg/helpers.py

@@ -890,6 +890,82 @@ def yes(msg=None, retry_msg=None, false_msg=None, true_msg=None,
             ofile.flush()
 
 
+class ProgressIndicatorPercent:
+    def __init__(self, total, step=5, start=0, same_line=False, msg="%3.0f%%", file=sys.stderr):
+        """
+        Percentage-based progress indicator
+
+        :param total: total amount of items
+        :param step: step size in percent
+        :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
+        self.file = file
+        self.msg = msg
+        self.same_line = same_line
+
+    def progress(self, current=None):
+        if current is not None:
+            self.counter = current
+        pct = self.counter * 100 / self.total
+        self.counter += 1
+        if pct >= self.trigger_at:
+            self.trigger_at += self.step
+            return pct
+
+    def show(self, current=None):
+        pct = self.progress(current)
+        if pct is not None:
+            return self.output(pct)
+
+    def output(self, percent):
+        print(self.msg % percent, file=self.file, end='\r' if self.same_line else '\n')
+
+    def finish(self):
+        if self.same_line:
+            print(" " * len(self.msg % 100.0), file=self.file, end='\r')
+
+
+
+class ProgressIndicatorEndless:
+    def __init__(self, step=10, file=sys.stderr):
+        """
+        Progress indicator (long row of dots)
+
+        :param step: every Nth call, call the func
+        :param file: output file, default: sys.stderr
+        """
+        self.counter = 0  # call counter
+        self.triggered = 0  # increases 1 per trigger event
+        self.step = step  # trigger every <step> calls
+        self.file = file
+
+    def progress(self):
+        self.counter += 1
+        trigger = self.counter % self.step == 0
+        if trigger:
+            self.triggered += 1
+        return trigger
+
+    def show(self):
+        trigger = self.progress()
+        if trigger:
+            return self.output(self.triggered)
+
+    def output(self, triggered):
+        print('.', end='', file=self.file)  # python 3.3 gives us flush=True
+        self.file.flush()
+
+    def finish(self):
+        print(file=self.file)
+
+
 def sysinfo():
     info = []
     info.append('Platform: %s' % (' '.join(platform.uname()), ))

borg/repository.py

@@ -10,7 +10,8 @@ import shutil
 import struct
 from zlib import crc32
 
-from .helpers import Error, ErrorWithTraceback, IntegrityError, read_msgpack, write_msgpack, unhexlify
+from .helpers import Error, ErrorWithTraceback, IntegrityError, read_msgpack, write_msgpack, \
+                     unhexlify, ProgressIndicatorPercent
 from .hashindex import NSIndex
 from .locking import UpgradableLock, LockError, LockErrorT
 from .lrucache import LRUCache
@@ -243,13 +244,17 @@ class Repository:
     def replay_segments(self, index_transaction_id, segments_transaction_id):
         self.prepare_txn(index_transaction_id, do_cleanup=False)
         try:
-            for segment, filename in self.io.segment_iterator():
+            segment_count = sum(1 for _ in self.io.segment_iterator())
+            pi = ProgressIndicatorPercent(total=segment_count, msg="Replaying segments %3.0f%%", same_line=True)
+            for i, (segment, filename) in enumerate(self.io.segment_iterator()):
+                pi.show(i)
                 if index_transaction_id is not None and segment <= index_transaction_id:
                     continue
                 if segment > segments_transaction_id:
                     break
                 objects = self.io.iter_objects(segment)
                 self._update_index(segment, objects)
+            pi.finish()
             self.write_index()
         finally:
             self.rollback()
@@ -299,6 +304,7 @@ class Repository:
             error_found = True
             logger.error(msg)
 
+        logger.info('Starting repository check')
         assert not self._active_txn
         try:
             transaction_id = self.get_transaction_id()
@@ -314,7 +320,10 @@ class Repository:
             self.io.cleanup(transaction_id)
         segments_transaction_id = self.io.get_segments_transaction_id()
         self.prepare_txn(None)  # self.index, self.compact, self.segments all empty now!
-        for segment, filename in self.io.segment_iterator():
+        segment_count = sum(1 for _ in self.io.segment_iterator())
+        pi = ProgressIndicatorPercent(total=segment_count, msg="Checking segments %3.0f%%", same_line=True)
+        for i, (segment, filename) in enumerate(self.io.segment_iterator()):
+            pi.show(i)
             if segment > transaction_id:
                 continue
             try:
@@ -326,6 +335,7 @@ class Repository:
                     self.io.recover_segment(segment, filename)
                     objects = list(self.io.iter_objects(segment))
             self._update_index(segment, objects, report_error)
+        pi.finish()
         # self.index, self.segments, self.compact now reflect the state of the segment files up to <transaction_id>
         # We might need to add a commit tag if no committed segment is found
         if repair and segments_transaction_id is None:
@@ -345,6 +355,13 @@ class Repository:
             self.compact_segments()
             self.write_index()
         self.rollback()
+        if error_found:
+            if repair:
+                logger.info('Completed repository check, errors found and repaired.')
+            else:
+                logger.info('Completed repository check, errors found.')
+        else:
+            logger.info('Completed repository check, no problems found.')
         return not error_found or repair
 
     def rollback(self):

borg/testsuite/helpers.py

@@ -11,7 +11,8 @@ import msgpack.fallback
 
 from ..helpers import adjust_patterns, exclude_path, Location, format_file_size, format_timedelta, IncludePattern, ExcludePattern, make_path_safe, \
     prune_within, prune_split, get_cache_dir, Statistics, is_slow_msgpack, yes, \
-    StableDict, int_to_bigint, bigint_to_int, parse_timestamp, CompressionSpec, ChunkerParams
+    StableDict, int_to_bigint, bigint_to_int, parse_timestamp, CompressionSpec, ChunkerParams, \
+    ProgressIndicatorPercent, ProgressIndicatorEndless
 from . import BaseTestCase, environment_variable, FakeInputs
 
 
@@ -566,3 +567,77 @@ def test_yes_output(capfd):
     assert 'intro-msg' in err
     assert 'retry-msg' not in err
     assert 'false-msg' in err
+
+
+def test_progress_percentage_multiline(capfd):
+    pi = ProgressIndicatorPercent(1000, step=5, start=0, same_line=False, msg="%3.0f%%", file=sys.stderr)
+    pi.show(0)
+    out, err = capfd.readouterr()
+    assert err == '  0%\n'
+    pi.show(420)
+    out, err = capfd.readouterr()
+    assert err == ' 42%\n'
+    pi.show(1000)
+    out, err = capfd.readouterr()
+    assert err == '100%\n'
+    pi.finish()
+    out, err = capfd.readouterr()
+    assert err == ''
+
+
+def test_progress_percentage_sameline(capfd):
+    pi = ProgressIndicatorPercent(1000, step=5, start=0, same_line=True, msg="%3.0f%%", file=sys.stderr)
+    pi.show(0)
+    out, err = capfd.readouterr()
+    assert err == '  0%\r'
+    pi.show(420)
+    out, err = capfd.readouterr()
+    assert err == ' 42%\r'
+    pi.show(1000)
+    out, err = capfd.readouterr()
+    assert err == '100%\r'
+    pi.finish()
+    out, err = capfd.readouterr()
+    assert err == ' ' * 4 + '\r'
+
+
+def test_progress_percentage_step(capfd):
+    pi = ProgressIndicatorPercent(100, step=2, start=0, same_line=False, msg="%3.0f%%", file=sys.stderr)
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == '  0%\n'
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == ''  # no output at 1% as we have step == 2
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == '  2%\n'
+
+
+def test_progress_endless(capfd):
+    pi = ProgressIndicatorEndless(step=1, file=sys.stderr)
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == '.'
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == '.'
+    pi.finish()
+    out, err = capfd.readouterr()
+    assert err == '\n'
+
+
+def test_progress_endless_step(capfd):
+    pi = ProgressIndicatorEndless(step=2, file=sys.stderr)
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == ''  # no output here as we have step == 2
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == '.'
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == ''  # no output here as we have step == 2
+    pi.show()
+    out, err = capfd.readouterr()
+    assert err == '.'

borg/upgrader.py

@@ -7,7 +7,7 @@ import shutil
 import sys
 import time
 
-from .helpers import get_keys_dir, get_cache_dir
+from .helpers import get_keys_dir, get_cache_dir, ProgressIndicatorPercent
 from .locking import UpgradableLock
 from .repository import Repository, MAGIC
 from .key import KeyfileKey, KeyfileNotFoundError
@@ -65,17 +65,15 @@ class AtticRepositoryUpgrader(Repository):
         luckily the magic string length didn't change so we can just
         replace the 8 first bytes of all regular files in there."""
         logger.info("converting %d segments..." % len(segments))
-        i = 0
-        for filename in segments:
-            i += 1
-            print("\rconverting segment %d/%d, %.2f%% done (%s)"
-                  % (i, len(segments), 100*float(i)/len(segments), filename),
-                  end='', file=sys.stderr)
+        segment_count = len(segments)
+        pi = ProgressIndicatorPercent(total=segment_count, msg="Converting segments %3.0f%%", same_line=True)
+        for i, filename in enumerate(segments):
+            pi.show(i)
             if dryrun:
                 time.sleep(0.001)
             else:
                 AtticRepositoryUpgrader.header_replace(filename, ATTIC_MAGIC, MAGIC, inplace=inplace)
-        print(file=sys.stderr)
+        pi.finish()
 
     @staticmethod
     def header_replace(filename, old_magic, new_magic, inplace=True):