diff --git a/CHANGELOG b/CHANGELOG index 5f9c5dcd61..eb210d72ea 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -8,6 +8,8 @@ git-annex (10.20220625) UNRELEASED; urgency=medium build flag enabled. * add: Fix reversion when adding an annex link that has been moved to another directory. (Introduced in version 10.20220624) + * filter-process: Fix a bug involving handling of empty files, + that caused git to kill git-annex filter-process. -- Joey Hess Tue, 28 Jun 2022 14:49:17 -0400 diff --git a/Git/FilterProcess.hs b/Git/FilterProcess.hs index 57541a0b73..7e04e46118 100644 --- a/Git/FilterProcess.hs +++ b/Git/FilterProcess.hs @@ -162,7 +162,9 @@ respondFilterRequest b = do send b' = let (pktline, rest) = encodePktLine b' in do - writePktLine stdout pktline + if isFlushPkt pktline + then return () + else writePktLine stdout pktline case rest of Just b'' -> send b'' Nothing -> writePktLine stdout flushPkt diff --git a/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15.mdwn b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15.mdwn index 83d302a17b..136ae77dbb 100644 --- a/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15.mdwn +++ b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15.mdwn @@ -97,3 +97,5 @@ FWIW, I'm not using lfs. ### Have you had any luck using git-annex before? (Sometimes we get tired of reading bug reports all day and a lil' positive end note does wonders) Otherwise, it's great. + +> [[fixed|done]] --[[Joey]] diff --git a/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_2_5ebfc18008cf4bc21ffce57067314fc0._comment b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_2_5ebfc18008cf4bc21ffce57067314fc0._comment new file mode 100644 index 0000000000..4ef52812d5 --- /dev/null +++ b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_2_5ebfc18008cf4bc21ffce57067314fc0._comment @@ -0,0 +1,85 @@ +[[!comment format=mdwn + username="joey" + subject="""comment 2""" + date="2022-07-13T19:53:44Z" + content=""" +Just reproduced this. In my big repo, I had commit +eab6ac8b34be1d7c36df2a2f41a9414cf5908041 checked out +and ran `git reset --hard fbbe4045871f` + +Git reported that it updated 112465 files, and near to the beginning, +filter-process died of signal 15. + +Even better, it is reproducible, going back to that +starting commit and running that command again works every time! + +And I got a strace too. Here is the git command: + + write(5, "0013command=smudge\n", 19) = 19 + write(5, "0019pathname=new/cleanup\n", 25) = 25 + write(5, "0035treeish=fbbe4045871fb749299b"..., 53) = 53 + write(5, "0032blob=baad2545defeae59f526ea3"..., 50) = 50 + write(5, "0000", 4) = 4 + write(5, "0322", 4) = 4 + write(5, "#!/bin/sh\n\ngit commit -m 'pre cl"..., 798) = 798 + write(5, "0000", 4) = 4 + read(6, "0000", 4) = 4 + rt_sigaction(SIGPIPE, {sa_handler=0x563cf8debb50, sa_mask=[PIPE], sa_flags=SA_RES + TORER|SA_RESTART, sa_restorer=0x7fab5717c920}, {sa_handler=SIG_IGN, sa_mask=[PIPE + ], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fab5717c920}, 8) = 0 + write(2, "error: external filter 'git-anne"..., 57) = 57 + kill(1638045, SIGTERM) = 0 + +So git sends SIGTERM when it gets unhappy with the response it got from +git-annex filter-process. + +Here is where git runs git-annex filter-process via the shell: + + execve("/bin/sh", ["/bin/sh", "-c", "git-annex filter-process", "git-annex filter-process"], 0x563cfacbfb40 /* 68 vars */) = 0 + ... + newfstatat(AT_FDCWD, "/home/joey/bin/git-annex", {st_mode=S_IFREG|0755, st_size=72524080, ...}, 0) = 0 + rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], NULL, 8) = 0 + vfork() = 1631132 + rt_sigprocmask(SIG_SETMASK, [], ~[KILL STOP RTMIN RT_1], 8) = 0 + wait4(-1, 0x7fff910d697c, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) + --- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=1631129, si_uid=1000} --- + +++ killed by SIGTERM +++ + +But the actual git-annex process read the last thing git wrote to it, +replied, and keeps running until it later reads an EOF from git. + + write(1, "0000", 4) = 4 + poll([{fd=0, events=POLLIN}], 1, 0) = 0 (Timeout) + epoll_ctl(4, EPOLL_CTL_MOD, 0, {EPOLLIN|EPOLLONESHOT, {u32=0, u64=287065581021036544}}) = 0 + futex(0x67fe568, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0 + futex(0x67fe570, FUTEX_WAKE_PRIVATE, 1) = 0 + futex(0x67fe68c, FUTEX_WAKE_PRIVATE, 1) = 1 + read(0, "0013command=smudge\n0019pathname=new/cleanup\n0035treeish=fbbe4045871fb749299b4484862645bd9a7f175a\n0032blob=baad2545defeae59f526ea3d64174398899cb9cc\n00000322", 8192) = 155 + poll([{fd=0, events=POLLIN}], 1, 0) = 1 ([{fd=0, revents=POLLIN}]) + futex(0x67fe688, FUTEX_WAKE_PRIVATE, 1) = 1 + futex(0x67fe690, FUTEX_WAKE_PRIVATE, 1) = 0 + read(0, "#!/bin/sh....", 8192) = 802 + futex(0x67fe56c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable) + futex(0x67fe570, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable) + futex(0x67fe570, FUTEX_WAKE_PRIVATE, 1) = 0 + poll([{fd=1, events=POLLOUT}], 1, 0) = 1 ([{fd=1, revents=POLLOUT}]) + futex(0x67fe68c, FUTEX_WAKE_PRIVATE, 1) = 1 + futex(0x67fe690, FUTEX_WAKE_PRIVATE, 1) = 0 + write(1, "0013status=success\n", 19) = 19 + futex(0x67fe568, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0 + futex(0x67fe570, FUTEX_WAKE_PRIVATE, 1) = 0 + poll([{fd=1, events=POLLOUT}], 1, 0) = 1 ([{fd=1, revents=POLLOUT}]) + write(1, "0000", 4) = 4 + poll([{fd=1, events=POLLOUT}], 1, 0) = 1 ([{fd=1, revents=POLLOUT}]) + write(1, "0322#!/bin/sh...", 802) = 802 + poll([{fd=1, events=POLLOUT}], 1, 0) = 1 ([{fd=1, revents=POLLOUT}]) + write(1, "0000", 4) = 4 + poll([{fd=1, events=POLLOUT}], 1, 0) = 1 ([{fd=1, revents=POLLOUT}]) + write(1, "0000", 4) = 4 + poll([{fd=0, events=POLLIN}], 1, 0) = 0 (Timeout) + +Git does not see that 0013status=success response though. It sees "0000", +which must be the one that git-annex wrote earlier (top of above strace). + +So, this seems like a protocol problem of some kind. +"""] diff --git a/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_3_c74018853a4da8e609da1803051a6893._comment b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_3_c74018853a4da8e609da1803051a6893._comment new file mode 100644 index 0000000000..93f088f6c0 --- /dev/null +++ b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_3_c74018853a4da8e609da1803051a6893._comment @@ -0,0 +1,14 @@ +[[!comment format=mdwn + username="joey" + subject="""comment 3""" + date="2022-07-13T20:32:03Z" + content=""" +I also saw this when adding a single file to git: + + joey@darkstar:/tmp/a1>touch .foo.lck + joey@darkstar:/tmp/a1>git add .foo.lck + error: external filter 'git-annex filter-process' failed + error: git-annex filter-process died of signal 15 + +But, I have not succeeded to reproduce that again. This was in a v9 repository BTW. +"""]] diff --git a/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_4_0a80393f055ead9a3a62da0aa4ec3298._comment b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_4_0a80393f055ead9a3a62da0aa4ec3298._comment new file mode 100644 index 0000000000..004b6170d0 --- /dev/null +++ b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_4_0a80393f055ead9a3a62da0aa4ec3298._comment @@ -0,0 +1,54 @@ +[[!comment format=mdwn + username="joey" + subject="""comment 4""" + date="2022-07-13T20:35:53Z" + content=""" +Feeling like this is most likley a pkt-line protocol bug in git-annex, and +probably one inovlving empty files. Both because of the prior comment with +the empty file and it turns out there is also an empty file in my first +reproducer. + +Here is a `GIT_TRACE_PACKET=1` log when reproducing it. I have omitted +the actual content of my files.. + + 16:30:18.248308 pkt-line.c:80 packet: git> command=smudge + 16:30:18.248335 pkt-line.c:80 packet: git> pathname=new/.updater + 16:30:18.248344 pkt-line.c:80 packet: git> treeish=fbbe4045871fb749299b4484862645bd9a7f175a + 16:30:18.248352 pkt-line.c:80 packet: git> blob=dd75da379e8a2cad5a793d352e7def865d65158d + 16:30:18.248358 pkt-line.c:80 packet: git> 0000 + 16:30:18.248397 pkt-line.c:80 packet: git> #!/bin/sh.... + 16:30:18.248409 pkt-line.c:80 packet: git> 0000 + 16:30:18.248637 pkt-line.c:80 packet: git< status=success + 16:30:18.248728 pkt-line.c:80 packet: git< 0000 + 16:30:18.248806 pkt-line.c:80 packet: git< #!/bin/sh.... + 16:30:18.248818 pkt-line.c:80 packet: git< 0000 + 16:30:18.248826 pkt-line.c:80 packet: git< 0000 + 16:30:18.248985 pkt-line.c:80 packet: git> command=smudge + 16:30:18.249007 pkt-line.c:80 packet: git> pathname=new/.updater.lock + 16:30:18.249017 pkt-line.c:80 packet: git> treeish=fbbe4045871fb749299b4484862645bd9a7f175a + 16:30:18.249024 pkt-line.c:80 packet: git> blob=e69de29bb2d1d6434b8b29ae775ad8c2e48c5391 + 16:30:18.249031 pkt-line.c:80 packet: git> 0000 + 16:30:18.249037 pkt-line.c:80 packet: git> 0000 + 16:30:18.249245 pkt-line.c:80 packet: git< status=success + 16:30:18.249262 pkt-line.c:80 packet: git< 0000 + 16:30:18.249270 pkt-line.c:80 packet: git< 0000 + 16:30:18.249277 pkt-line.c:80 packet: git< 0000 + 16:30:18.280842 pkt-line.c:80 packet: git> command=smudge + 16:30:18.280882 pkt-line.c:80 packet: git> pathname=new/cleanup + 16:30:18.280891 pkt-line.c:80 packet: git> treeish=fbbe4045871fb749299b4484862645bd9a7f175a + 16:30:18.280898 pkt-line.c:80 packet: git> blob=baad2545defeae59f526ea3d64174398899cb9cc + 16:30:18.280904 pkt-line.c:80 packet: git> 0000 + 16:30:18.280932 pkt-line.c:80 packet: git> #!/bin/sh... + 16:30:18.280942 pkt-line.c:80 packet: git> 0000 + 16:30:18.280953 pkt-line.c:80 packet: git< 0000 + error: external filter 'git-annex filter-process' failed + error: git-annex filter-process died of signal 15 + +Now, from git's perspective, the last response of "0000" does look wrong. +It should have been "status=success" followed by "0000" and then the file +content, and then "0000" and "0000" again. + +But as seen in the strace, git-annex sends more than that. + +My guess is that git-annex is sending one 0000 too many for an empty file. +"""]] diff --git a/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_5_8b27c6099afea7011717492f53fcdac4._comment b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_5_8b27c6099afea7011717492f53fcdac4._comment new file mode 100644 index 0000000000..0ba99290ca --- /dev/null +++ b/doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_5_8b27c6099afea7011717492f53fcdac4._comment @@ -0,0 +1,7 @@ +[[!comment format=mdwn + username="joey" + subject="""comment 5""" + date="2022-07-13T21:11:07Z" + content=""" +Indeed, I put in a special case for empty files and solved this! +"""]]