Re: do people find t5504.8 flaky?

From: SZEDER Gábor <szeder.dev@gmail.com>
Date: Nov 13, 2019, 00:07 UTC
Message-ID: <20191113000747.GQ4348@szeder.dev>
In-Reply-To: <20190423030254.GA19604@sigill.intra.peff.net>

On Mon, Apr 22, 2019 at 11:02:54PM -0400, Jeff King wrote:

Show 10 quoted lines

> 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

Show 18 quoted lines

> 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