t5559-http-fetch-smart-http2 failures

t5559-http-fetch-smart-http2 failures

[Todd Zullinger]

Hi,

I started seeing failures in rc0 but I was distracted by the
long weekend.

The changes in 73c49a4474 (t: run t5551 tests with both HTTP
and HTTP/2, 2022-11-11) seem to rather frequently trigger
test failures on Fedora.

The most frequent test to fail is "large fetch-pack requests
can be sent using chunked encoding" (t5559.30), but earlier
tests have also failed on occasion.  For the common failure,
the test exits with:

    expecting success of 5559.30 'large fetch-pack requests can be sent using chunked encoding': 
	    GIT_TRACE_CURL=true git -c http.postbuffer=65536 \
		    clone --bare "$HTTPD_URL/smart/repo.git" split.git 2>err &&
	    {
		    test_have_prereq HTTP2 ||
		    grep "^=> Send header: Transfer-Encoding: chunked" err
	    }
    +++ GIT_TRACE_CURL=true
    +++ git -c http.postbuffer=65536 clone --bare http://127.0.0.1:5559/smart/repo.git split.git
    error: last command exited with $?=128
    not ok 30 - large fetch-pack requests can be sent using chunked encoding

(Less frequently, I've seen the last command exit 141.)

I haven't been able to track down the problem, which happens
a lot on the Fedora build system but less often during local
builds.  Obviously, the bug is too shy to show itself while
anyone is watching. ;)

I can easily disable the failing tests for a bit, but does
anyone have an idea what might be the cause or how to better
debug it when it occurs on a buildsystem without direct
access?

Thanks,

-- 
Todd

Re: t5559-http-fetch-smart-http2 failures

[Jeff King]

On Wed, Nov 30, 2022 at 05:09:34PM -0500, Todd Zullinger wrote:

> The changes in 73c49a4474 (t: run t5551 tests with both HTTP
> and HTTP/2, 2022-11-11) seem to rather frequently trigger
> test failures on Fedora.

Thanks for the report. I can't seem to reproduce here on my Debian
system, even with --stress.

I can try a Fedora chroot or vm, but it may take some time to set up. It
also sounds like you're not able to reproduce it locally on a Fedora
system? Have you tried "./t5559-* --stress"?

> The most frequent test to fail is "large fetch-pack requests
> can be sent using chunked encoding" (t5559.30), but earlier
> tests have also failed on occasion.  For the common failure,
> the test exits with:
> 
>     expecting success of 5559.30 'large fetch-pack requests can be sent using chunked encoding': 
> 	    GIT_TRACE_CURL=true git -c http.postbuffer=65536 \
> 		    clone --bare "$HTTPD_URL/smart/repo.git" split.git 2>err &&
> 	    {
> 		    test_have_prereq HTTP2 ||
> 		    grep "^=> Send header: Transfer-Encoding: chunked" err
> 	    }
>     +++ GIT_TRACE_CURL=true
>     +++ git -c http.postbuffer=65536 clone --bare http://127.0.0.1:5559/smart/repo.git split.git
>     error: last command exited with $?=128
>     not ok 30 - large fetch-pack requests can be sent using chunked encoding
> 
> (Less frequently, I've seen the last command exit 141.)

Interesting. 141 implies SIGPIPE, but that may be a red herring. The
operation isn't supposed to fail, but if it does due to the server
bailing, then the client sometimes hitting SIGPIPE is a known unrelated
problem.

Is it possible to see the contents of "err" here? That will have the
message from the client, but also the curl trace, which is probably
helpful.

It might also be interesting to see the server's view, which would be in
httpd/error.log in the trash directory (also access.log, but probably
that is not interesting).

> I can easily disable the failing tests for a bit, but does
> anyone have an idea what might be the cause or how to better
> debug it when it occurs on a buildsystem without direct
> access?

If t5551 isn't failing similarly, then presumably the problem is either:

  1. There is some race or bad interaction between curl and apache
     speaking http2 (possibly a buggy version of one?)

  2. http2 requires using mpm_event instead of mpm_prefork. Maybe this
     introduces problems with apache on this system?

  3. there is a bug in git. ;) This is always a possibility, of course,
     but we literally do nothing differently from our end, except pass
     it to curl via CURLOPT_HTTP_VERSION.

It would be interesting to see if doing this:

diff --git a/t/lib-httpd/apache.conf b/t/lib-httpd/apache.conf
index 0294739a77..b24ca44a95 100644
--- a/t/lib-httpd/apache.conf
+++ b/t/lib-httpd/apache.conf
@@ -73,16 +73,9 @@ LockFile accept.lock
 	LoadModule unixd_module modules/mod_unixd.so
 </IfModule>
 
-<IfDefine HTTP2>
 <IfModule !mod_mpm_event.c>
 	LoadModule mpm_event_module modules/mod_mpm_event.so
 </IfModule>
-</IfDefine>
-<IfDefine !HTTP2>
-<IfModule !mod_mpm_prefork.c>
-	LoadModule mpm_prefork_module modules/mod_mpm_prefork.so
-</IfModule>
-</IfDefine>
 </IfVersion>
 
 PassEnv GIT_VALGRIND

also causes t5551 to start failing. If so, then we can blame mpm_event,
and not http2.

-Peff

Re: t5559-http-fetch-smart-http2 failures

[Todd Zullinger]

Sorry for the delay.  I wanted to gather some data but could
only do it in small chunks at a time.  Hopefully that
doesn't make this too rambling and/or disjointed.

One upside is that I finally got around to teaching the
Fedora builds to include not just the failing test output,
but tar up the contents of test-results and any trash
directories on failures.  That makes it easier to poke
around when a build fails on a remote build system where I
can't get a shell. :)

Jeff King wrote:
> On Wed, Nov 30, 2022 at 05:09:34PM -0500, Todd Zullinger wrote:
> 
>> The changes in 73c49a4474 (t: run t5551 tests with both HTTP
>> and HTTP/2, 2022-11-11) seem to rather frequently trigger
>> test failures on Fedora.
> 
> Thanks for the report. I can't seem to reproduce here on my Debian
> system, even with --stress.

One notable difference between Debian/Ubuntu and Fedora is
that Debian/Ubuntu uses mod_http2 included with the upstream
Apache httpd source.  Fedora is using the newer, stand-alone
module (which is the upstream source for the http2 module).

Ubuntu 22.04.1 has httpd-2.4.52 with mod_http2-1.15.26 (per
MOD_HTTP2_VERSION in modules/http2/h2_version.h).

Fedora 37, 36, and rawhide have httpd-httpd-2.4.54 with
mod_http2-2.0.9.  They also have curl-7.86 in rawhide (where
I've done the most testing), 7.85.0 in 37, and 7.82.0 in 36.

Interestingly, if I build the same git source rpm against
RHEL-9 which has httpd-2.4.53 and mod_http2-1.15.19, I don't
see any failures.

I'm tempted to do a build of mod_http2-1.x or the embedded
mod_http2 and test with that, but I have not yet made time
to do so.

Searching for errors similar to what I found in the test
failures, I found an old curl issue and a related Fedora
bug:

    https://github.com/curl/curl/issues/3750
    https://bugzilla.redhat.com/show_bug.cgi?id=1690971

Of course, these are from 2019 so you'd think this
particular issue was long-gone.  But perhaps with mod_http2
still being actively developed, similar bugs can crop up.

> I can try a Fedora chroot or vm, but it may take some time to set up. It
> also sounds like you're not able to reproduce it locally on a Fedora
> system? Have you tried "./t5559-* --stress"?

I had, but at the time the failures I got seemed unrelated,
particularly because they triggered on earlier tests and
somewhat randomly.

After I changed the test to append $test_count to err so I
could see the reason for the failure more clearly, I think
they are more similar.

With --stress, http2 fails at various points with errors
like:

    expecting success of 5559.6 'fetch changes via http': 
	    echo content >>file &&
	    git commit -a -m two &&
	    git push public &&
	    (cd clone && git pull) &&
	    test_cmp file clone/file

    +++ echo content
    +++ git commit -a -m two
    [main 5647d5f] two
     Author: A U Thor <author@example.com>
     1 file changed, 1 insertion(+)
    +++ git push public
    To /builddir/build/BUILD/git-2.39.0.rc2/t/trash directory.t5559-http-fetch-smart-http2.stress-13/httpd/www/repo.git
       f39a923..5647d5f  main -> main
    +++ cd clone
    +++ git pull
    error: RPC failed; curl 16 Error in the HTTP2 framing layer
    fatal: expected flush after ref listing
    error: last command exited with $?=1
    not ok 6 - fetch changes via http

or sometimes with the same error in test 30, as below.

>> The most frequent test to fail is "large fetch-pack requests
>> can be sent using chunked encoding" (t5559.30), but earlier
>> tests have also failed on occasion.  For the common failure,
>> the test exits with:
>> 
>>     expecting success of 5559.30 'large fetch-pack requests can be sent using chunked encoding': 
>> 	    GIT_TRACE_CURL=true git -c http.postbuffer=65536 \
>> 		    clone --bare "$HTTPD_URL/smart/repo.git" split.git 2>err &&
>> 	    {
>> 		    test_have_prereq HTTP2 ||
>> 		    grep "^=> Send header: Transfer-Encoding: chunked" err
>> 	    }
>>     +++ GIT_TRACE_CURL=true
>>     +++ git -c http.postbuffer=65536 clone --bare http://127.0.0.1:5559/smart/repo.git split.git
>>     error: last command exited with $?=128
>>     not ok 30 - large fetch-pack requests can be sent using chunked encoding
>> 
>> (Less frequently, I've seen the last command exit 141.)
> 
> Interesting. 141 implies SIGPIPE, but that may be a red herring. The
> operation isn't supposed to fail, but if it does due to the server
> bailing, then the client sometimes hitting SIGPIPE is a known unrelated
> problem.
> 
> Is it possible to see the contents of "err" here? That will have the
> message from the client, but also the curl trace, which is probably
> helpful.

Appending -$test_count to err in all the places it's used in
the test helped here, e.g.:

    sed -Ei 's/\berr\b/&-$test_count/' t/t5551-http-fetch-smart.sh

With that, one of the more common errors is:

    error: RPC failed; HTTP 101 curl 92 HTTP/2 stream 1 was not closed cleanly before end of the underlying stream

others are:

    error: RPC failed; HTTP 101 curl 16 Error in the HTTP2 framing layer
    fatal: expected flush after ref listing

    error: RPC failed; HTTP 101 curl 16 Error in the HTTP2 framing layer

    error: RPC failed; curl 16 Error in the HTTP2 framing layer 
    fatal: expected 'packfile'

The full err output is usually around 5k lines, so it's not
ideal for inclusion here, but I've saved a number of them
and can either extract portions or post them somewhere and
link to them, if you think they might be useful.

> It might also be interesting to see the server's view, which would be in
> httpd/error.log in the trash directory (also access.log, but probably
> that is not interesting).

The error.log looks the same for the failed runs I've
collected:

    [Tue Dec 06 16:35:40.840250 2022] [mpm_event:notice] [pid 298654:tid 298654] AH00489: Apache/2.4.54 (Fedora Linux) configured -- resuming normal operations
    [Tue Dec 06 16:35:40.840388 2022] [core:notice] [pid 298654:tid 298654] AH00094: Command line: '/usr/sbin/httpd -d /tmp/git-t.oOfy/trash directory.t5559-http-fetch-smart-http2/httpd -f /builddir/build/BUILD/git-2.39.0.rc2/t/lib-httpd/apache.conf -D HTTP2 -c Listen 127.0.0.1:5559'
    [Tue Dec 06 16:35:42.372099 2022] [cgi:error] [pid 298658:tid 298768] [remote 127.0.0.1:55644] AH01215: stderr from /builddir/build/BUILD/git-2.39.0.rc2/git-http-backend: Unsupported service: getanyfile
    [Tue Dec 06 16:35:46.209758 2022] [cgi:error] [pid 300664:tid 300695] [client 127.0.0.1:60712] AH01215: stderr from /builddir/build/BUILD/git-2.39.0.rc2/git-http-backend: fatal: git upload-pack: not our ref 51c0379e3f0bea4537b50664334a941865f61b94
    [Tue Dec 06 16:35:46.912816 2022] [cgi:error] [pid 298659:tid 298663] [remote 127.0.0.1:60718] AH01215: stderr from /builddir/build/BUILD/git-2.39.0.rc2/git-http-backend: fatal: git upload-pack: not our ref 51c0379e3f0bea4537b50664334a941865f61b94
    [Tue Dec 06 16:35:53.962296 2022] [auth_basic:error] [pid 300664:tid 300707] [client 127.0.0.1:60926] AH01618: user bogus not found: /auth/smart/repo.git/info/refs
    [Tue Dec 06 16:35:56.627946 2022] [auth_basic:error] [pid 300664:tid 300713] [client 127.0.0.1:37644] AH01617: user user@host: authentication failure for "/auth/smart/repo.git/info/refs": Password Mismatch
    [Tue Dec 06 16:35:58.185699 2022] [mpm_event:notice] [pid 298654:tid 298654] AH00491: caught SIGTERM, shutting down

The LogLevel might need to be adjusted to get more useful
output there, perhaps?

> If t5551 isn't failing similarly, then presumably the problem is either:
> 
>   1. There is some race or bad interaction between curl and apache
>      speaking http2 (possibly a buggy version of one?)
> 
>   2. http2 requires using mpm_event instead of mpm_prefork. Maybe this
>      introduces problems with apache on this system?
> 
>   3. there is a bug in git. ;) This is always a possibility, of course,
>      but we literally do nothing differently from our end, except pass
>      it to curl via CURLOPT_HTTP_VERSION.
> 
> It would be interesting to see if doing this:
> 
> diff --git a/t/lib-httpd/apache.conf b/t/lib-httpd/apache.conf
> index 0294739a77..b24ca44a95 100644
> --- a/t/lib-httpd/apache.conf
> +++ b/t/lib-httpd/apache.conf
> @@ -73,16 +73,9 @@ LockFile accept.lock
>  	LoadModule unixd_module modules/mod_unixd.so
>  </IfModule>
>  
> -<IfDefine HTTP2>
>  <IfModule !mod_mpm_event.c>
>  	LoadModule mpm_event_module modules/mod_mpm_event.so
>  </IfModule>
> -</IfDefine>
> -<IfDefine !HTTP2>
> -<IfModule !mod_mpm_prefork.c>
> -	LoadModule mpm_prefork_module modules/mod_mpm_prefork.so
> -</IfModule>
> -</IfDefine>
>  </IfVersion>
>  
>  PassEnv GIT_VALGRIND
> 
> also causes t5551 to start failing. If so, then we can blame mpm_event,
> and not http2.

Good idea.  With that applied, I've still not seen a failure
in t5551, not even when run via --stress for some minutes.

I'm not sure whether any of this points to a bug in Git's
http2 code at all.  It _seems_ like it's going to be
elsewhere, in curl and/or httpd/mod_http2.  In other words,
your 1 above.

If nothing jumps out to point to a possible issue in git,
I'll extract a reproduction recipe from the test suite and
file a Fedora bug.  Maybe the folks who have looked at
similar issues in curl and httpd/mod_http2 will spot
something.

Thanks!

-- 
Todd

Re: t5559-http-fetch-smart-http2 failures

[Jeff King]

On Thu, Dec 08, 2022 at 09:20:00PM -0500, Todd Zullinger wrote:

> Sorry for the delay.  I wanted to gather some data but could
> only do it in small chunks at a time.  Hopefully that
> doesn't make this too rambling and/or disjointed.

No problem. I would be happy if all bug reports were this thorough and
clear. :)

> > Thanks for the report. I can't seem to reproduce here on my Debian
> > system, even with --stress.
> 
> One notable difference between Debian/Ubuntu and Fedora is
> that Debian/Ubuntu uses mod_http2 included with the upstream
> Apache httpd source.  Fedora is using the newer, stand-alone
> module (which is the upstream source for the http2 module).
> 
> Ubuntu 22.04.1 has httpd-2.4.52 with mod_http2-1.15.26 (per
> MOD_HTTP2_VERSION in modules/http2/h2_version.h).

Makes sense. I'm on Debian unstable, which is httpd-2.4.54 and
mod_http2-1.15.28 (the latter I pulled from "strings mod_http2.so", so
uh...it's probably right).

> Fedora 37, 36, and rawhide have httpd-httpd-2.4.54 with
> mod_http2-2.0.9.  They also have curl-7.86 in rawhide (where
> I've done the most testing), 7.85.0 in 37, and 7.82.0 in 36.

So that's the same httpd and curl version (7.86.0) I'm using, which
implies to me the problem is in the newer mod_http2 version. And...

> Interestingly, if I build the same git source rpm against
> RHEL-9 which has httpd-2.4.53 and mod_http2-1.15.19, I don't
> see any failures.

...that data point would be consistent with the theory.

> I'm tempted to do a build of mod_http2-1.x or the embedded
> mod_http2 and test with that, but I have not yet made time
> to do so.

Yeah, I suspect it would make the problem go away. In theory it may even
be possible to bisect within mod_http2, but I don't know how painful it
is to do a build+test cycle.

> With that, one of the more common errors is:
> 
>     error: RPC failed; HTTP 101 curl 92 HTTP/2 stream 1 was not closed cleanly before end of the underlying stream
> 
> others are:
> 
>     error: RPC failed; HTTP 101 curl 16 Error in the HTTP2 framing layer
>     fatal: expected flush after ref listing
> 
>     error: RPC failed; HTTP 101 curl 16 Error in the HTTP2 framing layer
> 
>     error: RPC failed; curl 16 Error in the HTTP2 framing layer 
>     fatal: expected 'packfile'

OK, that makes me pretty confident that there's nothing Git is doing
wrong here. I don't think we could stimulate a failure at that layer of
curl even if we wanted to. And those errors plus the racy nature of what
you're seeing really makes it look like there is just some race
condition or other bug in mod_http2 (possibly coupled with the mpm).

> The error.log looks the same for the failed runs I've
> collected:
> [...]
> The LogLevel might need to be adjusted to get more useful
> output there, perhaps?

Yeah, that output is not particularly enlightening. In a sense it's not
surprising, though. If there's a bug on the server side, we're not
likely to get a log line saying "sending garbage output to the client".
It's the client who sees the problem and hangs up. Turning up the log
level could help, but I'd be surprised.

> > also causes t5551 to start failing. If so, then we can blame mpm_event,
> > and not http2.
> 
> Good idea.  With that applied, I've still not seen a failure
> in t5551, not even when run via --stress for some minutes.

OK. So I think that rules out mpm_event being a problem by itself. It's
possible there's some bad interaction between mpm_event and mod_http2,
but it seems more likely there's simply a bug or race in mod_http2.

> I'm not sure whether any of this points to a bug in Git's
> http2 code at all.  It _seems_ like it's going to be
> elsewhere, in curl and/or httpd/mod_http2.  In other words,
> your 1 above.

My best guess is a bug in mod_http2. But one thing that it still _could_
be is that Git's server-side CGI interacts badly with mod_http2 somehow
(or maybe only some versions of it).

I guess some other things to try would be:

  1. Take Git out of the mix completely. If we stress-test command-line
     curl hitting our test apache, serving up static files, can we
     trigger the problem? If not, then...

  2. Try the same thing, but hit endpoints that trigger git-http-backend
     on the server side. If that fails, then we've absolved Git's client
     code, and the bug is either in mod_http2 or some bad interaction
     with Git's CGI output.

> If nothing jumps out to point to a possible issue in git,
> I'll extract a reproduction recipe from the test suite and
> file a Fedora bug.  Maybe the folks who have looked at
> similar issues in curl and httpd/mod_http2 will spot
> something.

You might try running the failing tests with GIT_TRACE_CURL set in the
environment. That should get you a pretty detailed view of what curl is
seeing, which would probably be helpful for a bug report.

-Peff