From fbc3c223a6be27d108f8c9663f443b375d7289ff Mon Sep 17 00:00:00 2001 From: Joey Hess Date: Wed, 13 Jul 2022 17:13:54 -0400 Subject: [PATCH] filter-process: Fix protocol for empty files This caused git to complain that filter-process failed and kill it with signal 15. Because it wrote an extra flushPkt for an empty file, which git did not expect, and so git saw an unexpected response to the next request. Luckily, filter-process is only used by default in v9 and up, and v8 is still the default. Also, git had to be updating an empty file, followed by another file, which is a fairly unlikely situation. And git restarts filter-process after this happens and uses it to filter the rest of the files. So this isn't a crippling bug. Sponsored-by: Luke Shumaker on Patreon --- CHANGELOG | 2 + Git/FilterProcess.hs | 4 +- ...nnex_filter-process_died_of_signal_15.mdwn | 2 + ..._5ebfc18008cf4bc21ffce57067314fc0._comment | 85 +++++++++++++++++++ ..._c74018853a4da8e609da1803051a6893._comment | 14 +++ ..._0a80393f055ead9a3a62da0aa4ec3298._comment | 54 ++++++++++++ ..._8b27c6099afea7011717492f53fcdac4._comment | 7 ++ 7 files changed, 167 insertions(+), 1 deletion(-) create mode 100644 doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_2_5ebfc18008cf4bc21ffce57067314fc0._comment create mode 100644 doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_3_c74018853a4da8e609da1803051a6893._comment create mode 100644 doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_4_0a80393f055ead9a3a62da0aa4ec3298._comment create mode 100644 doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_5_8b27c6099afea7011717492f53fcdac4._comment 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! +"""]]