diff --git a/src/borg/helpers/parseformat.py b/src/borg/helpers/parseformat.py index 2cf2e8227f..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 @@ -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) 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 482a14e001..a52384a419 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) + 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): 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..776219a2ce 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,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 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 9c6a5b796c..2ad16ea9d3 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,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