diff: show timestamp changes with full nanosecond precision, fixes #9147

src/borg/helpers/parseformat.py

@@ -26,7 +26,7 @@
 from .fs import make_path_safe, slashify
 from .argparsing import Action, ArgumentError, ArgumentTypeError, register_type
 from .msgpack import Timestamp
-from .time import OutputTimestamp, format_time, safe_timestamp
+from .time import OutputTimestamp, format_time, format_time_ns, safe_timestamp
 from .. import __version__ as borg_version
 from .. import __version_tuple__ as borg_version_tuple
 from ..constants import *  # NOQA
@@ -1284,7 +1284,13 @@ def format_content(self, diff: "ItemDiff"):
 
     def format_time(self, key, diff: "ItemDiff"):
         change = diff.changes().get(key)
-        return f"[{key}: {change.diff_data['item1']} -> {change.diff_data['item2']}]" if change else ""
+        if not change:
+            return ""
+        # show the full nanosecond precision: time diffs are often sub-second (e.g. ctime
+        # updates of surviving hardlinks), second precision would render both timestamps
+        # identically.
+        ts1, ts2 = change.diff_data["item1"], change.diff_data["item2"]
+        return f"[{key}: {format_time_ns(ts1.ts, ts1.ns)} -> {format_time_ns(ts2.ts, ts2.ns)}]"
 
     def format_iso_time(self, key, diff: "ItemDiff"):
         change = diff.changes().get(key)

src/borg/helpers/time.py

@@ -105,6 +105,15 @@ def format_time(ts: datetime, format_spec=""):
     return ts.astimezone().strftime("%a, %Y-%m-%d %H:%M:%S %z" if format_spec == "" else format_spec)
 
 
+def format_time_ns(ts: datetime, ns: int):
+    """
+    Like format_time (default format), but with the seconds fraction in nanosecond precision,
+    taken from *ns* (the nanoseconds timestamp *ts* was derived from).
+    """
+    dt = ts.astimezone()
+    return f"{dt:%a, %Y-%m-%d %H:%M:%S}.{ns % 1_000_000_000:09d} {dt:%z}"
+
+
 def format_timedelta(td):
     """Format a timedelta in a human-friendly format."""
     ts = td.total_seconds()
@@ -178,8 +187,11 @@ def get_month_and_year_from_total(total_completed_months):
 
 
 class OutputTimestamp:
-    def __init__(self, ts: datetime):
+    def __init__(self, ts: datetime, ns: int = None):
+        # ns optionally gives the nanoseconds timestamp *ts* was derived from,
+        # so the sub-second part can be output in full precision.
         self.ts = ts
+        self.ns = safe_ns(ns) if ns is not None else None
 
     def __format__(self, format_spec):
         # we want to output a timestamp in the user's local timezone
@@ -190,7 +202,12 @@ def __str__(self):
 
     def isoformat(self):
         # we want to output a timestamp in the user's local timezone
-        return self.ts.astimezone().isoformat(timespec="microseconds")
+        if self.ns is None:
+            return self.ts.astimezone().isoformat(timespec="microseconds")
+        # nanosecond precision: datetime.isoformat can only do microseconds, so build
+        # "YYYY-MM-DDTHH:MM:SS" + ".<9-digit fraction>" + "+HH:MM" ourselves.
+        base = self.ts.astimezone().replace(microsecond=0).isoformat()
+        return f"{base[:19]}.{self.ns % 1_000_000_000:09d}{base[19:]}"
 
     to_json = isoformat
 

src/borg/item.pyx

@@ -775,10 +775,15 @@ class ItemDiff:
     def _time_diffs(self):
         attrs = ["ctime", "mtime"]
         for attr in attrs:
-            if attr in self._item1 and attr in self._item2 and self._item1.get(attr) != self._item2.get(attr):
-                ts1 = OutputTimestamp(safe_timestamp(self._item1.get(attr)))
-                ts2 = OutputTimestamp(safe_timestamp(self._item2.get(attr)))
-                self._changes[attr] = DiffChange(attr, {"item1": ts1, "item2": ts2},)
+            if attr in self._item1 and attr in self._item2:
+                ts1_ns = self._item1.get(attr)
+                ts2_ns = self._item2.get(attr)
+                if ts1_ns != ts2_ns:
+                    # pass ns so formatters can show the full sub-second precision,
+                    # the datetime in OutputTimestamp.ts only has microseconds.
+                    ts1 = OutputTimestamp(safe_timestamp(ts1_ns), ns=ts1_ns)
+                    ts2 = OutputTimestamp(safe_timestamp(ts2_ns), ns=ts2_ns)
+                    self._changes[attr] = DiffChange(attr, {"item1": ts1, "item2": ts2})
         return True
 
     def content(self):

src/borg/testsuite/archiver/diff_cmd_test.py

@@ -1,13 +1,14 @@
 import json
 import os
 from pathlib import Path
+import re
 import stat
 import time
 import pytest
 
 from ...constants import *  # NOQA
 from .. import are_symlinks_supported, are_hardlinks_supported, granularity_sleep
-from ...platformflags import is_win32, is_freebsd, is_netbsd
+from ...platformflags import is_win32, is_freebsd, is_netbsd, is_openbsd
 from . import (
     cmd,
     create_regular_file,
@@ -428,8 +429,7 @@ def test_sort_by_all_keys_with_directions(archivers, request, sort_key):
 
 
 @pytest.mark.skipif(
-    not are_hardlinks_supported() or is_freebsd or is_netbsd or is_win32,
-    reason="hardlinks not supported or test failing on freebsd, netbsd and windows",
+    not are_hardlinks_supported() or is_win32, reason="hardlinks not supported or not available on windows"
 )
 def test_hard_link_deletion_and_replacement(archivers, request):
     archiver = request.getfixturevalue(archivers)
@@ -511,5 +511,18 @@ def test_hard_link_deletion_and_replacement(archivers, request):
     assert_line_exists(lines, "[cm]time:.*[cm]time:.*input/a$")
     # From test1 to test2's POV, the a/hardlink file is a fresh new file.
     assert_line_exists(lines, "added.*B.*input/a/hardlink")
-    # But the b/hardlink file was not modified at all.
-    assert_line_not_exists(lines, ".*input/b/hardlink")
+    if is_freebsd or is_netbsd or is_openbsd:
+        # On the BSDs, b/hardlink may show a (usually sub-second) ctime update in this
+        # scenario (POSIX permits this). If it shows up, it must be a ctime-only change
+        # and the displayed timestamps must be distinguishable (microsecond precision).
+        for line in lines:
+            if re.search("input/b/hardlink", line):
+                m = re.search(r"\[ctime: (.+?) -> (.+?)\]", line)
+                assert m is not None, f"unexpected non-ctime change: {line!r}"
+                assert m.group(1) != m.group(2), f"indistinguishable timestamps: {line!r}"
+        assert_line_not_exists(lines, "mtime:.*input/b/hardlink")
+        assert_line_not_exists(lines, "modified.*input/b/hardlink")
+        assert_line_not_exists(lines, "-[r-][w-][x-].*input/b/hardlink")
+    else:
+        # But the b/hardlink file was not modified at all.
+        assert_line_not_exists(lines, ".*input/b/hardlink")

src/borg/testsuite/helpers/parseformat_test.py

@@ -28,8 +28,10 @@
     swidth_slice,
     eval_escapes,
     ChunkerParams,
+    DiffFormatter,
 )
 from ...helpers.time import format_timedelta, parse_timestamp
+from ...item import Item, ItemDiff
 from ...platformflags import is_win32
 
 
@@ -747,3 +749,26 @@ def test_json_dump_indent(monkeypatch, env_value, expect_newlines):
     else:
         assert "\n" not in result
     assert json.loads(result) == obj
+
+
+@pytest.mark.parametrize(
+    "ctime1_ns, ctime2_ns",
+    [
+        (1000000000_000123_111, 1000000000_000123_999),  # same microsecond, different nanosecond
+        (1000000000_000123_000, 1000000000_000456_000),  # same second, different microsecond
+        (1000000000_000123_000, 1000000001_000123_000),  # different second
+    ],
+)
+def test_diff_formatter_time_precision(ctime1_ns, ctime2_ns):
+    """DiffFormatter renders time changes with nanosecond precision, so that timestamps
+    differing at sub-second level (e.g. hardlink ctime updates, see #9147) are distinguishable."""
+    item1 = Item(path="p", mode=0o100644, mtime=0, ctime=ctime1_ns)
+    item2 = Item(path="p", mode=0o100644, mtime=0, ctime=ctime2_ns)
+    diff = ItemDiff("p", item1, item2, iter([]), iter([]), can_compare_chunk_ids=True)
+    formatter = DiffFormatter("{ctime} {path}{NL}")
+    output = formatter.format_item(diff)
+    m = re.search(r"\[ctime: (.+?) -> (.+?)\]", output)
+    assert m is not None
+    assert re.search(r"\.\d{9} ", m.group(1))  # 9-digit fraction is shown
+    assert re.search(r"\.\d{9} ", m.group(2))
+    assert m.group(1) != m.group(2)  # timestamps are distinguishable

src/borg/testsuite/helpers/time_test.py

@@ -1,7 +1,8 @@
 import pytest
 from datetime import datetime, timezone
 
-from ...helpers.time import safe_ns, safe_s, SUPPORT_32BIT_PLATFORMS
+from ...helpers.time import safe_ns, safe_s, safe_timestamp, SUPPORT_32BIT_PLATFORMS
+from ...helpers.time import format_time, format_time_ns, OutputTimestamp
 
 
 def utcfromtimestamp(timestamp):
@@ -36,3 +37,26 @@ def test_safe_timestamps():
             utcfromtimestamp(beyond_y10k)
         assert utcfromtimestamp(safe_s(beyond_y10k)) > datetime(2262, 1, 1)
         assert utcfromtimestamp(safe_ns(beyond_y10k) / 1000000000) > datetime(2262, 1, 1)
+
+
+def test_format_time_ns():
+    ns = 1000000000_000123_456
+    ts = safe_timestamp(ns)
+    result = format_time_ns(ts, ns)
+    # full nanosecond precision fraction, otherwise identical to format_time's output
+    assert result.replace(".000123456", "") == format_time(ts)
+
+
+def test_output_timestamp_ns_isoformat():
+    ns = 1000000000_000123_456
+    ots = OutputTimestamp(safe_timestamp(ns), ns=ns)
+    iso = ots.isoformat()
+    # full nanosecond precision fraction, otherwise identical to the seconds-precision isoformat
+    assert iso.replace(".000123456", "") == safe_timestamp(ns).astimezone().isoformat(timespec="seconds")
+    assert ots.to_json() == iso
+
+
+def test_output_timestamp_without_ns_isoformat():
+    ns = 1000000000_000123_456
+    ots = OutputTimestamp(safe_timestamp(ns))  # no ns given
+    assert ots.isoformat() == safe_timestamp(ns).astimezone().isoformat(timespec="microseconds")

src/borg/testsuite/item_test.py

@@ -1,7 +1,7 @@
 import pytest
 
 from ..cache import ChunkListEntry
-from ..item import Item, chunks_contents_equal
+from ..item import Item, ItemDiff, chunks_contents_equal
 from ..helpers import StableDict
 from ..helpers.msgpack import Timestamp
 
@@ -173,3 +173,21 @@ def test_chunk_content_equal(chunk_a: str, chunk_b: str, chunks_equal):
     compare2 = chunks_contents_equal(iter(chunks_b), iter(chunks_a))
     assert compare1 == compare2
     assert compare1 == chunks_equal
+
+
+@pytest.mark.parametrize(
+    "ctime1_ns, ctime2_ns, change_expected",
+    [
+        (1000000000_000000_000, 1000000000_000000_000, False),  # identical
+        (1000000000_000000_000, 1000000000_000000_001, True),  # nanosecond difference
+        (1000000000_000000_000, 1000000000_000001_000, True),  # microsecond difference
+        (1000000000_000000_000, 1000000001_000000_000, True),  # second difference
+    ],
+)
+def test_item_diff_time_ns_resolution(ctime1_ns, ctime2_ns, change_expected):
+    """ItemDiff compares timestamps with full nanosecond resolution."""
+    item1 = Item(path="p", mode=0o100644, mtime=0, ctime=ctime1_ns)
+    item2 = Item(path="p", mode=0o100644, mtime=0, ctime=ctime2_ns)
+    diff = ItemDiff("p", item1, item2, iter([]), iter([]), can_compare_chunk_ids=True)
+    assert (diff.ctime() is not None) == change_expected
+    assert diff.mtime() is None