From 8ba8ec0a37812c69401cd59cf40851f418c53bd5 Mon Sep 17 00:00:00 2001 From: Thomas Waldmann Date: Thu, 2 Jul 2026 10:30:34 +0200 Subject: [PATCH 1/2] diff: always use microsecond precision for timestamp changes, fixes #9147 Time changes shown by borg diff are often sub-second (e.g. POSIX-valid ctime updates of surviving hardlinks). With the previous second-precision format, both timestamps could render identically, giving confusing output like [ctime: Wed, ... 17:45:53 +0000 -> Wed, ... 17:45:53 +0000]. - DiffFormatter.format_time: always render with microsecond precision. - ItemDiff._time_diffs: compare timestamps with microsecond granularity: sub-microsecond differences can neither be represented by datetime nor displayed, so reporting them would produce the same confusing output. - re-enable test_hard_link_deletion_and_replacement on FreeBSD, NetBSD and OpenBSD: accept a ctime-only change of the surviving hardlink there. Based on the analysis and tests of PR #9561 by hiepau1231 - thanks! Co-authored-by: hiepau1231 Co-Authored-By: Claude Fable 5 --- src/borg/helpers/parseformat.py | 7 +++++- src/borg/item.pyx | 13 +++++++---- src/borg/testsuite/archiver/diff_cmd_test.py | 23 +++++++++++++++---- .../testsuite/helpers/parseformat_test.py | 23 +++++++++++++++++++ src/borg/testsuite/item_test.py | 21 ++++++++++++++++- 5 files changed, 76 insertions(+), 11 deletions(-) diff --git a/src/borg/helpers/parseformat.py b/src/borg/helpers/parseformat.py index 2cf2e8227f..17f4d63b1c 100644 --- a/src/borg/helpers/parseformat.py +++ b/src/borg/helpers/parseformat.py @@ -1284,7 +1284,12 @@ 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 "" + # always show microseconds: time diffs are often sub-second (e.g. ctime updates of + # surviving hardlinks), second precision would render both timestamps identically. + fmt = "%a, %Y-%m-%d %H:%M:%S.%f %z" + return f"[{key}: {change.diff_data['item1']:{fmt}} -> {change.diff_data['item2']:{fmt}}]" def format_iso_time(self, key, diff: "ItemDiff"): change = diff.changes().get(key) diff --git a/src/borg/item.pyx b/src/borg/item.pyx index 482a14e001..525f673a9a 100644 --- a/src/borg/item.pyx +++ b/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) + # compare with microsecond granularity: datetime can't represent sub-microsecond + # differences, so reporting them would display two identical-looking timestamps. + if ts1_ns // 1000 != ts2_ns // 1000: + ts1 = OutputTimestamp(safe_timestamp(ts1_ns)) + ts2 = OutputTimestamp(safe_timestamp(ts2_ns)) + self._changes[attr] = DiffChange(attr, {"item1": ts1, "item2": ts2}) return True def content(self): diff --git a/src/borg/testsuite/archiver/diff_cmd_test.py b/src/borg/testsuite/archiver/diff_cmd_test.py index ab073bc8af..90984104ea 100644 --- a/src/borg/testsuite/archiver/diff_cmd_test.py +++ b/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") diff --git a/src/borg/testsuite/helpers/parseformat_test.py b/src/borg/testsuite/helpers/parseformat_test.py index 0f61c49f04..0cd9932b3c 100644 --- a/src/borg/testsuite/helpers/parseformat_test.py +++ b/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,24 @@ 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_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 microsecond 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 "." in m.group(1) and "." in m.group(2) # microseconds are shown + assert m.group(1) != m.group(2) # timestamps are distinguishable diff --git a/src/borg/testsuite/item_test.py b/src/borg/testsuite/item_test.py index 9c6a5b796c..2d03d03b0d 100644 --- a/src/borg/testsuite/item_test.py +++ b/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,22 @@ 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_999, False), # sub-microsecond difference + (1000000000_000000_000, 1000000000_000001_000, True), # microsecond difference + (1000000000_000000_000, 1000000001_000000_000, True), # second difference + ], +) +def test_item_diff_time_granularity(ctime1_ns, ctime2_ns, change_expected): + """ItemDiff compares timestamps with microsecond granularity: differences below that + can neither be represented by datetime nor displayed, so they are not reported.""" + 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 From 2b14dc9fa8a7d057964ae83f5b78d95927e400b2 Mon Sep 17 00:00:00 2001 From: Thomas Waldmann Date: Thu, 2 Jul 2026 10:53:16 +0200 Subject: [PATCH 2/2] diff: report and display timestamp changes with nanosecond precision A sub-microsecond timestamp difference is a real difference - borg stores timestamps as int nanoseconds, so quantizing the comparison to microseconds (as the previous commit did) made borg diff silently omit genuine metadata changes. Instead, compare at full nanosecond resolution again and make the displayed precision match the stored precision: - OutputTimestamp optionally carries the raw nanoseconds value; its isoformat()/to_json() then emit a 9-digit fraction, so the ISO format keys and the JSON-lines output can also represent sub-microsecond differences. - new helpers.time.format_time_ns(): like format_time() (default format), but with a 9-digit seconds fraction taken from the raw nanoseconds. - ItemDiff._time_diffs() compares the raw ns ints and passes them to OutputTimestamp; DiffFormatter.format_time() renders via format_time_ns(). With the fixed 9-digit fraction, any reported time change always renders as two distinguishable timestamps, in text as well as in JSON output. Co-Authored-By: Claude Fable 5 --- src/borg/helpers/parseformat.py | 11 ++++---- src/borg/helpers/time.py | 21 +++++++++++++-- src/borg/item.pyx | 10 +++---- .../testsuite/helpers/parseformat_test.py | 6 +++-- src/borg/testsuite/helpers/time_test.py | 26 ++++++++++++++++++- src/borg/testsuite/item_test.py | 7 +++-- 6 files changed, 62 insertions(+), 19 deletions(-) diff --git a/src/borg/helpers/parseformat.py b/src/borg/helpers/parseformat.py index 17f4d63b1c..9436a147ba 100644 --- a/src/borg/helpers/parseformat.py +++ b/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 @@ -1286,10 +1286,11 @@ def format_time(self, key, diff: "ItemDiff"): change = diff.changes().get(key) if not change: return "" - # always show microseconds: time diffs are often sub-second (e.g. ctime updates of - # surviving hardlinks), second precision would render both timestamps identically. - fmt = "%a, %Y-%m-%d %H:%M:%S.%f %z" - return f"[{key}: {change.diff_data['item1']:{fmt}} -> {change.diff_data['item2']:{fmt}}]" + # 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) diff --git a/src/borg/helpers/time.py b/src/borg/helpers/time.py index e54394cdc0..ef79fe7920 100644 --- a/src/borg/helpers/time.py +++ b/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 diff --git a/src/borg/item.pyx b/src/borg/item.pyx index 525f673a9a..a52384a419 100644 --- a/src/borg/item.pyx +++ b/src/borg/item.pyx @@ -778,11 +778,11 @@ class ItemDiff: if attr in self._item1 and attr in self._item2: ts1_ns = self._item1.get(attr) ts2_ns = self._item2.get(attr) - # compare with microsecond granularity: datetime can't represent sub-microsecond - # differences, so reporting them would display two identical-looking timestamps. - if ts1_ns // 1000 != ts2_ns // 1000: - ts1 = OutputTimestamp(safe_timestamp(ts1_ns)) - ts2 = OutputTimestamp(safe_timestamp(ts2_ns)) + 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 diff --git a/src/borg/testsuite/helpers/parseformat_test.py b/src/borg/testsuite/helpers/parseformat_test.py index 0cd9932b3c..776219a2ce 100644 --- a/src/borg/testsuite/helpers/parseformat_test.py +++ b/src/borg/testsuite/helpers/parseformat_test.py @@ -754,12 +754,13 @@ def test_json_dump_indent(monkeypatch, env_value, expect_newlines): @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 microsecond precision, so that timestamps + """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) @@ -768,5 +769,6 @@ def test_diff_formatter_time_precision(ctime1_ns, ctime2_ns): output = formatter.format_item(diff) m = re.search(r"\[ctime: (.+?) -> (.+?)\]", output) assert m is not None - assert "." in m.group(1) and "." in m.group(2) # microseconds are shown + 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 diff --git a/src/borg/testsuite/helpers/time_test.py b/src/borg/testsuite/helpers/time_test.py index 7dcffc8278..612094b48b 100644 --- a/src/borg/testsuite/helpers/time_test.py +++ b/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") diff --git a/src/borg/testsuite/item_test.py b/src/borg/testsuite/item_test.py index 2d03d03b0d..2ad16ea9d3 100644 --- a/src/borg/testsuite/item_test.py +++ b/src/borg/testsuite/item_test.py @@ -179,14 +179,13 @@ def test_chunk_content_equal(chunk_a: str, chunk_b: str, chunks_equal): "ctime1_ns, ctime2_ns, change_expected", [ (1000000000_000000_000, 1000000000_000000_000, False), # identical - (1000000000_000000_000, 1000000000_000000_999, False), # sub-microsecond difference + (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_granularity(ctime1_ns, ctime2_ns, change_expected): - """ItemDiff compares timestamps with microsecond granularity: differences below that - can neither be represented by datetime nor displayed, so they are not reported.""" +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)