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

diff --git a/CHANGELOG b/CHANGELOG
index 5f9c5dcd61ce018a87a3edeb83645fd9b2fb6e47..eb210d72ea40376a3afeeb2742b46f3c5f9abeb6 100644 (file)
--- 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 <id@joeyh.name>  Tue, 28 Jun 2022 14:49:17 -0400
 

diff --git a/Git/FilterProcess.hs b/Git/FilterProcess.hs
index 57541a0b7355a0c835c8ebc5b60beee1c60f649f..7e04e46118d22fb82586a9ff8fd0670bad9be9c1 100644 (file)
--- 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 83d302a17bb348edbfadb1ee368debaa8dee2f52..136ae77dbb39d4a7e4a912ac31a3da30eb1e11e6 100644 (file)
--- 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 (file)
index 0000000..4ef5281
--- /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 (file)
index 0000000..93f088f
--- /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 (file)
index 0000000..004b617
--- /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 (file)
index 0000000..0ba9929
--- /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!
+"""]]