git annex test never exits?

Please describe the problem.

I got a new server for the repronim project (welcome typhon to the family of smaug, drogon, and falkor). Wanted to redo https://www.datalad.org/test_fs_analysis.html benchmarking. Added git annex test call to see how its time would vary across file systems etc.

My surprise was that my script never exited.

Current ps tree is (yeah, running as root, likely will reinstall the thing anyways fully after I am done benchmarking)

root      185696  0.0  0.0  62536 54768 pts/1    S+   Nov15   2:56           python test_fs.py benchmark
root     3655423  0.0  0.0   2484   516 pts/1    S+   Nov18   0:00             /bin/sh -c cd test9; git annex test
root     3655424  0.0  0.0   9728  3340 pts/1    S+   Nov18   0:00               git annex test
root     3655425  0.0  0.0 1076293924 28360 pts/1 Sl+ Nov18   0:00                 /usr/bin/git-annex test
root     3696268  0.2  0.0 1074196636 41932 pts/1 Sl+ Nov18  13:14                   /usr/bin/git-annex --color=never test
root     3710526  0.0  0.0 1074122856 44736 pts/1 Sl+ Nov18   0:00                     /usr/bin/git-annex move --to origin foo
root     3710593  0.0  0.0      0     0 pts/1    Z+   Nov18   0:00                       [git] <defunct>
root     3710594  0.0  0.0      0     0 pts/1    Z+   Nov18   0:00                       [git] <defunct>
root     3710595  0.0  0.0      0     0 pts/1    Z+   Nov18   0:00                       [git] <defunct>
root     3710596  0.0  0.0      0     0 pts/1    Z+   Nov18   0:00                       [git] <defunct>
root     3710597  0.0  0.0   2484   516 pts/1    S+   Nov18   0:00                       sh -c git-annex test --fakessh -- 'localhost' 'git-annex-shell '"'"'p2pstdio'"'"' '"'"'/mnt/test/test9/.t/75/main0'"'"' '"'"'6129b8ec-34af-47d1-b7e6-3c4fcc0d33e3'"'"' --uuid c129397d-8209-40ea-8347-16a8c3fe69de'
root     3710598  0.0  0.0 1074048960 20408 pts/1 Sl+ Nov18   0:00                         git-annex test --fakessh -- localhost git-annex-shell 'p2pstdio' '/mnt/test/test9/.t/75/main0' '6129b8ec-34af-47d1-b7e6-3c4fcc0d33e3' --uuid c129397d-8209-40ea-8347-16a8c3fe69de
root     3710604  0.0  0.0   2484   580 pts/1    S+   Nov18   0:00                           /bin/sh -c git-annex-shell 'p2pstdio' '/mnt/test/test9/.t/75/main0' '6129b8ec-34af-47d1-b7e6-3c4fcc0d33e3' --uuid c129397d-8209-40ea-8347-16a8c3fe69de
root     3710605  0.0  0.0 1074122860 18948 pts/1 Sl+ Nov18   2:39                             git-annex-shell p2pstdio /mnt/test/test9/.t/75/main0 6129b8ec-34af-47d1-b7e6-3c4fcc0d33e3 --uuid c129397d-8209-40ea-8347-16a8c3fe69de

What version of git-annex are you using? On what operating system?

git-annex version: 10.20221003
build flags: Assistant Webapp Pairing Inotify DBus DesktopNotify TorrentParser MagicMime Benchmark Feeds Testsuite S3 WebDAV
dependency versions: aws-0.22 bloomfilter-2.0.1.0 cryptonite-0.26 DAV-1.3.4 feed-1.3.0.1 ghc-8.8.4 http-client-0.6.4.1 persistent-sqlite-2.10.6.2 torrent-10000.1.1 uuid-1.3.13 yesod-1.6.1.0
key/value backends: SHA256E SHA256 SHA512E SHA512 SHA224E SHA224 SHA384E SHA384 SHA3_256E SHA3_256 SHA3_512E SHA3_512 SHA3_224E SHA3_224 SHA3_384E SHA3_384 SKEIN256E SKEIN256 SKEIN512E SKEIN512 BLAKE2B256E BLAKE2B256 BLAKE2B512E BLAKE2B512 BLAKE2B160E BLAKE2B160 BLAKE2B224E BLAKE2B224 BLAKE2B384E BLAKE2B384 BLAKE2BP512E BLAKE2BP512 BLAKE2S256E BLAKE2S256 BLAKE2S160E BLAKE2S160 BLAKE2S224E BLAKE2S224 BLAKE2SP256E BLAKE2SP256 BLAKE2SP224E BLAKE2SP224 SHA1E SHA1 MD5E MD5 WORM URL X*
remote types: git gcrypt p2p S3 bup directory rsync web bittorrent webdav adb tahoe glacier ddar git-lfs httpalso borg hook external
operating system: linux x86_64
supported repository versions: 8 9 10
upgrade supported from repository versions: 0 1 2 3 4 5 6 7 8 9 10

any ideas? need access to troubleshoot?

fixed --Joey

RSS Atom

comment 1

Seems like the test it is stuck in is "move (ssh remote)".

Is this replicable?

I wonder if test_fs.py is doing something that causes the problem. There is some complexity in there. Maybe it's happening on one particular FS.

If it happens when not run by test_fs.py, it would be useful to get a debug log, because I think that seeing the P2P protocol dump would help explain what has happened.

There was not a good way to get the test suite to output a full debug log, so I had to implement one. With an updated build of git-annex, you can use:

git-annex test -J1 --test-debug

Here's the expected output of that section of the test suite, when it is working properly:

move foo [2022-11-28 14:54:11.10011679] (Utility.Process) process [390399] chat: sh ["-c","git-annex test --fakessh -- 'localhost' 'git-annex-shell '"'"'p2pstdio'"'"' '"'"'/home/joey/src/git-annex/.t/3/main1'"'"' '"'"'--debug'"'"' '"'"'c76e0406-38ea-413e-9fb0-56cc32847734'"'"' --uuid 000c7285-ec19-4c15-9c67-4dd4b7c74775'"]
[2022-11-28 14:54:11.129754519] (P2P.IO) [ThreadId 4] P2P > AUTH-SUCCESS 000c7285-ec19-4c15-9c67-4dd4b7c74775
[2022-11-28 14:54:11.130259741] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P < AUTH-SUCCESS 000c7285-ec19-4c15-9c67-4dd4b7c74775
[2022-11-28 14:54:11.13041388] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P > VERSION 1
[2022-11-28 14:54:11.130680315] (P2P.IO) [ThreadId 4] P2P < VERSION 1
[2022-11-28 14:54:11.13087982] (P2P.IO) [ThreadId 4] P2P > VERSION 1
[2022-11-28 14:54:11.131127415] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P < VERSION 1
[2022-11-28 14:54:11.131262307] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P > CHECKPRESENT SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77
[2022-11-28 14:54:11.131679501] (P2P.IO) [ThreadId 4] P2P < CHECKPRESENT SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77
[2022-11-28 14:54:11.132388822] (P2P.IO) [ThreadId 4] P2P > FAILURE
[2022-11-28 14:54:11.13261351] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P < FAILURE
(to origin...) 
[2022-11-28 14:54:11.135583194] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P > PUT foo SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77
[2022-11-28 14:54:11.136134981] (P2P.IO) [ThreadId 4] P2P < PUT foo SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77
[2022-11-28 14:54:11.136824468] (P2P.IO) [ThreadId 4] P2P > PUT-FROM 0
[2022-11-28 14:54:11.137123219] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P < PUT-FROM 0
...
[2022-11-28 14:54:11.148194515] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P > DATA 20
[2022-11-28 14:54:11.148414855] (P2P.IO) [ThreadId 4] P2P < DATA 20
[2022-11-28 14:54:11.148739395] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P > VALID
^M100%  20 B              2 KiB/s 0s[2022-11-28 14:54:11.152428942] (P2P.IO) [ThreadId 4] P2P < VALID
...
[2022-11-28 14:54:11.177599567] (P2P.IO) [ThreadId 4] P2P > SUCCESS
[2022-11-28 14:54:11.177858296] (P2P.IO) [ssh connection Just 390399] [ThreadId 4] P2P < SUCCESS

Comment by joey — Mon Nov 28 18:11:41 2022

Remove comment

comment 2

I examined this situation on the machine. I had to ctrl-z the process to get a shell.

Then I checked what the stdin of 3710605 was, and it was still open, and was a pipe from 3710526. So that's why the p2pstdio process was still running; that pipe should be closed when the parent git-annex is done, but the parent was apparently stuck on something.

Then I straced 3710605 but it was suspended (oops). So I ran fg. This somehow unstuck everything! The test suite finished up very fast.

Here is what it output for the test that had gotten stuck:

Tests
  Repo Tests v8 unlocked
    Init Tests
      init:            OK (2.54s)
      add:             OK (5.48s)
    move (ssh remote): FAIL (958561.16s)
      ./Test/Framework.hs:398:
      bad content in location log for foo key SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77 uuid UUID "c129397d-8209-40ea-8347-16a8c3fe69de"
      expected: True
       but got: False

That seems like it must come from here in the test suite:

    git_annex "move" ["--to", "origin", annexedfile] "move --to of file"
    inmainrepo $ annexed_present annexedfile

So it seems that the content was moved back to origin successfully (annexed_present checks that the object file is present before checking the location log), but that the location log didn't get updated. Need to check if that update would have been done by the p2pstdio process or the move process.

Why would a SIGCONT have unstuck it I wonder?

I have re-ran the command to see if the bug replicates..

Comment by joey — Tue Nov 29 21:45:15 2022

Remove comment

comment 3

I have re-ran the command to see if the bug replicates..

note: it was considerable amount of time (days?) for it to take there I made a copy test_fs_testonly.py where I removed all other "benchmarks" prior running annex test -- might get there faster if works so feel free to interrupt and rerun that one. That code is old (circa 2014 ;)) , and I should do some face lift but haven't had a chance yet :-/

Comment by yarikoptic — Tue Nov 29 22:25:42 2022

Remove comment

comment 4

The rerun did not get stuck. So it's not something directly the fault of the script running git-annex test, I think.

Comment by joey — Mon Dec 5 17:48:52 2022

Remove comment

comment 5

what kind of a "fault" could it be?

Comment by yarikoptic — Mon Dec 5 18:08:02 2022

Remove comment

comment 6

Well, a specific filesystem or mount option that the script sets up, for example.

Or if it's something of that kind, it's also intermittent.

This will limit the test suite to only running the that test:

git-annex test --pattern '/move (ssh remote)/ && /Repo Tests v8 unlocked/'

I have that repeating locally in a loop, in case it's just something that happens every 1000 test runs or something like that.

(I've patched git-annex to speed up the above command 400%.)

Comment by joey — Wed Dec 7 16:36:44 2022

Remove comment

comment 7

Very good news! Reproduced the hang on kite, after 500 iterations of test suite.

All 0 tests passed (0.01s)
Tests
  Repo Tests v10 adjusted unlocked branch
    Init Tests
      init:            OK (0.44s)
      add:             OK (0.81s)
    move (ssh remote):

strace of the git-annex move process:

joey@kite:~/tmp>strace  -p 1710605 -f
strace: Process 1710605 attached with 6 threads
[pid 1710671] futex(0x7fab6801c398, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710614] futex(0x5a21968, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710613] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 1710611] futex(0x4868648, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 1710610] futex(0x4868648, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710605] futex(0x5a2164c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710611] <... futex resumed>)      = 0
[pid 1710610] <... futex resumed>)      = -1 EAGAIN (Resource temporarily unavailable)
[pid 1710611] epoll_wait(3,  <unfinished ...>
[pid 1710610] futex(0x48685e0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 1710611] <... epoll_wait resumed>[], 64, 0) = 0
[pid 1710610] <... futex resumed>)      = 0
[pid 1710611] epoll_wait(3,  <unfinished ...>
[pid 1710610] read(10,  <unfinished ...>
[pid 1710611] <... epoll_wait resumed>[], 64, 0) = 0
[pid 1710610] <... read resumed>"\344\16\0\0\0\0\0\0", 8) = 8
[pid 1710611] epoll_wait(3,  <unfinished ...>
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] write(9, "\377\0\0\0\0\0\0\0", 8 <unfinished ...>
[pid 1710613] <... restart_syscall resumed>) = 1
[pid 1710610] <... write resumed>)      = 8
[pid 1710613] read(9,  <unfinished ...>
[pid 1710610] read(10,  <unfinished ...>
[pid 1710613] <... read resumed>"\377\0\0\0\0\0\0\0", 8) = 8
[pid 1710613] futex(0x5a21968, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 1710614] <... futex resumed>)      = 0
[pid 1710613] <... futex resumed>)      = 1
[pid 1710613] poll([{fd=7, events=POLLIN}, {fd=9, events=POLLIN}], 2, -1 <unfinished ...>
[pid 1710614] futex(0x5a21970, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 1710614] sched_getaffinity(0, 128, [0, 1]) = 8
[pid 1710614] rt_sigprocmask(SIG_BLOCK, [HUP INT QUIT TERM CONT TSTP], [], 8) = 0
[pid 1710610] <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] read(10,  <unfinished ...>
[pid 1710614] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 1710614] futex(0x5a2196c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710610] <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710610] futex(0x486864c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY

Strace of the child:

joey@kite:~/tmp>strace  -p 1710650 -f
strace: Process 1710650 attached with 6 threads
[pid 1710658] futex(0x51ef9ec, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710655] futex(0x51ef7ec, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710653] read(10,  <unfinished ...>
[pid 1710650] fcntl(12, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>
[pid 1710673] futex(0x7f6ec001c3e8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710657] futex(0x7f6ed0000bf8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 1710653] <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 1710653] read(10, "\1\0\0\0\0\0\0\0", 8) = 8

Which looks like it's blocked on taking a lock of /home/joey/tmp/.t/3/main0/.git/annex/restage.lck

Comment by joey — Wed Dec 7 18:19:19 2022

Remove comment

comment 8

Oh interesting, the same process has restage.lck open twice.

lrwx------ 1 joey joey 64 Dec  7 14:20 /proc/1710650/fd/12 -> /home/joey/tmp/.t/3/main0/.git/annex/restage.lck
lrwx------ 1 joey joey 64 Dec  7 16:53 /proc/1710650/fd/16 -> /home/joey/tmp/.t/3/main0/.git/annex/restage.lck

There are other processes that have the same restage.lck open too. In the process tree below, pid 1710382 does, and so does pid 1710483.

1710368 pts/8    S+     0:00 sh -c git-annex test --fakessh -- 'localhost' 'git-annex-shell '"'"'p2pstdio'"'"' '"'"'/home/joey/tmp/.t/3/main0'"'"' '"'"'6e958d13-c3cb-4c78-a360-e14308368520'"'"' --uuid 3a4d8ec8-3f33-4b80-bd67-119b1c65fc88'
1710369 pts/8    Sl+    0:00  \_ git-annex test --fakessh -- localhost git-annex-shell 'p2pstdio' '/home/joey/tmp/.t/3/main0' '6e958d13-c3cb-4c78-a360-e14308368520' --uuid 3a4d8ec8-3f33-4b80-bd67-119b1c65fc88
1710380 pts/8    S+     0:00      \_ /bin/sh -c git-annex-shell 'p2pstdio' '/home/joey/tmp/.t/3/main0' '6e958d13-c3cb-4c78-a360-e14308368520' --uuid 3a4d8ec8-3f33-4b80-bd67-119b1c65fc88
1710382 pts/8    Sl+    0:00          \_ git-annex-shell p2pstdio /home/joey/tmp/.t/3/main0 6e958d13-c3cb-4c78-a360-e14308368520 --uuid 3a4d8ec8-3f33-4b80-bd67-119b1c65fc88
1710411 pts/8    S+     0:00              \_ git --git-dir=/home/joey/tmp/.t/3/main0/.git --work-tree=/home/joey/tmp/.t/3/main0 --literal-pathspecs cat-file --batch
1710476 pts/8    S+     0:00              \_ git --git-dir=/home/joey/tmp/.t/3/main0/.git --work-tree=/home/joey/tmp/.t/3/main0 --literal-pathspecs -c core.safecrlf=false update-index -q --refresh -z --stdin
1710479 pts/8    S+     0:00                  \_ /bin/sh -c git-annex filter-process git-annex filter-process
1710483 pts/8    Sl+    0:21                      \_ git-annex filter-process
1710504 pts/8    S+     0:00                          \_ git --git-dir=.git --work-tree=. --literal-pathspecs cat-file --batch-check=%(objectname) %(objecttype) %(objectsize)
1710506 pts/8    S+     0:00                          \_ git --git-dir=.git --work-tree=. --literal-pathspecs cat-file --batch
1710533 pts/8    S+     0:00                          \_ git --git-dir=.git --work-tree=. --literal-pathspecs hash-object -w --stdin-paths --no-filters
1710540 pts/8    S+     0:00                          \_ git --git-dir=.git --work-tree=. --literal-pathspecs cat-file --batch

64 Dec  7 17:01 /proc/1710382/fd/13 -> /home/joey/tmp/.t/3/main0/.git/annex/restage.lck
64 Dec  7 16:53 /proc/1710483/fd/11 -> /home/joey/tmp/.t/3/main0/.git/annex/restage.lck
64 Dec  7 16:53 /proc/1710483/fd/19 -> /home/joey/tmp/.t/3/main0/.git/annex/restage.lck

(Strange that pid 1710368 is not a child process of the main git-annex test run. I'm unsure why that happens. )

Stracing 1710483, it is also stuck on fcntl F_SETLKW. This looks like it may be the main deadlock, because the parent is waiting on git update-index, which is waiting on git-annex filter-process, which is stuck waiting to take the lock... which its parent is holding!

(There are also several other process trees, running git-annex test --fakessh, that have gotten deparented from the main test run, and are hanging around. Those also have restage.lck open, though in their cases it is a since-deleted file.)

I think this is a bug in restagePointerFiles, which uses streamRestageLog while refreshIndex is running. The restage.log was added 2 months ago, in 6a3bd283b8af53f810982e002e435c0d7c040c59.

I suspect that git-annex filter-process is running populatePointerFile via Command.Smudge.getMoveRaceRecovery, which needs to write to the restage.log. That would explain why the deadlock only happens sometimes, because it involves a race that triggers that code.

Reading the whole restage.log into memory first would probably avoid the bug, but is not ideal.

Comment by joey — Wed Dec 7 20:55:35 2022

Remove comment

comment 9

I've developed a fix. Gonna re-run the reproducer long enough to be sure the bug is squashed..

Comment by joey — Thu Dec 8 18:07:47 2022

Remove comment

comment 10

The retest seemed to hang again, but I'm not sure I was testing the right binary. Running it again.

This patch exposes when the lock is held and so illustrates the bug reliably and quickly:

diff --git a/Command/Smudge.hs b/Command/Smudge.hs
index a5d8871998..cf6e2973f8 100644
--- a/Command/Smudge.hs
+++ b/Command/Smudge.hs
@@ -127,7 +129,8 @@ clean'
    -> (Key -> Annex ())
    -- ^ emitpointer: Emit a pointer file for the key.
    -> Annex ()
-clean' file mk passthrough discardreststdin emitpointer =
+clean' file mk passthrough discardreststdin emitpointer = do
+   calcRestageLog () (\_ _ -> ())
    ifM (fileOutsideRepo file)
        ( passthrough
        , inSmudgeCleanFilter go

With that patch, the unfixed git-annex hangs immediately. With my fix, it does not hang, which seems to show I fixed it correctly..

Comment by joey — Fri Dec 9 16:16:10 2022

Remove comment

comment 11

Got a clean test run with the right binary for sure, and I've confirmed this bug is really fixed. Test ran 20k iterations successfully.

Comment by joey — Sat Dec 10 16:02:15 2022

Remove comment

Add a comment