curl 8.10.0 regression breaks uploads with HTTP/2 and http.postbuffer

Hi,

I noticed that GitLab's CI started to fail consistently with our Alpine-based builds in t5559.30. After investigating a bit I couldn't notice anything obvious on our side changing, so I checked whether Alpine itself updated any packages. And indeed, it updated to curl 8.10 yesterday.

I first expected this to be musl-specific, but I can reproduce the issue on my glibc system, as well. The issue bisects to 35bf76628 (http2: improved upload eos handling, 2024-08-04), which checks out with the symptoms.

Reproducer in the Git project:

    ```
    $ make
    $ cd t/
    $ ./t5559-http-fetch-smart-http2.sh --run=1-4,30 -ix
    ```

Apache logs:

    [Fri Sep 13 05:10:57.153872 2024] [ssl:warn] [pid 1435033:tid 1435033] AH01909: dummy:443:0 server certificate does NOT include an ID which matches the server name
    [Fri Sep 13 05:10:57.156090 2024] [ssl:warn] [pid 1435035:tid 1435035] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
    [Fri Sep 13 05:10:57.157052 2024] [ssl:warn] [pid 1435035:tid 1435035] AH01909: dummy:443:0 server certificate does NOT include an ID which matches the server name
    [Fri Sep 13 05:10:57.158122 2024] [mpm_event:notice] [pid 1435035:tid 1435035] AH00489: Apache/2.4.62 (Unix) OpenSSL/3.0.14 configured -- resuming normal operations
    [Fri Sep 13 05:10:57.158140 2024] [core:notice] [pid 1435035:tid 1435035] AH00094: Command line: '/nix/store/r2vzwkm8xvzdkfyqc9m3b3cc6q6jdly4-apache-httpd-2.4.62/bin/httpd -d /tmp/git-tests/trash directory.t5559-http-fetch-smart-http2/httpd -f /home/pks/Development/git/t/lib-httpd/apache.conf -D HTTP2 -D SSL -c Listen 127.0.0.1:5559'
    [Fri Sep 13 05:11:57.434888 2024] [cgi:error] [pid 1435039:tid 1435046] (70007)The timeout specified has expired: [remote 127.0.0.1:53154] AH01225: Error reading request entity data
    [Fri Sep 13 05:11:57.545789 2024] [mpm_event:notice] [pid 1435035:tid 1435035] AH00491: caught SIGTERM, shutting down

Most lines are expected, but the second-to-last line mentions an expired timeout. So I suspect that with the mentioned commit, curl does not detect the EOS correctly in all scenarios anymore. This only happens with HTTP/2 -- the tests continue to work just fine with HTTP/1, which we execute via t5551.

I didn't dig much further than that.

Patrick

On Fri, 13 Sep 2024, Patrick Steinhardt wrote:

Can you clarify for us exactly what the test case does so that we can try to reproduce this?

We already fixed one 8.10.0 regression for HTTP/2 uploads with this PR:

   https://github.com/curl/curl/pull/14877

On Fri, 13 Sep 2024, Daniel Stenberg wrote:

I should also probably mention that we plan to ship curl 8.10.1 on September 18, addressing this and a few other regressions.

On Fri, Sep 13, 2024 at 08:11:37AM +0200, Daniel Stenberg wrote:

In a nutshell:

  - We set up Apache with HTTP/2 support via -DHTTP2.

  - We create a bunch of Git repositories to serve via Apache. The
    number of refs in the repository is rather biggish.

  - We then clone a repository from Apache with http.postbuffer=65536,
    which makes us use a small buffer when POSTing data via curl. We
    typically use 1MB buffers, and when changing it back to 1MB instead
    of 65kB the test works just fine.

I've appended two curl traces, the working one with 1MB buffers and the failing one with 65kB buffers. I hope that helps.

I've applid 70d3a9b6a (http2: when uploading data from stdin, fix eos forwarding, 2024-09-12), but it doesn't fix the issue. I've also verified that the latest `master` at 8ca603083 (RELEASE-NOTES: synced, 2024-09-12) still runs into the timeout in the same way.

Patrick

### Working, 1MB buffer

== Info: Couldn't find host 127.0.0.1 in the .netrc file; using defaults == Info: Trying 127.0.0.1:5559... == Info: Connected to 127.0.0.1 () port 5559 == Info: ALPN: curl offers h2,http/1.1 => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... == Info: TLSv1.3 (OUT), TLS handshake, Client hello (1): => Send SSL data, 0000000512 bytes (0x00000200) => Send SSL data: ...........#v.#..qb.f.2a...d.W...+.... mNB...0K.._...Uz"... => Send SSL data: .C.x.@5.....>.......,.0.........+./...$.(.k.#.'.g.....9..... => Send SSL data: 3.....=.<.5./.....u......................................... => Send SSL data: h2.http/1.1.........1.....*.(............................... => Send SSL data: ..........+............-.....3.&.$... St.........s7..[%.44g. => Send SSL data: .Sf7+jl..\.................................................. => Send SSL data: ............................................................ => Send SSL data: ............................................................ => Send SSL data: ................................ <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....z == Info: TLSv1.3 (IN), TLS handshake, Server hello (2): <= Recv SSL data, 0000000122 bytes (0x0000007a) <= Recv SSL data: ...v...o.z....a&....Bz.<,.....!.bL.f.. mNB...0K.._...Uz"... <= Recv SSL data: .C.x.@5..........+.....3.$... .".1.KV.G....X.$T......o.....x <= Recv SSL data: 8? <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: .... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8): <= Recv SSL data, 0000000015 bytes (0x0000000f) <= Recv SSL data: .............h2 <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Certificate (11): <= Recv SSL data, 0000000704 bytes (0x000002c0) <= Recv SSL data: ...........0...0........,./..H.cz....e..40...*.H........0.1. <= Recv SSL data: 0...U....127.0.0.10...240913063249Z..241013063249Z0.1.0...U. <= Recv SSL data: ...127.0.0.10.."0...*.H.............0..........F....OHgR..(. <= Recv SSL data: ......X\.ue.r.|.?....k}..9.0.J....=0..".Y+w&.m.=.a._!..Z.... <= Recv SSL data: .]U.M.\.Dk....a. v.j.pV8..FU..;..j.e.M...'<............y...t <= Recv SSL data: ....W&....e.......d......7.7}..j.!..._8.n..5..+..........x.. <= Recv SSL data: .v.........ef.....bpe..../....^.Tu....;NG.R..Y...K...L....l. <= Recv SSL data: y.....0...*.H..............1w...w......c..i.P..2....Ht.:u0.. <= Recv SSL data: Ef!d}....*KNv."b....|..d..>s..M6......u..;.....&J<...<@.qg <= Recv SSL data: ....GD.....3.6... ....Q..Nk..f.xf.xP>....]..m=.[OP0..,..t..3 <= Recv SSL data: ..iE8B..Mu....4j.=. ...ll.1....k.2<.]w.U..*.&..k.C....T.6.A. <= Recv SSL data: ......t..O...rW...1..A..y.b...I.........]... <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, CERT verify (15): <= Recv SSL data, 0000000264 bytes (0x00000108) <= Recv SSL data: ........Y.s.'.=qB.Mh.j!\..j.........>.1..F...n85n(/......... <= Recv SSL data: ....[!5Jq.\.7....E...#...,-:...m......}..4..#N.n.\+v].ae...7 <= Recv SSL data: zy..r..f.8..e...".........L..<....Hf.k;.[ M..xhY2.."L..aS4.. <= Recv SSL data: .(..:..7.....`...%. .i.uh...... oVA...iIe.Sg/.qrkN...V9.n..P <= Recv SSL data: .......f_..G"....:.E.%@P <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....E <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Finished (20): <= Recv SSL data, 0000000052 bytes (0x00000034) <= Recv SSL data: ...0D~...K.{.t_KQ.v.S...v...M...;......j..B.:tWf...x => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... == Info: TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1): => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....E => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . == Info: TLSv1.3 (OUT), TLS handshake, Finished (20): => Send SSL data, 0000000052 bytes (0x00000034) => Send SSL data: ...0.b..0..k.[.N..z.G.....*.......tMqU..Q."(E8.L...3 == Info: SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / X25519 / RSASSA-PSS == Info: ALPN: server accepted h2 == Info: Server certificate: == Info: subject: CN=127.0.0.1 == Info: start date: Sep 13 06:32:49 2024 GMT == Info: expire date: Oct 13 06:32:49 2024 GMT == Info: issuer: CN=127.0.0.1 == Info: SSL certificate verify result: self-signed certificate (18), continuing anyway. == Info: Certificate level 0: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....Q => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . == Info: using HTTP/2 == Info: [HTTP/2] [1] OPENED stream for https://127.0.0.1:5559/smart/repo.git/info/refs?service=git-upload-pack == Info: [HTTP/2] [1] [:method: GET] == Info: [HTTP/2] [1] [:scheme: https] == Info: [HTTP/2] [1] [:authority: 127.0.0.1:5559] == Info: [HTTP/2] [1] [:path: /smart/repo.git/info/refs?service=git-upload-pack] == Info: [HTTP/2] [1] [user-agent: git/2.46.0.556.gcfcff505c7f.dirty] == Info: [HTTP/2] [1] [accept: */*] == Info: [HTTP/2] [1] [accept-encoding: deflate, gzip, br, zstd] == Info: [HTTP/2] [1] [pragma: no-cache] == Info: [HTTP/2] [1] [git-protocol: version=2] => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send header, 0000000231 bytes (0x000000e7) => Send header: GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/2 => Send header: Host: 127.0.0.1:5559 => Send header: User-Agent: git/2.46.0.556.gcfcff505c7f.dirty => Send header: Accept: */* => Send header: Accept-Encoding: deflate, gzip, br, zstd => Send header: Pragma: no-cache => Send header: Git-Protocol: version=2 => Send header: <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4): <= Recv SSL data, 0000000265 bytes (0x00000109) <= Recv SSL data: .......,9.J............#....GL.A-J.E..%...+.Q..O,.I..0F..... <= Recv SSL data: ...~{O.50W(._..}..k.6..sUo..OZS.&.c.m.1a..|.1xQH...KWf..... <= Recv SSL data: ....P.i(V.@...@......8.%x7M.....Z.T..t..Q..'..#..h.[..'jp... <= Recv SSL data: ......p}[.mB....HD..F%[d...]$P.S....C.J%Q=.&.R...M5E._..7.?. <= Recv SSL data: .^. Q.I..-..b,.....K..,.. <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4): <= Recv SSL data, 0000000265 bytes (0x00000109) <= Recv SSL data: .......,..V............#....GL.A-J.E..%$.....D.A..5.......B. <= Recv SSL data: 5..'.Y..X,.Z...ba..[.)0...eZ-.X......iZ)...0.......w.d...km. <= Recv SSL data: ..I.m...`W..r.?...B.. 7.yF....RLW.Mt"4.q....(.$>bE.....OT..D <= Recv SSL data: u.x...o.O*..T:t...N..3.o.c... ........A...*e.:.tD...F.....=. <= Recv SSL data: ..*..8....P...._...|..0.. <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....- <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . == Info: Request completely sent off <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv header, 0000000013 bytes (0x0000000d) <= Recv header: HTTP/2 200 <= Recv header, 0000000040 bytes (0x00000028) <= Recv header: expires: Fri, 01 Jan 1980 00:00:00 GMT <= Recv header, 0000000018 bytes (0x00000012) <= Recv header: pragma: no-cache <= Recv header, 0000000053 bytes (0x00000035) <= Recv header: cache-control: no-cache, max-age=0, must-revalidate <= Recv header, 0000000059 bytes (0x0000003b) <= Recv header: content-type: application/x-git-upload-pack-advertisement <= Recv header, 0000000037 bytes (0x00000025) <= Recv header: date: Fri, 13 Sep 2024 06:32:49 GMT <= Recv header, 0000000045 bytes (0x0000002d) <= Recv header: server: Apache/2.4.62 (Unix) OpenSSL/3.0.14 <= Recv header, 0000000002 bytes (0x00000002) <= Recv header: => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000154 bytes (0x0000009a) <= Recv data: 000eversion 2.002cagent=git/2.46.0.556.gcfcff505c7f.dirty.00 <= Recv data: 13ls-refs=unborn.0020fetch=shallow wait-for-done.0012server- <= Recv data: option.0017object-format=sha1.0000 <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000000 bytes (0x00000000) == Info: Connection #0 to host 127.0.0.1 left intact == Info: Couldn't find host 127.0.0.1 in the .netrc file; using defaults == Info: Re-using existing connection with host 127.0.0.1 == Info: [HTTP/2] [3] OPENED stream for https://127.0.0.1:5559/smart/repo.git/git-upload-pack == Info: [HTTP/2] [3] [:method: POST] == Info: [HTTP/2] [3] [:scheme: https] == Info: [HTTP/2] [3] [:authority: 127.0.0.1:5559] == Info: [HTTP/2] [3] [:path: /smart/repo.git/git-upload-pack] == Info: [HTTP/2] [3] [user-agent: git/2.46.0.556.gcfcff505c7f.dirty] == Info: [HTTP/2] [3] [accept-encoding: deflate, gzip, br, zstd] == Info: [HTTP/2] [3] [content-type: application/x-git-upload-pack-request] == Info: [HTTP/2] [3] [accept: application/x-git-upload-pack-result] == Info: [HTTP/2] [3] [git-protocol: version=2] == Info: [HTTP/2] [3] [content-length: 198] => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....E => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send header, 0000000303 bytes (0x0000012f) => Send header: POST /smart/repo.git/git-upload-pack HTTP/2 => Send header: Host: 127.0.0.1:5559 => Send header: User-Agent: git/2.46.0.556.gcfcff505c7f.dirty => Send header: Accept-Encoding: deflate, gzip, br, zstd => Send header: Content-Type: application/x-git-upload-pack-request => Send header: Accept: application/x-git-upload-pack-result => Send header: Git-Protocol: version=2 => Send header: Content-Length: 198 => Send header: => Send data, 0000000198 bytes (0x000000c6) => Send data: 0014command=ls-refs.002bagent=git/2.46.0.556.gcfcff505c7f.di => Send data: rty0016object-format=sha100010009peel.000csymrefs.000bunborn => Send data: .0014ref-prefix HEAD.001bref-prefix refs/heads/.001aref-pref => Send data: ix refs/tags/.0000 == Info: upload completely sent off: 198 bytes <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....< <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv header, 0000000013 bytes (0x0000000d) <= Recv header: HTTP/2 200 <= Recv header, 0000000040 bytes (0x00000028) <= Recv header: expires: Fri, 01 Jan 1980 00:00:00 GMT <= Recv header, 0000000018 bytes (0x00000012) <= Recv header: pragma: no-cache <= Recv header, 0000000053 bytes (0x00000035) <= Recv header: cache-control: no-cache, max-age=0, must-revalidate <= Recv header, 0000000052 bytes (0x00000034) <= Recv header: content-type: application/x-git-upload-pack-result <= Recv header, 0000000037 bytes (0x00000025) <= Recv header: date: Fri, 13 Sep 2024 06:32:49 GMT <= Recv header, 0000000045 bytes (0x0000002d) <= Recv header: server: Apache/2.4.62 (Unix) OpenSSL/3.0.14 <= Recv header, 0000000002 bytes (0x00000002) <= Recv header: => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000145 bytes (0x00000091) <= Recv data: 0050f39a92305d069e3dcdc4ce95c3001deec3642dc3 HEAD symref-tar <= Recv data: get:refs/heads/main.003df39a92305d069e3dcdc4ce95c3001deec364 <= Recv data: 2dc3 refs/heads/main.0000 <= Recv data, 0000000000 bytes (0x00000000) == Info: Connection #0 to host 127.0.0.1 left intact == Info: Couldn't find host 127.0.0.1 in the .netrc file; using defaults == Info: Re-using existing connection with host 127.0.0.1 == Info: [HTTP/2] [5] OPENED stream for https://127.0.0.1:5559/smart/repo.git/git-upload-pack == Info: [HTTP/2] [5] [:method: POST] == Info: [HTTP/2] [5] [:scheme: https] == Info: [HTTP/2] [5] [:authority: 127.0.0.1:5559] == Info: [HTTP/2] [5] [:path: /smart/repo.git/git-upload-pack] == Info: [HTTP/2] [5] [user-agent: git/2.46.0.556.gcfcff505c7f.dirty] == Info: [HTTP/2] [5] [accept-encoding: deflate, gzip, br, zstd] == Info: [HTTP/2] [5] [content-type: application/x-git-upload-pack-request] == Info: [HTTP/2] [5] [accept: application/x-git-upload-pack-result] == Info: [HTTP/2] [5] [git-protocol: version=2] == Info: [HTTP/2] [5] [content-length: 240] => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....8 => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send header, 0000000303 bytes (0x0000012f) => Send header: POST /smart/repo.git/git-upload-pack HTTP/2 => Send header: Host: 127.0.0.1:5559 => Send header: User-Agent: git/2.46.0.556.gcfcff505c7f.dirty => Send header: Accept-Encoding: deflate, gzip, br, zstd => Send header: Content-Type: application/x-git-upload-pack-request => Send header: Accept: application/x-git-upload-pack-result => Send header: Git-Protocol: version=2 => Send header: Content-Length: 240 => Send header: => Send data, 0000000240 bytes (0x000000f0) => Send data: 0011command=fetch002bagent=git/2.46.0.556.gcfcff505c7f.dirty => Send data: 0016object-format=sha10001000dthin-pack000fno-progress000dof => Send data: s-delta0032want f39a92305d069e3dcdc4ce95c3001deec3642dc3.003 => Send data: 2want f39a92305d069e3dcdc4ce95c3001deec3642dc3.0009done.0000 == Info: upload completely sent off: 240 bytes <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....! <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv header, 0000000013 bytes (0x0000000d) <= Recv header: HTTP/2 200 <= Recv header, 0000000040 bytes (0x00000028) <= Recv header: expires: Fri, 01 Jan 1980 00:00:00 GMT <= Recv header, 0000000018 bytes (0x00000012) <= Recv header: pragma: no-cache <= Recv header, 0000000053 bytes (0x00000035) <= Recv header: cache-control: no-cache, max-age=0, must-revalidate <= Recv header, 0000000052 bytes (0x00000034) <= Recv header: content-type: application/x-git-upload-pack-result <= Recv header, 0000000037 bytes (0x00000025) <= Recv header: date: Fri, 13 Sep 2024 06:32:49 GMT <= Recv header, 0000000045 bytes (0x0000002d) <= Recv header: server: Apache/2.4.62 (Unix) OpenSSL/3.0.14 <= Recv header, 0000000002 bytes (0x00000002) <= Recv header: => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....' <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000013 bytes (0x0000000d) <= Recv data: 000dpackfile. <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000230 bytes (0x000000e6) <= Recv data: 00e0.PACK..........x.+)JMU00775N31.073ML6LLK5202H22I510.0.0. <= Recv data: LJ1I.0.J,-../RpT.U..1l .......9.z...v....F..&.....@c......%% <= Recv data: .E.........\..n...T....0...x.340031QH..Ie..ou..].Ui...`..... <= Recv data: O.......8x.K..+I.+........}....#Z.l.R.v.D.\.0006.. <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000004 bytes (0x00000004) <= Recv data: 0000 <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000000 bytes (0x00000000) == Info: Connection #0 to host 127.0.0.1 left intact

### Failing

== Info: Couldn't find host 127.0.0.1 in the .netrc file; using defaults == Info: Trying 127.0.0.1:5559... == Info: Connected to 127.0.0.1 () port 5559 == Info: ALPN: curl offers h2,http/1.1 => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... == Info: TLSv1.3 (OUT), TLS handshake, Client hello (1): => Send SSL data, 0000000512 bytes (0x00000200) => Send SSL data: .......e.K.6.u....b..."p.p..0.S...oJ}. .6...........a....!.. => Send SSL data: ...Q..u.9...>.......,.0.........+./...$.(.k.#.'.g.....9..... => Send SSL data: 3.....=.<.5./.....u......................................... => Send SSL data: h2.http/1.1.........1.....*.(............................... => Send SSL data: ..........+............-.....3.&.$... ....S..[%t.S].+......4 => Send SSL data: .C.G..<.;.................................................. => Send SSL data: ............................................................ => Send SSL data: ............................................................ => Send SSL data: ................................ <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....z == Info: TLSv1.3 (IN), TLS handshake, Server hello (2): <= Recv SSL data, 0000000122 bytes (0x0000007a) <= Recv SSL data: ...v......%.jD]3....Q...t.v.;....H.K;. .6...........a....!.. <= Recv SSL data: ...Q..u.9........+.....3.$... ...(......r.^.=L......FmI.CS.A <= Recv SSL data: .4 <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: .... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8): <= Recv SSL data, 0000000015 bytes (0x0000000f) <= Recv SSL data: .............h2 <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Certificate (11): <= Recv SSL data, 0000000704 bytes (0x000002c0) <= Recv SSL data: ...........0...0.....O~.......F.......I.d0...*.H........0.1. <= Recv SSL data: 0...U....127.0.0.10...240913063318Z..241013063318Z0.1.0...U. <= Recv SSL data: ...127.0.0.10.."0...*.H.............0.........y..i.^xtl..... <= Recv SSL data: .D:..g...B[................s.P.Ea.O...M[....#Q. ..g._U.&..l9 <= Recv SSL data: ...uU......w... ...6.x...U........&.H|.+....H..bm....w...tx. <= Recv SSL data: .....~\k....f4........u...6..1.[Z.Bu.X...H...!..h%.O.'.RdNG. <= Recv SSL data: o..V.p.0.u60.....<.....^kC..n.w..=..y.*J(n....m...lB...K.... <= Recv SSL data: ......0...*.H..............[....0.X..if.C{....d..n....k.AI.. <= Recv SSL data: ......Q..m....>.m.i^.W.S..,Pt.m.........Uo..Qk.*.u.w..9lM.. <= Recv SSL data: .........k....L2.5..7+...j.cU...E.je..QPG.jt..H..~.P.(.../.A <= Recv SSL data: ..S.b...[hV.r....35.`..(..a.........u<e.9..P.N........8..*.% <= Recv SSL data: \(.......Sj...\l.3J.....#..={.~...^...Zv... <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, CERT verify (15): <= Recv SSL data, 0000000264 bytes (0x00000108) <= Recv SSL data: ........o.P..jt.2m.L4)..9p...K..................i.. G.$yz.U <= Recv SSL data: A..s.CPk.....A........]....f.P.\(0...>..a.~}"......|.5....=. <= Recv SSL data: N...|.6.M.g....1.........>.8.....h1....-.1.].o.yO......Ex(.g <= Recv SSL data: .Y.u..+...<.2...[::y.....2bL.....|..._.<...n.9.+d....X.8-A~D <= Recv SSL data: _.T.^.}......c..A]*G.... <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....E <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Finished (20): <= Recv SSL data, 0000000052 bytes (0x00000034) <= Recv SSL data: ...0...nl.I..$..f.3.3T.+.i.......8f..1e.{G.....@5J.. => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... == Info: TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1): => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....E => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . == Info: TLSv1.3 (OUT), TLS handshake, Finished (20): => Send SSL data, 0000000052 bytes (0x00000034) => Send SSL data: ...0|.*2\{U.Z.<..9.......-i..9..bnE. V....R...([.d.. == Info: SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / X25519 / RSASSA-PSS == Info: ALPN: server accepted h2 == Info: Server certificate: == Info: subject: CN=127.0.0.1 == Info: start date: Sep 13 06:33:18 2024 GMT == Info: expire date: Oct 13 06:33:18 2024 GMT == Info: issuer: CN=127.0.0.1 == Info: SSL certificate verify result: self-signed certificate (18), continuing anyway. == Info: Certificate level 0: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....Q => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . == Info: using HTTP/2 == Info: [HTTP/2] [1] OPENED stream for https://127.0.0.1:5559/smart/repo.git/info/refs?service=git-upload-pack == Info: [HTTP/2] [1] [:method: GET] == Info: [HTTP/2] [1] [:scheme: https] == Info: [HTTP/2] [1] [:authority: 127.0.0.1:5559] == Info: [HTTP/2] [1] [:path: /smart/repo.git/info/refs?service=git-upload-pack] == Info: [HTTP/2] [1] [user-agent: git/2.46.0.556.gcfcff505c7f.dirty] == Info: [HTTP/2] [1] [accept: */*] == Info: [HTTP/2] [1] [accept-encoding: deflate, gzip, br, zstd] == Info: [HTTP/2] [1] [pragma: no-cache] == Info: [HTTP/2] [1] [git-protocol: version=2] => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send header, 0000000231 bytes (0x000000e7) => Send header: GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/2 => Send header: Host: 127.0.0.1:5559 => Send header: User-Agent: git/2.46.0.556.gcfcff505c7f.dirty => Send header: Accept: */* => Send header: Accept-Encoding: deflate, gzip, br, zstd => Send header: Pragma: no-cache => Send header: Git-Protocol: version=2 => Send header: == Info: Request completely sent off <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4): <= Recv SSL data, 0000000265 bytes (0x00000109) <= Recv SSL data: .......,.#..............<....T..Xpu..............X~.......b. <= Recv SSL data: ..dW{-.*@...!c.....C..."4<...o.8\.W^Yhev.w.o......k.e...A.B. <= Recv SSL data: ....k..B....R..R....3...G.X<.nO>...v|.7z'..(+...u<.Ob../.*y. <= Recv SSL data: :a.=..`..1..F c..G..H....'8....|h..?.b................./f#. <= Recv SSL data: ..n.........x..M...)t... <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . == Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4): <= Recv SSL data, 0000000265 bytes (0x00000109) <= Recv SSL data: .......,{.p.............<....T..Xpu.....v........".,.a<...lV <= Recv SSL data: .v..g.........k.....zjo........J..... .. _....u....S..v...>. <= Recv SSL data: ...}.N.9#bc.(.-kn..G5..N.....4....i^6.&....}..../b.z.`...... <= Recv SSL data: .-....I.C.w../..[.._W.Id..Q,..n....F(`.....t...K.\.......2.O <= Recv SSL data: ..u.-..x..A..e....D.[8@.. <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....- <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv header, 0000000013 bytes (0x0000000d) <= Recv header: HTTP/2 200 <= Recv header, 0000000040 bytes (0x00000028) <= Recv header: expires: Fri, 01 Jan 1980 00:00:00 GMT <= Recv header, 0000000018 bytes (0x00000012) <= Recv header: pragma: no-cache <= Recv header, 0000000053 bytes (0x00000035) <= Recv header: cache-control: no-cache, max-age=0, must-revalidate <= Recv header, 0000000059 bytes (0x0000003b) <= Recv header: content-type: application/x-git-upload-pack-advertisement <= Recv header, 0000000037 bytes (0x00000025) <= Recv header: date: Fri, 13 Sep 2024 06:33:18 GMT <= Recv header, 0000000045 bytes (0x0000002d) <= Recv header: server: Apache/2.4.62 (Unix) OpenSSL/3.0.14 <= Recv header, 0000000002 bytes (0x00000002) <= Recv header: => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000154 bytes (0x0000009a) <= Recv data: 000eversion 2.002cagent=git/2.46.0.556.gcfcff505c7f.dirty.00 <= Recv data: 13ls-refs=unborn.0020fetch=shallow wait-for-done.0012server- <= Recv data: option.0017object-format=sha1.0000 <= Recv data, 0000000000 bytes (0x00000000) == Info: Connection #0 to host 127.0.0.1 left intact == Info: Couldn't find host 127.0.0.1 in the .netrc file; using defaults == Info: Re-using existing connection with host 127.0.0.1 == Info: [HTTP/2] [3] OPENED stream for https://127.0.0.1:5559/smart/repo.git/git-upload-pack == Info: [HTTP/2] [3] [:method: POST] == Info: [HTTP/2] [3] [:scheme: https] == Info: [HTTP/2] [3] [:authority: 127.0.0.1:5559] == Info: [HTTP/2] [3] [:path: /smart/repo.git/git-upload-pack] == Info: [HTTP/2] [3] [user-agent: git/2.46.0.556.gcfcff505c7f.dirty] == Info: [HTTP/2] [3] [content-type: application/x-git-upload-pack-request] == Info: [HTTP/2] [3] [accept: application/x-git-upload-pack-result] == Info: [HTTP/2] [3] [content-length: 4] => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: .... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send header, 0000000234 bytes (0x000000ea) => Send header: POST /smart/repo.git/git-upload-pack HTTP/2 => Send header: Host: 127.0.0.1:5559 => Send header: User-Agent: git/2.46.0.556.gcfcff505c7f.dirty => Send header: Content-Type: application/x-git-upload-pack-request => Send header: Accept: application/x-git-upload-pack-result => Send header: Content-Length: 4 => Send header: => Send data, 0000000004 bytes (0x00000004) => Send data: 0000 == Info: upload completely sent off: 4 bytes <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....< <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv header, 0000000013 bytes (0x0000000d) <= Recv header: HTTP/2 200 <= Recv header, 0000000040 bytes (0x00000028) <= Recv header: expires: Fri, 01 Jan 1980 00:00:00 GMT <= Recv header, 0000000018 bytes (0x00000012) <= Recv header: pragma: no-cache <= Recv header, 0000000053 bytes (0x00000035) <= Recv header: cache-control: no-cache, max-age=0, must-revalidate <= Recv header, 0000000052 bytes (0x00000034) <= Recv header: content-type: application/x-git-upload-pack-result <= Recv header, 0000000037 bytes (0x00000025) <= Recv header: date: Fri, 13 Sep 2024 06:33:18 GMT <= Recv header, 0000000045 bytes (0x0000002d) <= Recv header: server: Apache/2.4.62 (Unix) OpenSSL/3.0.14 <= Recv header, 0000000002 bytes (0x00000002) <= Recv header: => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ..... <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv data, 0000000000 bytes (0x00000000) == Info: Connection #0 to host 127.0.0.1 left intact == Info: Couldn't find host 127.0.0.1 in the .netrc file; using defaults == Info: Re-using existing connection with host 127.0.0.1 == Info: [HTTP/2] [5] OPENED stream for https://127.0.0.1:5559/smart/repo.git/git-upload-pack == Info: [HTTP/2] [5] [:method: POST] == Info: [HTTP/2] [5] [:scheme: https] == Info: [HTTP/2] [5] [:authority: 127.0.0.1:5559] == Info: [HTTP/2] [5] [:path: /smart/repo.git/git-upload-pack] == Info: [HTTP/2] [5] [user-agent: git/2.46.0.556.gcfcff505c7f.dirty] == Info: [HTTP/2] [5] [accept-encoding: deflate, gzip, br, zstd] == Info: [HTTP/2] [5] [content-type: application/x-git-upload-pack-request] == Info: [HTTP/2] [5] [accept: application/x-git-upload-pack-result] == Info: [HTTP/2] [5] [git-protocol: version=2] => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....W => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send header, 0000000282 bytes (0x0000011a) => Send header: POST /smart/repo.git/git-upload-pack HTTP/2 => Send header: Host: 127.0.0.1:5559 => Send header: User-Agent: git/2.46.0.556.gcfcff505c7f.dirty => Send header: Accept-Encoding: deflate, gzip, br, zstd => Send header: Content-Type: application/x-git-upload-pack-request => Send header: Accept: application/x-git-upload-pack-result => Send header: Git-Protocol: version=2 => Send header: => Send data, 0000000020 bytes (0x00000014) => Send data: 0014command=ls-refs. => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....E => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000043 bytes (0x0000002b) => Send data: 002bagent=git/2.46.0.556.gcfcff505c7f.dirty => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....0 => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000022 bytes (0x00000016) => Send data: 0016object-format=sha1 => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000004 bytes (0x00000004) => Send data: 0001 => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....# => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000009 bytes (0x00000009) => Send data: 0009peel. => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....& => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000012 bytes (0x0000000c) => Send data: 000csymrefs. => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....% => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000011 bytes (0x0000000b) => Send data: 000bunborn. => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000020 bytes (0x00000014) => Send data: 0014ref-prefix HEAD. => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....5 => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000027 bytes (0x0000001b) => Send data: 001bref-prefix refs/heads/. => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ....4 => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000026 bytes (0x0000001a) => Send data: 001aref-prefix refs/tags/. => Send SSL data, 0000000005 bytes (0x00000005) => Send SSL data: ..... => Send SSL data, 0000000001 bytes (0x00000001) => Send SSL data: . => Send data, 0000000004 bytes (0x00000004) => Send data: 0000 == Info: upload completely sent off: 198 bytes <= Recv SSL data, 0000000005 bytes (0x00000005) <= Recv SSL data: ....0 <= Recv SSL data, 0000000001 bytes (0x00000001) <= Recv SSL data: . <= Recv header, 0000000013 bytes (0x0000000d) <= Recv header: HTTP/2 408 <= Recv header, 0000000021 bytes (0x00000015) <= Recv header: content-length: 221 <= Recv header, 0000000045 bytes (0x0000002d) <= Recv header: content-type: text/html; charset=iso-8859-1 <= Recv header, 0000000037 bytes (0x00000025) <= Recv header: date: Fri, 13 Sep 2024 06:33:18 GMT <= Recv header, 0000000045 bytes (0x0000002d) <= Recv header: server: Apache/2.4.62 (Unix) OpenSSL/3.0.14 <= Recv header, 0000000002 bytes (0x00000002) <= Recv header: <= Recv data, 0000000221 bytes (0x000000dd) <= Recv data: <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">.<html><he <= Recv data: ad>.<title>408 Request Timeout</title>.</head><body>.<h1>Req <= Recv data: uest Timeout</h1>.<p>Server timeout waiting for the HTTP req <= Recv data: uest from the client.</p>.</body></html>. <= Recv data, 0000000000 bytes (0x00000000) == Info: Connection #0 to host 127.0.0.1 left intact

On Fri, 13 Sep 2024, Patrick Steinhardt wrote:

Thanks, this is helpful.

Is this a git buffer size or is this a value you tell libcurl in an option to set a buffer size?

How are you feeding the data to libcurl? (callback or by setting the postfields option?) I noticed that in the working case log, the POST requests always have a content-length header while the failing case log shows that header lacking in the final POST request.

Is that on purpose?

libcurl should still handle it fine, it might just be a clue for me to narrow down my search.

On Fri, Sep 13, 2024 at 09:49:27AM +0200, Daniel Stenberg wrote:

I'm not all that familiar with the "remote-curl.c" remote helper in Git, so let me try to figure out things as we go.

  - The code that sets up the POST buffer is `stateless_connect()`. The
    buffer is allocated by ourselves.

  - We then execute `post_rpc()` in a loop until we see EOF.

  - `post_rpc()` itself is doing all the work to set up the curl handle,
    mostly via calls to `curl_easy_setopt()`.

  - In there we hit the `large_request` code path. We set up
    CURLOPT_READFUNCTION and CURLOPT_SEEKFUNCTION. The callback that
    uses our buffer is the one set up via CURLOPT_READFUNCTION, which is
    `rpc_out()`.

Whether or not we hit `large_request` depends on out POST buffer size. We first try to read all the data we want to send into the buffer, and if it fits we send it out in a single call to curl by setting up CURLOPT_POSTFIELDS and CURLOPT_POSTFIELDSIZE_LARGE. If it doesn't fit into the buffer, which is the case for in this testcase, we instead use the callbacks to write data via curl.

I think so. We're using a "chunked" transfer encoding in the `large_request` case and do not yet know how much data we are about to send. We'll only figure that out as we go.

Patrick

On Fri, 13 Sep 2024, Patrick Steinhardt wrote:

Thanks, I ended up able to write a stand-alone reproducer. Stefan Eissing wrote up a fix that seems to fix the case for us at least and it would be great if you could test this in your end:

   https://github.com/curl/curl/pull/14895

The actual code patch is tiny. The PR is mostly about adding test cases to reproduce and verify.

On Fri, Sep 13, 2024 at 01:04:57PM +0200, Daniel Stenberg wrote:

I can confirm that this pull request fixes the regression. Thanks a bunch for the quick turnaround, highly appreciated!

Patrick

Patrick Steinhardt <ps@pks.im> writes:

FWIW, it seems that osx jobs at GitHub's CI started exhibiting the same symptom.

  https://github.com/git/git/actions/runs/10932986544