Repository: borgbackup/borg

Issue:
timestamp microseconds parsing issue
Spurious failure seen in a unrelated 1.1-maint PR on py 3.4:
```
.tox/py34/lib/python3.4/site-packages/borg/archiver.py:1232: in _delete_archives
    manifest.write()
.tox/py34/lib/python3.4/site-packages/borg/helpers.py:393: in write
    prev_ts = self.last_timestamp
.tox/py34/lib/python3.4/site-packages/borg/helpers.py:321: in last_timestamp
    return datetime.strptime(self.timestamp, "%Y-%m-%dT%H:%M:%S.%f")

E           ValueError: time data '2017-09-02T16:16:34' does not match format '%Y-%m-%dT%H:%M:%S.%f'
```

Suspicion: crappy standard formatting behaviour of stdlib to only add `.uuu` for the microsecs if microsecs != 0, which then causes complications when trying to parse that.

Discussion:

Patch:
diff --git a/src/borg/archive.py b/src/borg/archive.py
index 0f4c2d0f..3cb0b7cf 100644
--- a/src/borg/archive.py
+++ b/src/borg/archive.py
@@ -461,8 +461,8 @@ def save(self, name=None, comment=None, timestamp=None, additional_metadata=None
             'cmdline': sys.argv,
             'hostname': socket.gethostname(),
             'username': getuser(),
-            'time': start.isoformat(),
-            'time_end': end.isoformat(),
+            'time': start.strftime(ISO_FORMAT),
+            'time_end': end.strftime(ISO_FORMAT),
             'chunker_params': self.chunker_params,
         }
         metadata.update(additional_metadata or {})
diff --git a/src/borg/archiver.py b/src/borg/archiver.py
index 3b468db1..48b9fde7 100644
--- a/src/borg/archiver.py
+++ b/src/borg/archiver.py
@@ -1467,11 +1467,6 @@ def do_with_lock(self, args, repository):
         # the encryption key (and can operate just with encrypted data).
         data = repository.get(Manifest.MANIFEST_ID)
         repository.put(Manifest.MANIFEST_ID, data)
-        # usually, a 0 byte (open for writing) segment file would be visible in the filesystem here.
-        # we write and close this file, to rather have a valid segment file on disk, before invoking the subprocess.
-        # we can only do this for local repositories (with .io), though:
-        if hasattr(repository, 'io'):
-            repository.io.close_segment()
         try:
             # we exit with the return code we get from the subprocess
             return subprocess.call([args.command] + args.args)
diff --git a/src/borg/constants.py b/src/borg/constants.py
index 6c13a9c9..36d6ee45 100644
--- a/src/borg/constants.py
+++ b/src/borg/constants.py
@@ -66,6 +66,12 @@
 EXIT_WARNING = 1  # reached normal end of operation, but there were issues
 EXIT_ERROR = 2  # terminated abruptly, did not reach end of operation
 
+# never use datetime.isoformat(), it is evil. always use one of these:
+# datetime.strftime(ISO_FORMAT)  # output always includes .microseconds
+# datetime.strftime(ISO_FORMAT_NO_USECS)  # output never includes microseconds
+ISO_FORMAT_NO_USECS = '%Y-%m-%dT%H:%M:%S'
+ISO_FORMAT = ISO_FORMAT_NO_USECS + '.%f'
+
 DASHES = '-' * 78
 
 PBKDF2_ITERATIONS = 100000
diff --git a/src/borg/helpers/manifest.py b/src/borg/helpers/manifest.py
index e92672f4..eb88c038 100644
--- a/src/borg/helpers/manifest.py
+++ b/src/borg/helpers/manifest.py
@@ -64,7 +64,7 @@ def __setitem__(self, name, info):
         id, ts = info
         assert isinstance(id, bytes)
         if isinstance(ts, datetime):
-            ts = ts.replace(tzinfo=None).isoformat()
+            ts = ts.replace(tzinfo=None).strftime(ISO_FORMAT)
         assert isinstance(ts, str)
         ts = ts.encode()
         self._archives[name] = {b'id': id, b'time': ts}
@@ -166,7 +166,7 @@ def id_str(self):
 
     @property
     def last_timestamp(self):
-        return datetime.strptime(self.timestamp, "%Y-%m-%dT%H:%M:%S.%f")
+        return parse_timestamp(self.timestamp, tzinfo=None)
 
     @classmethod
     def load(cls, repository, operations, key=None, force_tam_not_required=False):
@@ -236,11 +236,11 @@ def write(self):
             self.config[b'tam_required'] = True
         # self.timestamp needs to be strictly monotonically increasing. Clocks often are not set correctly
         if self.timestamp is None:
-            self.timestamp = datetime.utcnow().isoformat()
+            self.timestamp = datetime.utcnow().strftime(ISO_FORMAT)
         else:
             prev_ts = self.last_timestamp
-            incremented = (prev_ts + timedelta(microseconds=1)).isoformat()
-            self.timestamp = max(incremented, datetime.utcnow().isoformat())
+            incremented = (prev_ts + timedelta(microseconds=1)).strftime(ISO_FORMAT)
+            self.timestamp = max(incremented, datetime.utcnow().strftime(ISO_FORMAT))
         # include checks for limits as enforced by limited unpacker (used by load())
         assert len(self.archives) <= MAX_ARCHIVES
         assert all(len(name) <= 255 for name in self.archives)
diff --git a/src/borg/helpers/parseformat.py b/src/borg/helpers/parseformat.py
index 25114c46..f926bbe9 100644
--- a/src/borg/helpers/parseformat.py
+++ b/src/borg/helpers/parseformat.py
@@ -137,7 +137,7 @@ def __init__(self, dt):
 
     def __format__(self, format_spec):
         if format_spec == '':
-            format_spec = '%Y-%m-%dT%H:%M:%S'
+            format_spec = ISO_FORMAT_NO_USECS
         return self.dt.__format__(format_spec)
 
 
diff --git a/src/borg/helpers/time.py b/src/borg/helpers/time.py
index 2d22794a..c5a5ddd8 100644
--- a/src/borg/helpers/time.py
+++ b/src/borg/helpers/time.py
@@ -2,18 +2,21 @@
 import time
 from datetime import datetime, timezone
 
+from ..constants import ISO_FORMAT, ISO_FORMAT_NO_USECS
+
 
 def to_localtime(ts):
     """Convert datetime object from UTC to local time zone"""
     return datetime(*time.localtime((ts - datetime(1970, 1, 1, tzinfo=timezone.utc)).total_seconds())[:6])
 
 
-def parse_timestamp(timestamp):
+def parse_timestamp(timestamp, tzinfo=timezone.utc):
     """Parse a ISO 8601 timestamp string"""
-    if '.' in timestamp:  # microseconds might not be present
-        return datetime.strptime(timestamp, '%Y-%m-%dT%H:%M:%S.%f').replace(tzinfo=timezone.utc)
-    else:
-        return datetime.strptime(timestamp, '%Y-%m-%dT%H:%M:%S').replace(tzinfo=timezone.utc)
+    fmt = ISO_FORMAT if '.' in timestamp else ISO_FORMAT_NO_USECS
+    dt = datetime.strptime(timestamp, fmt)
+    if tzinfo is not None:
+        dt = dt.replace(tzinfo=tzinfo)
+    return dt
 
 
 def timestamp(s):
@@ -98,7 +101,7 @@ def isoformat_time(ts: datetime):
     Format *ts* according to ISO 8601.
     """
     # note: first make all datetime objects tz aware before adding %z here.
-    return ts.strftime('%Y-%m-%dT%H:%M:%S.%f')
+    return ts.strftime(ISO_FORMAT)
 
 
 def format_timedelta(td):
diff --git a/src/borg/repository.py b/src/borg/repository.py
index dada3c14..86b4ae9b 100644
--- a/src/borg/repository.py
+++ b/src/borg/repository.py
@@ -540,7 +540,8 @@ def rename_tmp(file):
         # Log transaction in append-only mode
         if self.append_only:
             with open(os.path.join(self.path, 'transactions'), 'a') as log:
-                print('transaction %d, UTC time %s' % (transaction_id, datetime.utcnow().isoformat()), file=log)
+                print('transaction %d, UTC time %s' % (
+                      transaction_id, datetime.utcnow().strftime(ISO_FORMAT)), file=log)
 
         # Write hints file
         hints_name = 'hints.%d' % transaction_id
@@ -1176,8 +1177,6 @@ def cleanup(self, transaction_id):
         count = 0
         for segment, filename in self.segment_iterator(reverse=True):
             if segment > transaction_id:
-                if segment in self.fds:
-                    del self.fds[segment]
                 truncate_and_unlink(filename)
                 count += 1
             else:
@@ -1234,12 +1233,6 @@ def get_write_fd(self, no_new=False, raise_full=False):
             self._write_fd = SyncFile(self.segment_filename(self.segment), binary=True)
             self._write_fd.write(MAGIC)
             self.offset = MAGIC_LEN
-            if self.segment in self.fds:
-                # we may have a cached fd for a segment file we already deleted and
-                # we are writing now a new segment file to same file name. get rid of
-                # of the cached fd that still refers to the old file, so it will later
-                # get repopulated (on demand) with a fd that refers to the new file.
-                del self.fds[self.segment]
         return self._write_fd
 
     def get_fd(self, segment):


Test patch:
diff --git a/src/borg/testsuite/archiver.py b/src/borg/testsuite/archiver.py
index 1bf3ed73..6af6008f 100644
--- a/src/borg/testsuite/archiver.py
+++ b/src/borg/testsuite/archiver.py
@@ -61,8 +61,6 @@
 
 src_dir = os.path.abspath(os.path.join(os.path.dirname(__file__), '..'))
 
-ISO_FORMAT = '%Y-%m-%dT%H:%M:%S.%f'
-
 
 def exec_cmd(*args, archiver=None, fork=False, exe=None, input=b'', binary_output=False, **kw):
     if fork:
@@ -3037,7 +3035,7 @@ def spoof_manifest(self, repository):
                 'version': 1,
                 'archives': {},
                 'config': {},
-                'timestamp': (datetime.utcnow() + timedelta(days=1)).isoformat(),
+                'timestamp': (datetime.utcnow() + timedelta(days=1)).strftime(ISO_FORMAT),
             })))
             repository.commit()
 
@@ -3049,7 +3047,7 @@ def test_fresh_init_tam_required(self):
             repository.put(Manifest.MANIFEST_ID, key.encrypt(msgpack.packb({
                 'version': 1,
                 'archives': {},
-                'timestamp': (datetime.utcnow() + timedelta(days=1)).isoformat(),
+                'timestamp': (datetime.utcnow() + timedelta(days=1)).strftime(ISO_FORMAT),
             })))
             repository.commit()
 
diff --git a/src/borg/testsuite/repository.py b/src/borg/testsuite/repository.py
index 1bec1400..e29c7d53 100644
--- a/src/borg/testsuite/repository.py
+++ b/src/borg/testsuite/repository.py
@@ -210,23 +210,6 @@ def test_sparse_delete(self):
         self.repository.commit()
         assert 0 not in [segment for segment, _ in self.repository.io.segment_iterator()]
 
-    def test_uncommitted_garbage(self):
-        # uncommitted garbage should be no problem, it is cleaned up automatically.
-        # we just have to be careful with invalidation of cached FDs in LoggedIO.
-        self.repository.put(H(0), b'foo')
-        self.repository.commit()
-        # write some crap to a uncommitted segment file
-        last_segment = self.repository.io.get_latest_segment()
-        with open(self.repository.io.segment_filename(last_segment + 1), 'wb') as f:
-            f.write(MAGIC + b'crapcrapcrap')
-        self.repository.close()
-        # usually, opening the repo and starting a transaction should trigger a cleanup.
-        self.repository = self.open()
-        with self.repository:
-            self.repository.put(H(0), b'bar')  # this may trigger compact_segments()
-            self.repository.commit()
-        # the point here is that nothing blows up with an exception.
-
 
 class RepositoryCommitTestCase(RepositoryTestCaseBase):