On Mon, Apr 22, 2019 at 11:02:54PM -0400, Jeff King wrote:
> On Tue, Apr 23, 2019 at 11:45:17AM +0900, Junio C Hamano wrote:
>
> > I have been seeing occasional failures of t5504-fetch-receive-strict
> > test on the cc/replace-graft-peel-tags topic, but it seems that the
> > fork point of that topic from the mainline already fails the same
> > step #8, only less frequently.
> >
> > The push is rejected as expected, but the remote side that receives
> > the "push" fails and the local side does not leave an expected
> > output we expect when the test fails.
I've seen it fail a few times on Travis CI, but it's rare, much rarer
than our "avarage" flaky test failures.
The subsequent test t5504.9 is flaky as well: the two tests are
essentially the same, they only differ in the configuration variable
that enables the fsck checks.
> No, I haven't seen it fail, nor does running with --stress turn up
> anything.
I can reproduce the failure fairly quickly with '-r 1,8 --stress' (and
nr of jobs = 4x cores).
FWIW, I enabled GIT_TRACE_PACKET and the relevant part of the failure
looks like this [1]:
+ test_must_fail env GIT_TRACE_PACKET=/home/szeder/src/git/t/trash directory.t5504-fetch-receive-strict.stress-8/trace-packet git push --porcelain dst master:refs/heads/test
remote: fatal: object of unexpected type
error: remote unpack failed: unpack-objects abnormal exit
error: failed to push some refs to 'dst'
+ cat trace-packet
packet: receive-pack> 0000000000000000000000000000000000000000 capabilities^{}\0report-status delete-refs side-band-64k quiet atomic ofs-delta agent=git/2.24.0.1.g52e0cf1d06
packet: receive-pack> 0000
packet: push< 0000000000000000000000000000000000000000 capabilities^{}\0report-status delete-refs side-band-64k quiet atomic ofs-delta agent=git/2.24.0.1.g52e0cf1d06
packet: push< 0000
packet: push> 0000000000000000000000000000000000000000 a7943252b7679bec6b9679dbc7863c08610ac2bc refs/heads/test\0 report-status side-band-64k quiet agent=git/2.24.0.1.g52e0cf1d06
packet: push> 0000
packet: receive-pack< 0000000000000000000000000000000000000000 a7943252b7679bec6b9679dbc7863c08610ac2bc refs/heads/test\0 report-status side-band-64k quiet agent=git/2.24.0.1.g52e0cf1d06
packet: receive-pack< 0000
packet: sideband< \2fatal: object of unexpected type
packet: receive-pack> unpack unpack-objects abnormal exit
packet: receive-pack> ng refs/heads/test unpacker error
packet: receive-pack> 0000
packet: sideband< \10028unpack unpack-objects abnormal exit0026ng refs/heads/test unpacker error0000
packet: receive-pack> 0000
packet: sideband< 0000
packet: push< unpack unpack-objects abnormal exit
+ test_cmp exp act
--- exp 2019-11-12 23:40:33.131679990 +0000
+++ act 2019-11-12 23:40:33.203680114 +0000
@@ -1,2 +0,0 @@
-To dst
-! refs/heads/master:refs/heads/test [remote rejected] (unpacker error)
error: last command exited with $?=1
not ok 8 - push with receive.fsckobjects
Note that 'sideband< 0000' is not the last packet.
For comparison, here is the packet trace from a successful test run:
+ cat trace-packet
packet: receive-pack> 0000000000000000000000000000000000000000 capabilities^{}\0report-status delete-refs side-band-64k quiet atomic ofs-delta agent=git/2.24.0.1.g52e0cf1d06
packet: receive-pack> 0000
packet: push< 0000000000000000000000000000000000000000 capabilities^{}\0report-status delete-refs side-band-64k quiet atomic ofs-delta agent=git/2.24.0.1.g52e0cf1d06
packet: push< 0000
packet: push> 0000000000000000000000000000000000000000 38af865a0f3f0170ef7a18edcb3088d3f7961b21 refs/heads/test\0 report-status side-band-64k quiet agent=git/2.24.0.1.g52e0cf1d06
packet: push> 0000
packet: receive-pack< 0000000000000000000000000000000000000000 38af865a0f3f0170ef7a18edcb3088d3f7961b21 refs/heads/test\0 report-status side-band-64k quiet agent=git/2.24.0.1.g52e0cf1d06
packet: receive-pack< 0000
packet: sideband< \2fatal: object of unexpected type
packet: receive-pack> unpack unpack-objects abnormal exit
packet: receive-pack> ng refs/heads/test unpacker error
packet: receive-pack> 0000
packet: sideband< \10028unpack unpack-objects abnormal exit0026ng refs/heads/test unpacker error0000
packet: push< unpack unpack-objects abnormal exit
packet: push< ng refs/heads/test unpacker error
packet: push< 0000
packet: receive-pack> 0000
packet: sideband< 0000
Note that 'sideband< 0000' is the final packet.
Whether this confirms Peff's theories below, I don't know; sideband
always makes me dizzy :)
FWIW, I could reproduce the failure on ef7e93d908 (do not override
receive-pack errors, 2012-02-13) as well, i.e. on the commit that
started checking 'git push's output.
Hope it helps.
[1] Note the lack of a dozen or so '-x' trace lines from
'test_must_fail' and 'test_cmp' ;) Current WIP patch at:
https://github.com/szeder/git/commit/52e0cf1d0695c107142e36905dfdbaceacdacf8c
> But looking at the test I would not be at all surprised if we
> have races around error hangups. I believe that index-pack will die
> unceremoniously as soon as something fails to pass its fsck check.
>
> The client will keep sending data, and may hit a SIGPIPE (or the network
> equivalent), depending on how much slack there is in the buffers,
> whether we hit the problem as a base object or after we receive
> everything and start resolving deltas, etc.
>
> I think after seeing a fatal error we probably ought to consider pumping
> the rest of the bytes from the client to /dev/null. That's wasteful, but
> it's the only clean way to get a message back, I think. It would also
> give us the opportunity to complain about other objects, too, if there
> are multiple (it might make sense to abort before resolving deltas,
> though; at that point we have all of the data and that phase is very CPU
> intensive).
>
> -Peff
