mirrors/git-annex
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages 1 Wiki Activity Actions

filter-process: Fix protocol for empty files

Browse source 
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
This commit is contained in:
Joey Hess 2022-07-13 17:13:54 -04:00
parent 1b680d330b
commit fbc3c223a6
No known key found for this signature in database
GPG key ID: DB12DB0FF05F8F38
7 changed files with 167 additions and 1 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
CHANGELOG
View file

@ -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

4
Git/FilterProcess.hs
View file

@ -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

2
doc/bugs/error__58___git-annex_filter-process_died_of_signal_15.mdwn
View file

@ -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]]

85
doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_2_5ebfc18008cf4bc21ffce57067314fc0._comment Normal file
View file

@ -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.
"""]

14
doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_3_c74018853a4da8e609da1803051a6893._comment Normal file
View file

@ -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.
"""]]

54
doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_4_0a80393f055ead9a3a62da0aa4ec3298._comment Normal file
View file

@ -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.
"""]]

7
doc/bugs/error__58___git-annex_filter-process_died_of_signal_15/comment_5_8b27c6099afea7011717492f53fcdac4._comment Normal file
View file

@ -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!
"""]]