Repository: borgbackup/borg

Issue:
Borg 1.1.x failing to handle exceptions for servers < 1.0.7
When `borg list server:repo` is run on version 1.0.11:

```
Remote: Borg 0.29.0: exception in RPC call:
Remote: Traceback (most recent call last):
Remote:   File "/usr/home/username/borgbackup-0.29.0/borg/remote.py", line 96, in serve
Remote: TypeError: open() takes from 2 to 5 positional arguments but 7 were given
Remote: Platform: FreeBSD servername.net 10.3-RELEASE FreeBSD 10.3-RELEASE #0: Wed Aug 30 20:40:07 CEST 2017     root@servername.net:/usr/src/sys/amd64/compile/servername_10.3 amd64
Remote: Python: CPython 3.4.3
Remote: 
Please note:
If you see a TypeError complaining about the number of positional arguments
given to open(), you can ignore it if it comes from a borg version < 1.0.7.
This TypeError is a cosmetic side effect of the compatibility code borg
clients >= 1.0.7 have to support older borg servers.
This problem will go away as soon as the server has been upgraded to 1.0.7+.
backup-2017-10-21T20:49:41.602262   Sat, 2017-10-21 20:49:49
backup-2017-10-23T10:44:59.177504   Mon, 2017-10-23 10:45:06
```

The same command run on version 1.1.1

```
Remote: Borg 0.29.0: exception in RPC call:
Remote: Traceback (most recent call last):
Remote:   File "/usr/home/username/borgbackup-0.29.0/borg/remote.py", line 96, in serve
Remote: TypeError: open() takes from 2 to 5 positional arguments but 7 were given
Remote: Platform: FreeBSD servername.net 10.3-RELEASE FreeBSD 10.3-RELEASE #0: Wed Aug 30 20:40:07 CEST 2017     root@servername.net:/usr/src/sys/amd64/compile/servername_10.3 amd64
Remote: Python: CPython 3.4.3
Remote: 
Please note:
If you see a TypeError complaining about the number of positional arguments
given to open(), you can ignore it if it comes from a borg version < 1.0.7.
This TypeError is a cosmetic side effect of the compatibility code borg
clients >= 1.0.7 have to support older borg servers.
This problem will go away as soon as the server has been upgraded to 1.0.7+.
Local Exception
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 591, in __init__
    do_open()
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 584, in do_open
    lock=lock, exclusive=exclusive, append_only=append_only)
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 476, in do_rpc
    return self.call(f.__name__, named, **extra)
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 707, in call
    for resp in self.call_many(cmd, [args], **kw):
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 773, in call_many
    handle_error(unpacked)
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 757, in handle_error
    raise self.RPCError(unpacked)
borg.remote.RemoteRepository.RPCError: {b'i': 2, b'exception_class': b'TypeError'}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/borg/archiver.py", line 4049, in main
    exit_code = archiver.run(args)
  File "/usr/lib/python3.6/site-packages/borg/archiver.py", line 3977, in run
    return set_ec(func(args))
  File "/usr/lib/python3.6/site-packages/borg/archiver.py", line 130, in wrapper
    lock_wait=self.lock_wait, lock=lock, append_only=append_only, args=args)
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 608, in __init__
    do_open()
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 584, in do_open
    lock=lock, exclusive=exclusive, append_only=append_only)
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 476, in do_rpc
    return self.call(f.__name__, named, **extra)
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 707, in call
    for resp in self.call_many(cmd, [args], **kw):
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 867, in call_many
    self.to_send = msgpack.packb((1, self.msgid, cmd, self.named_to_positional(cmd, args)))
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 704, in named_to_positional
    return [kwargs[name] for name in compatMap[method]]
  File "/usr/lib/python3.6/site-packages/borg/remote.py", line 704, in <listcomp>
    return [kwargs[name] for name in compatMap[method]]
KeyError: ('path', 'create', 'lock_wait', 'lock')

Platform: Linux mycomputer 4.13.8-1-ARCH #1 SMP PREEMPT Wed Oct 18 11:49:44 CEST 2017 x86_64 
Linux: arch  
Borg: 1.1.1  Python: CPython 3.6.3
PID: 23092  CWD: /root
sys.argv: ['/usr/bin/borg', 'list', 'server:repo']
SSH_ORIGINAL_COMMAND: None
```
I have also tested on 1.1.0. It seems all the 1.1.x branches have this issue.

Note: I'm connecting to the remote repo over SSH. In `~/.ssh/config` there is an entry called "server" that defines the HostName, User, and IdentityFile for the remote borg server.

Discussion:

Patch:
diff --git a/src/borg/archiver.py b/src/borg/archiver.py
index d678bb28..b09490bf 100644
--- a/src/borg/archiver.py
+++ b/src/borg/archiver.py
@@ -49,7 +49,7 @@
 from .helpers import BaseFormatter, ItemFormatter, ArchiveFormatter
 from .helpers import format_timedelta, format_file_size, parse_file_size, format_archive
 from .helpers import safe_encode, remove_surrogates, bin_to_hex, prepare_dump_dict
-from .helpers import interval, prune_within, prune_split, PRUNING_PATTERNS
+from .helpers import interval, prune_within, prune_split
 from .helpers import timestamp
 from .helpers import get_cache_dir
 from .helpers import Manifest, AI_HUMAN_SORT_KEYS
@@ -1333,48 +1333,45 @@ def do_prune(self, args, repository, manifest, key):
         # that is newer than a successfully completed backup - and killing the successful backup.
         archives = [arch for arch in archives_checkpoints if arch not in checkpoints]
         keep = []
-        # collect the rule responsible for the keeping of each archive in this dict
-        # keys are archive ids, values are a tuple
-        #   (<rulename>, <how many archives were kept by this rule so far >)
-        kept_because = {}
-
-        # find archives which need to be kept because of the keep-within rule
         if args.within:
-            keep += prune_within(archives, args.within, kept_because)
-
-        # find archives which need to be kept because of the various time period rules
-        for rule in PRUNING_PATTERNS.keys():
-            num = getattr(args, rule, None)
-            if num is not None:
-                keep += prune_split(archives, rule, num, kept_because)
-
+            keep += prune_within(archives, args.within)
+        if args.secondly:
+            keep += prune_split(archives, '%Y-%m-%d %H:%M:%S', args.secondly, keep)
+        if args.minutely:
+            keep += prune_split(archives, '%Y-%m-%d %H:%M', args.minutely, keep)
+        if args.hourly:
+            keep += prune_split(archives, '%Y-%m-%d %H', args.hourly, keep)
+        if args.daily:
+            keep += prune_split(archives, '%Y-%m-%d', args.daily, keep)
+        if args.weekly:
+            keep += prune_split(archives, '%G-%V', args.weekly, keep)
+        if args.monthly:
+            keep += prune_split(archives, '%Y-%m', args.monthly, keep)
+        if args.yearly:
+            keep += prune_split(archives, '%Y', args.yearly, keep)
         to_delete = (set(archives) | checkpoints) - (set(keep) | set(keep_checkpoints))
         stats = Statistics()
         with Cache(repository, key, manifest, do_files=False, lock_wait=self.lock_wait) as cache:
             list_logger = logging.getLogger('borg.output.list')
-            # set up counters for the progress display
-            to_delete_len = len(to_delete)
-            archives_deleted = 0
+            if args.output_list:
+                # set up counters for the progress display
+                to_delete_len = len(to_delete)
+                archives_deleted = 0
             for archive in archives_checkpoints:
                 if archive in to_delete:
                     if args.dry_run:
-                        log_message = 'Would prune:'
+                        if args.output_list:
+                            list_logger.info('Would prune:     %s' % format_archive(archive))
                     else:
-                        archives_deleted += 1
-                        log_message = 'Pruning archive (%d/%d):' % (archives_deleted, to_delete_len)
+                        if args.output_list:
+                            archives_deleted += 1
+                            list_logger.info('Pruning archive: %s (%d/%d)' % (format_archive(archive),
+                                                                              archives_deleted, to_delete_len))
                         Archive(repository, key, manifest, archive.name, cache,
                                 progress=args.progress).delete(stats, forced=args.forced)
                 else:
-                    if is_checkpoint(archive.name):
-                        log_message = 'Keeping checkpoint archive:'
-                    else:
-                        log_message = 'Keeping archive (rule: {rule} #{num}):'.format(
-                            rule=kept_because[archive.id][0], num=kept_because[archive.id][1]
-                        )
-                if args.output_list:
-                    list_logger.info("{message:<40} {archive}".format(
-                        message=log_message, archive=format_archive(archive)
-                    ))
+                    if args.output_list:
+                        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)
diff --git a/src/borg/helpers/misc.py b/src/borg/helpers/misc.py
index b0fbb203..e33b46f0 100644
--- a/src/borg/helpers/misc.py
+++ b/src/borg/helpers/misc.py
@@ -4,7 +4,7 @@
 import os.path
 import platform
 import sys
-from collections import deque, OrderedDict
+from collections import deque
 from datetime import datetime, timezone, timedelta
 from itertools import islice
 from operator import attrgetter
@@ -17,44 +17,22 @@
 from .. import chunker
 
 
-def prune_within(archives, hours, kept_because):
+def prune_within(archives, hours):
     target = datetime.now(timezone.utc) - timedelta(seconds=hours * 3600)
-    kept_counter = 0
-    result = []
-    for a in archives:
-        if a.ts > target:
-            kept_counter += 1
-            kept_because[a.id] = ("within", kept_counter)
-            result.append(a)
-    return result
-
-
-PRUNING_PATTERNS = OrderedDict([
-    ("secondly", '%Y-%m-%d %H:%M:%S'),
-    ("minutely", '%Y-%m-%d %H:%M'),
-    ("hourly", '%Y-%m-%d %H'),
-    ("daily", '%Y-%m-%d'),
-    ("weekly", '%G-%V'),
-    ("monthly", '%Y-%m'),
-    ("yearly", '%Y'),
-])
-
-
-def prune_split(archives, rule, n, kept_because=None):
+    return [a for a in archives if a.ts > target]
+
+
+def prune_split(archives, pattern, n, skip=[]):
     last = None
     keep = []
-    pattern = PRUNING_PATTERNS[rule]
-    if kept_because is None:
-        kept_because = {}
     if n == 0:
         return keep
     for a in sorted(archives, key=attrgetter('ts'), reverse=True):
         period = to_localtime(a.ts).strftime(pattern)
         if period != last:
             last = period
-            if a.id not in kept_because:
+            if a not in skip:
                 keep.append(a)
-                kept_because[a.id] = (rule, len(keep))
                 if len(keep) == n:
                     break
     return keep
diff --git a/src/borg/remote.py b/src/borg/remote.py
index d3c5e542..81067881 100644
--- a/src/borg/remote.py
+++ b/src/borg/remote.py
@@ -596,7 +596,7 @@ def do_open():
                     # emit this msg in the same way as the 'Remote: ...' lines that show the remote TypeError
                     sys.stderr.write(msg)
                     self.server_version = parse_version('1.0.6')
-                    compatMap['open'] = ('path', 'create', 'lock_wait', 'lock', ),
+                    compatMap['open'] = ('path', 'create', 'lock_wait', 'lock', )
                     # try again with corrected version and compatMap
                     do_open()
         except Exception:


Test patch:
diff --git a/src/borg/testsuite/archiver.py b/src/borg/testsuite/archiver.py
index 29fc50f7..c3a66632 100644
--- a/src/borg/testsuite/archiver.py
+++ b/src/borg/testsuite/archiver.py
@@ -6,7 +6,6 @@
 import os
 import pstats
 import random
-import re
 import shutil
 import socket
 import stat
@@ -1732,11 +1731,12 @@ def test_prune_repository(self):
         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', '--list', '--dry-run', self.repository_location, '--keep-daily=2')
-        assert re.search(r'Would prune:\s+test1', output)
+        self.assert_in('Keeping archive: test2', output)
+        self.assert_in('Would prune:     test1', output)
         # must keep the latest non-checkpoint archive:
-        assert re.search(r'Keeping archive \(rule: daily #1\):\s+test2', output)
+        self.assert_in('Keeping archive: test2', output)
         # must keep the latest checkpoint archive:
-        assert re.search(r'Keeping checkpoint archive:\s+test4.checkpoint', output)
+        self.assert_in('Keeping archive: test4.checkpoint', output)
         output = self.cmd('list', self.repository_location)
         self.assert_in('test1', output)
         self.assert_in('test2', output)
@@ -1766,8 +1766,8 @@ def test_prune_repository_save_space(self):
         self.cmd('create', self.repository_location + '::test1', src_dir)
         self.cmd('create', self.repository_location + '::test2', src_dir)
         output = self.cmd('prune', '--list', '--stats', '--dry-run', self.repository_location, '--keep-daily=2')
-        assert re.search(r'Keeping archive \(rule: daily #1\):\s+test2', output)
-        assert re.search(r'Would prune:\s+test1', output)
+        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)
@@ -1784,8 +1784,8 @@ def test_prune_repository_prefix(self):
         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', '--list', '--dry-run', self.repository_location, '--keep-daily=2', '--prefix=foo-')
-        assert re.search(r'Keeping archive \(rule: daily #1\):\s+foo-2015-08-12-20:00', output)
-        assert re.search(r'Would prune:\s+foo-2015-08-12-10:00', output)
+        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)
         self.assert_in('foo-2015-08-12-10:00', output)
         self.assert_in('foo-2015-08-12-20:00', output)
@@ -1805,8 +1805,8 @@ def test_prune_repository_glob(self):
         self.cmd('create', self.repository_location + '::2015-08-12-10:00-bar', src_dir)
         self.cmd('create', self.repository_location + '::2015-08-12-20:00-bar', src_dir)
         output = self.cmd('prune', '--list', '--dry-run', self.repository_location, '--keep-daily=2', '--glob-archives=2015-*-foo')
-        assert re.search(r'Keeping archive \(rule: daily #1\):\s+2015-08-12-20:00-foo', output)
-        assert re.search(r'Would prune:\s+2015-08-12-10:00-foo', output)
+        self.assert_in('Keeping archive: 2015-08-12-20:00-foo', output)
+        self.assert_in('Would prune:     2015-08-12-10:00-foo', output)
         output = self.cmd('list', self.repository_location)
         self.assert_in('2015-08-12-10:00-foo', output)
         self.assert_in('2015-08-12-20:00-foo', output)
diff --git a/src/borg/testsuite/helpers.py b/src/borg/testsuite/helpers.py
index 8d191974..15c029f5 100644
--- a/src/borg/testsuite/helpers.py
+++ b/src/borg/testsuite/helpers.py
@@ -1,10 +1,11 @@
 import hashlib
+import io
 import os
 import shutil
 import sys
 from argparse import ArgumentTypeError
 from datetime import datetime, timezone, timedelta
-from time import sleep
+from time import mktime, strptime, sleep
 
 import pytest
 
@@ -332,56 +333,40 @@ def test(self):
 
 class MockArchive:
 
-    def __init__(self, ts, id):
+    def __init__(self, ts):
         self.ts = ts
-        self.id = id
 
     def __repr__(self):
-        return "{0}: {1}".format(self.id, self.ts.isoformat())
-
-
-@pytest.mark.parametrize(
-    "rule,num_to_keep,expected_ids", [
-        ("yearly", 3, (13, 2, 1)),
-        ("monthly", 3, (13, 8, 4)),
-        ("weekly", 2, (13, 8)),
-        ("daily", 3, (13, 8, 7)),
-        ("hourly", 3, (13, 10, 8)),
-        ("minutely", 3, (13, 10, 9)),
-        ("secondly", 4, (13, 12, 11, 10)),
-        ("daily", 0, []),
-    ]
-)
-def test_prune_split(rule, num_to_keep, expected_ids):
-    def subset(lst, ids):
-        return {i for i in lst if i.id in ids}
-
-    archives = [
-        # years apart
-        MockArchive(datetime(2015, 1, 1, 10, 0, 0, tzinfo=timezone.utc), 1),
-        MockArchive(datetime(2016, 1, 1, 10, 0, 0, tzinfo=timezone.utc), 2),
-        MockArchive(datetime(2017, 1, 1, 10, 0, 0, tzinfo=timezone.utc), 3),
-        # months apart
-        MockArchive(datetime(2017, 2, 1, 10, 0, 0, tzinfo=timezone.utc), 4),
-        MockArchive(datetime(2017, 3, 1, 10, 0, 0, tzinfo=timezone.utc), 5),
-        # days apart
-        MockArchive(datetime(2017, 3, 2, 10, 0, 0, tzinfo=timezone.utc), 6),
-        MockArchive(datetime(2017, 3, 3, 10, 0, 0, tzinfo=timezone.utc), 7),
-        MockArchive(datetime(2017, 3, 4, 10, 0, 0, tzinfo=timezone.utc), 8),
-        # minutes apart
-        MockArchive(datetime(2017, 10, 1, 9, 45, 0, tzinfo=timezone.utc), 9),
-        MockArchive(datetime(2017, 10, 1, 9, 55, 0, tzinfo=timezone.utc), 10),
-        # seconds apart
-        MockArchive(datetime(2017, 10, 1, 10, 0, 1, tzinfo=timezone.utc), 11),
-        MockArchive(datetime(2017, 10, 1, 10, 0, 3, tzinfo=timezone.utc), 12),
-        MockArchive(datetime(2017, 10, 1, 10, 0, 5, tzinfo=timezone.utc), 13),
-    ]
-    kept_because = {}
-    keep = prune_split(archives, rule, num_to_keep, kept_because)
-
-    assert set(keep) == subset(archives, expected_ids)
-    for item in keep:
-        assert kept_because[item.id][0] == rule
+        return repr(self.ts)
+
+
+class PruneSplitTestCase(BaseTestCase):
+
+    def test(self):
+
+        def local_to_UTC(month, day):
+            """Convert noon on the month and day in 2013 to UTC."""
+            seconds = mktime(strptime('2013-%02d-%02d 12:00' % (month, day), '%Y-%m-%d %H:%M'))
+            return datetime.fromtimestamp(seconds, tz=timezone.utc)
+
+        def subset(lst, indices):
+            return {lst[i] for i in indices}
+
+        def dotest(test_archives, n, skip, indices):
+            for ta in test_archives, reversed(test_archives):
+                self.assert_equal(set(prune_split(ta, '%Y-%m', n, skip)),
+                                  subset(test_archives, indices))
+
+        test_pairs = [(1, 1), (2, 1), (2, 28), (3, 1), (3, 2), (3, 31), (5, 1)]
+        test_dates = [local_to_UTC(month, day) for month, day in test_pairs]
+        test_archives = [MockArchive(date) for date in test_dates]
+
+        dotest(test_archives, 3, [], [6, 5, 2])
+        dotest(test_archives, -1, [], [6, 5, 2, 0])
+        dotest(test_archives, 3, [test_archives[6]], [5, 2, 0])
+        dotest(test_archives, 3, [test_archives[5]], [6, 2, 0])
+        dotest(test_archives, 3, [test_archives[4]], [6, 5, 2])
+        dotest(test_archives, 0, [], [])
 
 
 class IntervalTestCase(BaseTestCase):
@@ -425,19 +410,14 @@ def subset(lst, indices):
 
         def dotest(test_archives, within, indices):
             for ta in test_archives, reversed(test_archives):
-                kept_because = {}
-                keep = prune_within(ta, interval(within), kept_because)
-                self.assert_equal(set(keep),
+                self.assert_equal(set(prune_within(ta, interval(within))),
                                   subset(test_archives, indices))
-                assert all("within" == kept_because[a.id][0] for a in keep)
 
         # 1 minute, 1.5 hours, 2.5 hours, 3.5 hours, 25 hours, 49 hours
         test_offsets = [60, 90*60, 150*60, 210*60, 25*60*60, 49*60*60]
         now = datetime.now(timezone.utc)
         test_dates = [now - timedelta(seconds=s) for s in test_offsets]
-        test_archives = [
-            MockArchive(date, i) for i, date in enumerate(test_dates)
-        ]
+        test_archives = [MockArchive(date) for date in test_dates]
 
         dotest(test_archives, '1H', [0])
         dotest(test_archives, '2H', [0, 1])