{"thread":{"id":"58879","subject":"t5559-http-fetch-smart-http2 failures","startedAt":"2022-11-30T22:10:28Z","lastAt":"2022-12-09T20:59:52Z","messageCount":4,"participants":["Todd Zullinger","Jeff King"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"468289","messageId":"Y4fUntdlc1mqwad5@pobox.com","threadId":"58879","inReplyTo":null,"subject":"t5559-http-fetch-smart-http2 failures","fromName":"Todd Zullinger","fromEmail":"tmz@pobox.com","sentAt":"2022-11-30T22:09:34Z","receivedAt":"2022-11-30T22:10:28Z","isPatch":false,"sender":{"key":"tmz@pobox.com","avatar":"https://avatars.githubusercontent.com/u/806319?v=4"},"body":"Hi,\n\nI started seeing failures in rc0 but I was distracted by the\nlong weekend.\n\nThe changes in 73c49a4474 (t: run t5551 tests with both HTTP\nand HTTP/2, 2022-11-11) seem to rather frequently trigger\ntest failures on Fedora.\n\nThe most frequent test to fail is \"large fetch-pack requests\ncan be sent using chunked encoding\" (t5559.30), but earlier\ntests have also failed on occasion.  For the common failure,\nthe test exits with:\n\n    expecting success of 5559.30 'large fetch-pack requests can be sent using chunked encoding': \n\t    GIT_TRACE_CURL=true git -c http.postbuffer=65536 \\\n\t\t    clone --bare \"$HTTPD_URL/smart/repo.git\" split.git 2>err &&\n\t    {\n\t\t    test_have_prereq HTTP2 ||\n\t\t    grep \"^=> Send header: Transfer-Encoding: chunked\" err\n\t    }\n    +++ GIT_TRACE_CURL=true\n    +++ git -c http.postbuffer=65536 clone --bare http://127.0.0.1:5559/smart/repo.git split.git\n    error: last command exited with $?=128\n    not ok 30 - large fetch-pack requests can be sent using chunked encoding\n\n(Less frequently, I've seen the last command exit 141.)\n\nI haven't been able to track down the problem, which happens\na lot on the Fedora build system but less often during local\nbuilds.  Obviously, the bug is too shy to show itself while\nanyone is watching. ;)\n\nI can easily disable the failing tests for a bit, but does\nanyone have an idea what might be the cause or how to better\ndebug it when it occurs on a buildsystem without direct\naccess?\n\nThanks,\n\n-- \nTodd\n"},{"id":"468352","messageId":"Y4kNu9iFQuKjuub1@coredump.intra.peff.net","threadId":"58879","inReplyTo":"Y4fUntdlc1mqwad5@pobox.com","subject":"Re: t5559-http-fetch-smart-http2 failures","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2022-12-01T20:25:31Z","receivedAt":"2022-12-01T20:25:41Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Nov 30, 2022 at 05:09:34PM -0500, Todd Zullinger wrote:\n\n> The changes in 73c49a4474 (t: run t5551 tests with both HTTP\n> and HTTP/2, 2022-11-11) seem to rather frequently trigger\n> test failures on Fedora.\n\nThanks for the report. I can't seem to reproduce here on my Debian\nsystem, even with --stress.\n\nI can try a Fedora chroot or vm, but it may take some time to set up. It\nalso sounds like you're not able to reproduce it locally on a Fedora\nsystem? Have you tried \"./t5559-* --stress\"?\n\n> The most frequent test to fail is \"large fetch-pack requests\n> can be sent using chunked encoding\" (t5559.30), but earlier\n> tests have also failed on occasion.  For the common failure,\n> the test exits with:\n> \n>     expecting success of 5559.30 'large fetch-pack requests can be sent using chunked encoding': \n> \t    GIT_TRACE_CURL=true git -c http.postbuffer=65536 \\\n> \t\t    clone --bare \"$HTTPD_URL/smart/repo.git\" split.git 2>err &&\n> \t    {\n> \t\t    test_have_prereq HTTP2 ||\n> \t\t    grep \"^=> Send header: Transfer-Encoding: chunked\" err\n> \t    }\n>     +++ GIT_TRACE_CURL=true\n>     +++ git -c http.postbuffer=65536 clone --bare http://127.0.0.1:5559/smart/repo.git split.git\n>     error: last command exited with $?=128\n>     not ok 30 - large fetch-pack requests can be sent using chunked encoding\n> \n> (Less frequently, I've seen the last command exit 141.)\n\nInteresting. 141 implies SIGPIPE, but that may be a red herring. The\noperation isn't supposed to fail, but if it does due to the server\nbailing, then the client sometimes hitting SIGPIPE is a known unrelated\nproblem.\n\nIs it possible to see the contents of \"err\" here? That will have the\nmessage from the client, but also the curl trace, which is probably\nhelpful.\n\nIt might also be interesting to see the server's view, which would be in\nhttpd/error.log in the trash directory (also access.log, but probably\nthat is not interesting).\n\n> I can easily disable the failing tests for a bit, but does\n> anyone have an idea what might be the cause or how to better\n> debug it when it occurs on a buildsystem without direct\n> access?\n\nIf t5551 isn't failing similarly, then presumably the problem is either:\n\n  1. There is some race or bad interaction between curl and apache\n     speaking http2 (possibly a buggy version of one?)\n\n  2. http2 requires using mpm_event instead of mpm_prefork. Maybe this\n     introduces problems with apache on this system?\n\n  3. there is a bug in git. ;) This is always a possibility, of course,\n     but we literally do nothing differently from our end, except pass\n     it to curl via CURLOPT_HTTP_VERSION.\n\nIt would be interesting to see if doing this:\n\ndiff --git a/t/lib-httpd/apache.conf b/t/lib-httpd/apache.conf\nindex 0294739a77..b24ca44a95 100644\n--- a/t/lib-httpd/apache.conf\n+++ b/t/lib-httpd/apache.conf\n@@ -73,16 +73,9 @@ LockFile accept.lock\n \tLoadModule unixd_module modules/mod_unixd.so\n </IfModule>\n \n-<IfDefine HTTP2>\n <IfModule !mod_mpm_event.c>\n \tLoadModule mpm_event_module modules/mod_mpm_event.so\n </IfModule>\n-</IfDefine>\n-<IfDefine !HTTP2>\n-<IfModule !mod_mpm_prefork.c>\n-\tLoadModule mpm_prefork_module modules/mod_mpm_prefork.so\n-</IfModule>\n-</IfDefine>\n </IfVersion>\n \n PassEnv GIT_VALGRIND\n\nalso causes t5551 to start failing. If so, then we can blame mpm_event,\nand not http2.\n\n-Peff\n"},{"id":"468814","messageId":"Y5KbUBC1ENOAVuTV@pobox.com","threadId":"58879","inReplyTo":"Y4kNu9iFQuKjuub1@coredump.intra.peff.net","subject":"Re: t5559-http-fetch-smart-http2 failures","fromName":"Todd Zullinger","fromEmail":"tmz@pobox.com","sentAt":"2022-12-09T02:20:00Z","receivedAt":"2022-12-09T02:20:16Z","isPatch":false,"sender":{"key":"tmz@pobox.com","avatar":"https://avatars.githubusercontent.com/u/806319?v=4"},"body":"Sorry for the delay.  I wanted to gather some data but could\nonly do it in small chunks at a time.  Hopefully that\ndoesn't make this too rambling and/or disjointed.\n\nOne upside is that I finally got around to teaching the\nFedora builds to include not just the failing test output,\nbut tar up the contents of test-results and any trash\ndirectories on failures.  That makes it easier to poke\naround when a build fails on a remote build system where I\ncan't get a shell. :)\n\nJeff King wrote:\n> On Wed, Nov 30, 2022 at 05:09:34PM -0500, Todd Zullinger wrote:\n> \n>> The changes in 73c49a4474 (t: run t5551 tests with both HTTP\n>> and HTTP/2, 2022-11-11) seem to rather frequently trigger\n>> test failures on Fedora.\n> \n> Thanks for the report. I can't seem to reproduce here on my Debian\n> system, even with --stress.\n\nOne notable difference between Debian/Ubuntu and Fedora is\nthat Debian/Ubuntu uses mod_http2 included with the upstream\nApache httpd source.  Fedora is using the newer, stand-alone\nmodule (which is the upstream source for the http2 module).\n\nUbuntu 22.04.1 has httpd-2.4.52 with mod_http2-1.15.26 (per\nMOD_HTTP2_VERSION in modules/http2/h2_version.h).\n\nFedora 37, 36, and rawhide have httpd-httpd-2.4.54 with\nmod_http2-2.0.9.  They also have curl-7.86 in rawhide (where\nI've done the most testing), 7.85.0 in 37, and 7.82.0 in 36.\n\nInterestingly, if I build the same git source rpm against\nRHEL-9 which has httpd-2.4.53 and mod_http2-1.15.19, I don't\nsee any failures.\n\nI'm tempted to do a build of mod_http2-1.x or the embedded\nmod_http2 and test with that, but I have not yet made time\nto do so.\n\nSearching for errors similar to what I found in the test\nfailures, I found an old curl issue and a related Fedora\nbug:\n\n    https://github.com/curl/curl/issues/3750\n    https://bugzilla.redhat.com/show_bug.cgi?id=1690971\n\nOf course, these are from 2019 so you'd think this\nparticular issue was long-gone.  But perhaps with mod_http2\nstill being actively developed, similar bugs can crop up.\n\n> I can try a Fedora chroot or vm, but it may take some time to set up. It\n> also sounds like you're not able to reproduce it locally on a Fedora\n> system? Have you tried \"./t5559-* --stress\"?\n\nI had, but at the time the failures I got seemed unrelated,\nparticularly because they triggered on earlier tests and\nsomewhat randomly.\n\nAfter I changed the test to append $test_count to err so I\ncould see the reason for the failure more clearly, I think\nthey are more similar.\n\nWith --stress, http2 fails at various points with errors\nlike:\n\n    expecting success of 5559.6 'fetch changes via http': \n\t    echo content >>file &&\n\t    git commit -a -m two &&\n\t    git push public &&\n\t    (cd clone && git pull) &&\n\t    test_cmp file clone/file\n\n    +++ echo content\n    +++ git commit -a -m two\n    [main 5647d5f] two\n     Author: A U Thor <author@example.com>\n     1 file changed, 1 insertion(+)\n    +++ git push public\n    To /builddir/build/BUILD/git-2.39.0.rc2/t/trash directory.t5559-http-fetch-smart-http2.stress-13/httpd/www/repo.git\n       f39a923..5647d5f  main -> main\n    +++ cd clone\n    +++ git pull\n    error: RPC failed; curl 16 Error in the HTTP2 framing layer\n    fatal: expected flush after ref listing\n    error: last command exited with $?=1\n    not ok 6 - fetch changes via http\n\nor sometimes with the same error in test 30, as below.\n\n>> The most frequent test to fail is \"large fetch-pack requests\n>> can be sent using chunked encoding\" (t5559.30), but earlier\n>> tests have also failed on occasion.  For the common failure,\n>> the test exits with:\n>> \n>>     expecting success of 5559.30 'large fetch-pack requests can be sent using chunked encoding': \n>> \t    GIT_TRACE_CURL=true git -c http.postbuffer=65536 \\\n>> \t\t    clone --bare \"$HTTPD_URL/smart/repo.git\" split.git 2>err &&\n>> \t    {\n>> \t\t    test_have_prereq HTTP2 ||\n>> \t\t    grep \"^=> Send header: Transfer-Encoding: chunked\" err\n>> \t    }\n>>     +++ GIT_TRACE_CURL=true\n>>     +++ git -c http.postbuffer=65536 clone --bare http://127.0.0.1:5559/smart/repo.git split.git\n>>     error: last command exited with $?=128\n>>     not ok 30 - large fetch-pack requests can be sent using chunked encoding\n>> \n>> (Less frequently, I've seen the last command exit 141.)\n> \n> Interesting. 141 implies SIGPIPE, but that may be a red herring. The\n> operation isn't supposed to fail, but if it does due to the server\n> bailing, then the client sometimes hitting SIGPIPE is a known unrelated\n> problem.\n> \n> Is it possible to see the contents of \"err\" here? That will have the\n> message from the client, but also the curl trace, which is probably\n> helpful.\n\nAppending -$test_count to err in all the places it's used in\nthe test helped here, e.g.:\n\n    sed -Ei 's/\\berr\\b/&-$test_count/' t/t5551-http-fetch-smart.sh\n\nWith that, one of the more common errors is:\n\n    error: RPC failed; HTTP 101 curl 92 HTTP/2 stream 1 was not closed cleanly before end of the underlying stream\n\nothers are:\n\n    error: RPC failed; HTTP 101 curl 16 Error in the HTTP2 framing layer\n    fatal: expected flush after ref listing\n\n    error: RPC failed; HTTP 101 curl 16 Error in the HTTP2 framing layer\n\n    error: RPC failed; curl 16 Error in the HTTP2 framing layer \n    fatal: expected 'packfile'\n\nThe full err output is usually around 5k lines, so it's not\nideal for inclusion here, but I've saved a number of them\nand can either extract portions or post them somewhere and\nlink to them, if you think they might be useful.\n\n> It might also be interesting to see the server's view, which would be in\n> httpd/error.log in the trash directory (also access.log, but probably\n> that is not interesting).\n\nThe error.log looks the same for the failed runs I've\ncollected:\n\n    [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\n    [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'\n    [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\n    [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\n    [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\n    [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\n    [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\n    [Tue Dec 06 16:35:58.185699 2022] [mpm_event:notice] [pid 298654:tid 298654] AH00491: caught SIGTERM, shutting down\n\nThe LogLevel might need to be adjusted to get more useful\noutput there, perhaps?\n\n> If t5551 isn't failing similarly, then presumably the problem is either:\n> \n>   1. There is some race or bad interaction between curl and apache\n>      speaking http2 (possibly a buggy version of one?)\n> \n>   2. http2 requires using mpm_event instead of mpm_prefork. Maybe this\n>      introduces problems with apache on this system?\n> \n>   3. there is a bug in git. ;) This is always a possibility, of course,\n>      but we literally do nothing differently from our end, except pass\n>      it to curl via CURLOPT_HTTP_VERSION.\n> \n> It would be interesting to see if doing this:\n> \n> diff --git a/t/lib-httpd/apache.conf b/t/lib-httpd/apache.conf\n> index 0294739a77..b24ca44a95 100644\n> --- a/t/lib-httpd/apache.conf\n> +++ b/t/lib-httpd/apache.conf\n> @@ -73,16 +73,9 @@ LockFile accept.lock\n>  \tLoadModule unixd_module modules/mod_unixd.so\n>  </IfModule>\n>  \n> -<IfDefine HTTP2>\n>  <IfModule !mod_mpm_event.c>\n>  \tLoadModule mpm_event_module modules/mod_mpm_event.so\n>  </IfModule>\n> -</IfDefine>\n> -<IfDefine !HTTP2>\n> -<IfModule !mod_mpm_prefork.c>\n> -\tLoadModule mpm_prefork_module modules/mod_mpm_prefork.so\n> -</IfModule>\n> -</IfDefine>\n>  </IfVersion>\n>  \n>  PassEnv GIT_VALGRIND\n> \n> also causes t5551 to start failing. If so, then we can blame mpm_event,\n> and not http2.\n\nGood idea.  With that applied, I've still not seen a failure\nin t5551, not even when run via --stress for some minutes.\n\nI'm not sure whether any of this points to a bug in Git's\nhttp2 code at all.  It _seems_ like it's going to be\nelsewhere, in curl and/or httpd/mod_http2.  In other words,\nyour 1 above.\n\nIf nothing jumps out to point to a possible issue in git,\nI'll extract a reproduction recipe from the test suite and\nfile a Fedora bug.  Maybe the folks who have looked at\nsimilar issues in curl and httpd/mod_http2 will spot\nsomething.\n\nThanks!\n\n-- \nTodd\n"},{"id":"468842","messageId":"Y5OhwqBAq9SCuruq@coredump.intra.peff.net","threadId":"58879","inReplyTo":"Y5KbUBC1ENOAVuTV@pobox.com","subject":"Re: t5559-http-fetch-smart-http2 failures","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2022-12-09T20:59:46Z","receivedAt":"2022-12-09T20:59:52Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Dec 08, 2022 at 09:20:00PM -0500, Todd Zullinger wrote:\n\n> Sorry for the delay.  I wanted to gather some data but could\n> only do it in small chunks at a time.  Hopefully that\n> doesn't make this too rambling and/or disjointed.\n\nNo problem. I would be happy if all bug reports were this thorough and\nclear. :)\n\n> > Thanks for the report. I can't seem to reproduce here on my Debian\n> > system, even with --stress.\n> \n> One notable difference between Debian/Ubuntu and Fedora is\n> that Debian/Ubuntu uses mod_http2 included with the upstream\n> Apache httpd source.  Fedora is using the newer, stand-alone\n> module (which is the upstream source for the http2 module).\n> \n> Ubuntu 22.04.1 has httpd-2.4.52 with mod_http2-1.15.26 (per\n> MOD_HTTP2_VERSION in modules/http2/h2_version.h).\n\nMakes sense. I'm on Debian unstable, which is httpd-2.4.54 and\nmod_http2-1.15.28 (the latter I pulled from \"strings mod_http2.so\", so\nuh...it's probably right).\n\n> Fedora 37, 36, and rawhide have httpd-httpd-2.4.54 with\n> mod_http2-2.0.9.  They also have curl-7.86 in rawhide (where\n> I've done the most testing), 7.85.0 in 37, and 7.82.0 in 36.\n\nSo that's the same httpd and curl version (7.86.0) I'm using, which\nimplies to me the problem is in the newer mod_http2 version. And...\n\n> Interestingly, if I build the same git source rpm against\n> RHEL-9 which has httpd-2.4.53 and mod_http2-1.15.19, I don't\n> see any failures.\n\n...that data point would be consistent with the theory.\n\n> I'm tempted to do a build of mod_http2-1.x or the embedded\n> mod_http2 and test with that, but I have not yet made time\n> to do so.\n\nYeah, I suspect it would make the problem go away. In theory it may even\nbe possible to bisect within mod_http2, but I don't know how painful it\nis to do a build+test cycle.\n\n> With that, one of the more common errors is:\n> \n>     error: RPC failed; HTTP 101 curl 92 HTTP/2 stream 1 was not closed cleanly before end of the underlying stream\n> \n> others are:\n> \n>     error: RPC failed; HTTP 101 curl 16 Error in the HTTP2 framing layer\n>     fatal: expected flush after ref listing\n> \n>     error: RPC failed; HTTP 101 curl 16 Error in the HTTP2 framing layer\n> \n>     error: RPC failed; curl 16 Error in the HTTP2 framing layer \n>     fatal: expected 'packfile'\n\nOK, that makes me pretty confident that there's nothing Git is doing\nwrong here. I don't think we could stimulate a failure at that layer of\ncurl even if we wanted to. And those errors plus the racy nature of what\nyou're seeing really makes it look like there is just some race\ncondition or other bug in mod_http2 (possibly coupled with the mpm).\n\n> The error.log looks the same for the failed runs I've\n> collected:\n> [...]\n> The LogLevel might need to be adjusted to get more useful\n> output there, perhaps?\n\nYeah, that output is not particularly enlightening. In a sense it's not\nsurprising, though. If there's a bug on the server side, we're not\nlikely to get a log line saying \"sending garbage output to the client\".\nIt's the client who sees the problem and hangs up. Turning up the log\nlevel could help, but I'd be surprised.\n\n> > also causes t5551 to start failing. If so, then we can blame mpm_event,\n> > and not http2.\n> \n> Good idea.  With that applied, I've still not seen a failure\n> in t5551, not even when run via --stress for some minutes.\n\nOK. So I think that rules out mpm_event being a problem by itself. It's\npossible there's some bad interaction between mpm_event and mod_http2,\nbut it seems more likely there's simply a bug or race in mod_http2.\n\n> I'm not sure whether any of this points to a bug in Git's\n> http2 code at all.  It _seems_ like it's going to be\n> elsewhere, in curl and/or httpd/mod_http2.  In other words,\n> your 1 above.\n\nMy best guess is a bug in mod_http2. But one thing that it still _could_\nbe is that Git's server-side CGI interacts badly with mod_http2 somehow\n(or maybe only some versions of it).\n\nI guess some other things to try would be:\n\n  1. Take Git out of the mix completely. If we stress-test command-line\n     curl hitting our test apache, serving up static files, can we\n     trigger the problem? If not, then...\n\n  2. Try the same thing, but hit endpoints that trigger git-http-backend\n     on the server side. If that fails, then we've absolved Git's client\n     code, and the bug is either in mod_http2 or some bad interaction\n     with Git's CGI output.\n\n> If nothing jumps out to point to a possible issue in git,\n> I'll extract a reproduction recipe from the test suite and\n> file a Fedora bug.  Maybe the folks who have looked at\n> similar issues in curl and httpd/mod_http2 will spot\n> something.\n\nYou might try running the failing tests with GIT_TRACE_CURL set in the\nenvironment. That should get you a pretty detailed view of what curl is\nseeing, which would probably be helpful for a bug report.\n\n-Peff\n"}]}