borg icon indicating copy to clipboard operation
borg copied to clipboard

freebsd test failure in test_hard_link_deletion_and_replacement

Open ThomasWaldmann opened this issue 1 month ago • 1 comments

Spotted this in PR #9146 (master branch):

=================================== FAILURES ===================================
2025-11-05T17:50:25.2963838Z ______________ test_hard_link_deletion_and_replacement[archiver] _______________
2025-11-05T17:50:25.2964927Z [gw1] freebsd14 -- Python 3.11.13 /home/runner/work/borg/borg/.venv/bin/python
2025-11-05T17:50:25.2965578Z 
2025-11-05T17:50:25.2965758Z archivers = 'archiver'
2025-11-05T17:50:25.2966629Z request = <FixtureRequest for <Function test_hard_link_deletion_and_replacement[archiver]>>
2025-11-05T17:50:25.2967444Z 
2025-11-05T17:50:25.2967986Z     @pytest.mark.skipif(not are_hardlinks_supported(), reason="hardlinks not supported")
2025-11-05T17:50:25.2968969Z     def test_hard_link_deletion_and_replacement(archivers, request):
2025-11-05T17:50:25.2969544Z         archiver = request.getfixturevalue(archivers)
2025-11-05T17:50:25.2969962Z     
2025-11-05T17:50:25.2970341Z         # repo-create changes umask, so create the repo first to avoid any
2025-11-05T17:50:25.2970853Z         # unexpected permission changes.
2025-11-05T17:50:25.2971782Z         cmd(archiver, "repo-create", RK_ENCRYPTION)
2025-11-05T17:50:25.2972272Z         path_a = os.path.join(archiver.input_path, "a")
2025-11-05T17:50:25.2972714Z         path_b = os.path.join(archiver.input_path, "b")
2025-11-05T17:50:25.2973100Z         os.mkdir(path_a)
2025-11-05T17:50:25.2973405Z         os.mkdir(path_b)
2025-11-05T17:50:25.2973730Z         hl_a = os.path.join(path_a, "hardlink")
2025-11-05T17:50:25.2974122Z         hl_b = os.path.join(path_b, "hardlink")
2025-11-05T17:50:25.2974637Z         create_regular_file(archiver.input_path, hl_a, contents=b"123456")
2025-11-05T17:50:25.2975115Z         os.link(hl_a, hl_b)
2025-11-05T17:50:25.2975413Z     
2025-11-05T17:50:25.2975672Z         cmd(archiver, "create", "test0", "input")
2025-11-05T17:50:25.2976179Z         os.unlink(hl_a)  # Don't duplicate warning message - one is enough.
2025-11-05T17:50:25.2976668Z         cmd(archiver, "create", "test1", "input")
2025-11-05T17:50:25.2977013Z     
2025-11-05T17:50:25.2977441Z         # Moral equivalent of test_multiple_link_exclusion in borg v1.x... see #8344
2025-11-05T17:50:25.2978076Z         # Borg v2 doesn't have this issue comparing hard-links, so we'll defer to
2025-11-05T17:50:25.2978567Z         # POSIX behavior:
2025-11-05T17:50:25.2979063Z         # https://pubs.opengroup.org/onlinepubs/9799919799/functions/unlink.html
2025-11-05T17:50:25.2979791Z         # Upon successful completion, unlink() shall mark for update the last data modification
2025-11-05T17:50:25.2980545Z         # and last file status change timestamps of the parent directory. Also, if the
2025-11-05T17:50:25.2981194Z         # file's link count is not 0, the last file status change timestamp of the
2025-11-05T17:50:25.2981858Z         # file shall be marked for update.
2025-11-05T17:50:25.2982294Z         output = cmd(
2025-11-05T17:50:25.2982809Z             archiver, "diff", "--pattern=+ fm:input/b", "--pattern=! **/", "test0", "test1", exit_code=EXIT_SUCCESS
2025-11-05T17:50:25.2983356Z         )
2025-11-05T17:50:25.2983604Z         lines = output.splitlines()
2025-11-05T17:50:25.2983956Z         # Directory was excluded.
2025-11-05T17:50:25.2984318Z         assert_line_not_exists(lines, "input/a$")
2025-11-05T17:50:25.2984680Z         # Remaining hardlink
2025-11-05T17:50:25.2985071Z         assert_line_exists(lines, "ctime:.*input/b/hardlink")
2025-11-05T17:50:25.2985584Z         assert_line_not_exists(lines, ".*mtime:.*input/b/hardlink")
2025-11-05T17:50:25.2986036Z         # Deleted hardlink was excluded
2025-11-05T17:50:25.2986486Z         assert_line_not_exists(lines, "input/a/hardlink$")
2025-11-05T17:50:25.2986869Z     
2025-11-05T17:50:25.2987133Z         # Now try again, except with no patterns!
2025-11-05T17:50:25.2987633Z         output = cmd(archiver, "diff", "test0", "test1", exit_code=EXIT_SUCCESS)
2025-11-05T17:50:25.2988410Z         lines = output.splitlines()
2025-11-05T17:50:25.2988942Z         # Directory... preferably, let's not care about order differences are presented.
2025-11-05T17:50:25.2989554Z         assert_line_exists(lines, "[cm]time:.*[cm]time:.*input/a")
2025-11-05T17:50:25.2989990Z         # Remaining hardlink
2025-11-05T17:50:25.2990368Z         assert_line_exists(lines, "ctime:.*input/b/hardlink")
2025-11-05T17:50:25.2990867Z         assert_line_not_exists(lines, ".*mtime:.*input/b/hardlink")
2025-11-05T17:50:25.2991313Z         # Deleted hardlink
2025-11-05T17:50:25.2991835Z         assert_line_exists(lines, "removed:.*input/a/hardlink")
2025-11-05T17:50:25.2992250Z     
2025-11-05T17:50:25.2992618Z         # Now recreate the unlinked file as a different entity with identical
2025-11-05T17:50:25.2993089Z         # contents.
2025-11-05T17:50:25.2993481Z         create_regular_file(archiver.input_path, hl_a, contents=b"123456")
2025-11-05T17:50:25.2993995Z         cmd(archiver, "create", "test2", "input")
2025-11-05T17:50:25.2994358Z     
2025-11-05T17:50:25.2994582Z         # Compare test0 and test2.
2025-11-05T17:50:25.2995039Z         output = cmd(archiver, "diff", "test0", "test2", exit_code=EXIT_SUCCESS)
2025-11-05T17:50:25.2995720Z         lines = output.splitlines()
2025-11-05T17:50:25.2996096Z         # Adding a file changes c/mtime.
2025-11-05T17:50:25.2996540Z         assert_line_exists(lines, "[cm]time:.*[cm]time:.*input/a$")
2025-11-05T17:50:25.2997104Z         # Different c/mtime but no apparent changes (i.e. perms) or content
2025-11-05T17:50:25.2997745Z         # modifications should be a hint that something hard-link related is going on.
2025-11-05T17:50:25.2998347Z         assert_line_exists(lines, "[cm]time:.*[cm]time:.*input/a/hardlink")
2025-11-05T17:50:25.2998923Z         assert_line_not_exists(lines, "modified.*B.*input/a/hardlink")
2025-11-05T17:50:25.2999459Z         assert_line_not_exists(lines, "-[r-][w-][x-].*input/a/hardlink")
2025-11-05T17:50:25.3000057Z         # ctime changed because the hard-link count went down. But no mtime changes
2025-11-05T17:50:25.3000693Z         # because file content isn't modified. No permissions changes either.
2025-11-05T17:50:25.3001286Z         # This is another hint that something hard-link related changed.
2025-11-05T17:50:25.3002012Z         assert_line_exists(lines, "ctime:.*input/b/hardlink")
2025-11-05T17:50:25.3002522Z         assert_line_not_exists(lines, ".*mtime:.*input/b/hardlink")
2025-11-05T17:50:25.3003079Z         assert_line_not_exists(lines, "modified.*B.*input/b/hardlink")
2025-11-05T17:50:25.3003627Z         assert_line_not_exists(lines, "-[r-][w-][x-].*input/b/hardlink")
2025-11-05T17:50:25.3004075Z     
2025-11-05T17:50:25.3004327Z         # Finally, compare test1 and test2.
2025-11-05T17:50:25.3004833Z         output = cmd(archiver, "diff", "test1", "test2", exit_code=EXIT_SUCCESS)
2025-11-05T17:50:25.3005349Z         lines = output.splitlines()
2025-11-05T17:50:25.3005752Z         # Same situation applies as previous diff for a.
2025-11-05T17:50:25.3006260Z         assert_line_exists(lines, "[cm]time:.*[cm]time:.*input/a$")
2025-11-05T17:50:25.3006811Z         # From test1 to test2's POV, the a/hardlink file is a fresh new file.
2025-11-05T17:50:25.3007379Z         assert_line_exists(lines, "added.*B.*input/a/hardlink")
2025-11-05T17:50:25.3007866Z         # But the b/hardlink file was not modified at all.
2025-11-05T17:50:25.3008351Z >       assert_line_not_exists(lines, ".*input/b/hardlink")
2025-11-05T17:50:25.3008655Z 
2025-11-05T17:50:25.3008999Z /home/runner/work/borg/borg/src/borg/testsuite/archiver/diff_cmd_test.py:516: 
2025-11-05T17:50:25.3009617Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2025-11-05T17:50:25.3009911Z 
2025-11-05T17:50:25.3010644Z lines = ['[mtime: Wed, 2025-11-05 17:45:53 +0000 -> Wed, 2025-11-05 17:45:53 +0000] [ctime: Wed, 2025-11-05 17:45:53 +0000 -> ...05 17:45:53 +0000 -> Wed, 2025-11-05 17:45:53 +0000] input/b/hardlink', 'added:                  6 B input/a/hardlink']
2025-11-05T17:50:25.3012049Z expected_regexpr = '.*input/b/hardlink'
2025-11-05T17:50:25.3012331Z 
2025-11-05T17:50:25.3012539Z     def assert_line_not_exists(lines, expected_regexpr):
2025-11-05T17:50:25.3012995Z >       assert not any(
2025-11-05T17:50:25.3013375Z             re.search(expected_regexpr, line) for line in lines
2025-11-05T17:50:25.3013895Z         ), f"unexpected match for {expected_regexpr} in {lines}"
2025-11-05T17:50:25.3015405Z E       AssertionError: unexpected match for .*input/b/hardlink in ['[mtime: Wed, 2025-11-05 17:45:53 +0000 -> Wed, 2025-11-05 17:45:53 +0000] [ctime: Wed, 2025-11-05 17:45:53 +0000 -> Wed, 2025-11-05 17:45:53 +0000] input/a', '[ctime: Wed, 2025-11-05 17:45:53 +0000 -> Wed, 2025-11-05 17:45:53 +0000] input/b/hardlink', 'added:                  6 B input/a/hardlink']
2025-11-05T17:50:25.3018750Z E       assert not True
2025-11-05T17:50:25.3019341Z E        +  where True = any(<generator object assert_line_not_exists.<locals>.<genexpr> at 0x12f2bfd758a0>)
2025-11-05T17:50:25.3019864Z 
2025-11-05T17:50:25.3020250Z /home/runner/work/borg/borg/src/borg/testsuite/archiver/__init__.py:362: AssertionError
2025-11-05T17:50:25.3021191Z =========================== short test summary info ============================
2025-11-05T17:50:25.3029458Z FAILED src/borg/testsuite/archiver/diff_cmd_test.py::test_hard_link_deletion_and_replacement[archiver] - AssertionError: unexpected match for .*input/b/hardlink in ['[mtime: Wed, 2025-11-05 17:45:53 +0000 -> Wed, 2025-11-05 17:45:53 +0000] [ctime: Wed, 2025-11-05 17:45:53 +0000 -> Wed, 2025-11-05 17:45:53 +0000] input/a', '[ctime: Wed, 2025-11-05 17:45:53 +0000 -> Wed, 2025-11-05 17:45:53 +0000] input/b/hardlink', 'added:                  6 B input/a/hardlink']
2025-11-05T17:50:25.3031350Z assert not True
2025-11-05T17:50:25.3032052Z  +  where True = any(<generator object assert_line_not_exists.<locals>.<genexpr> at 0x12f2bfd758a0>)
2025-11-05T17:50:25.3032789Z =========== 1 failed, 1592 passed, 388 skipped in 347.92s (0:05:47) ============

ThomasWaldmann avatar Nov 05 '25 18:11 ThomasWaldmann

Tried to fix this one:

  • It seems there is a ctime change for the b hardlink for unknown reasons.
  • When trying to add stat calls + debug output, the test failure vanishes.
  • When removing the stat calls and the debug output again and adding a granularity_sleep, it fails again.

@cr1901 Do you have an idea? Test fails can be seen in CI for freebsd.

If we can't fix this, I tend to just remove this test, see also the troubles in #9153.

ThomasWaldmann avatar Nov 09 '25 17:11 ThomasWaldmann