Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Observed test case failures 1700 / 1701 / 1702 (h2c upgrade) #7036

Closed
starrify opened this issue May 8, 2021 · 3 comments
Closed

Observed test case failures 1700 / 1701 / 1702 (h2c upgrade) #7036

starrify opened this issue May 8, 2021 · 3 comments

Comments

@starrify
Copy link
Contributor

starrify commented May 8, 2021

Overview

I have earlier observed failures of test cases 1700, 1701, and 1702 on my local machine at 1763ace, which was earlier mentioned in #7032.

These three cases are all for HTTP/2 on plaintext TCP with the Upgrade: h2c haeder. The only difference is the request method, which is GET, POST, and HEAD, respectively. Those three failures look almost identical, thus I may talk about only case 1700 for convenience.

Environment and issue reproduction

The failures may be reproduced stably at 51c0ebc and other recent revisions on my local machine, and in a Docker environment constructed purposely for reproducing this issue. Details on the Docker environment would be given below.

Click here for content of the Dockerfile, which may be used to build a Docker image using commands like docker build -t $IMAGE_NAME - < Dockerfile.
FROM ubuntu:20.04
ENV DEBIAN_FRONTEND noninteractive
# list picked from .travis.yml + a few manual additions (before / after)
RUN apt-get update && apt-get install -y \
  git \
  autoconf \
  libtool \
  libssl-dev \
  cmake \
  valgrind \
  libev-dev \
  libc-ares-dev \
  g++ \
  stunnel4 \
  libidn2-dev \
  gnutls-bin \
  python3-impacket \
  ninja-build \
  libgsasl7-dev \
  libnghttp2-dev \
  nghttp2
WORKDIR /curl
ARG REVISION=51c0ebcff2140c38ff389b4fcfb8216f5e9d198c
RUN git init . && git remote add origin https://github.com/curl/curl.git \
  && git fetch origin $REVISION && git checkout $REVISION
RUN ./buildconf && ./configure --with-openssl --enable-warnings --enable-werror && make
ARG TFLAGS=1700
# ignore the command failure so that the outcome may be saved
RUN make test-full || true
Click here for some debugging information from the configure output during the build.
configure: Configured to build curl/libcurl:

  Host setup:       x86_64-pc-linux-gnu
  Install prefix:   /usr/local
  Compiler:         gcc
   CFLAGS:          -Werror-implicit-function-declaration -O2 -pedantic -Wall -W -Wpointer-arith -Wwrite-strings -Wunused -Wshadow -Winline -Wnested-externs -Wmissing-declarations -Wmissing-prototypes -Wno-long-long -Wbad-function-cast -Wfloat-equal -Wno-multichar -Wsign-compare -Wundef -Wno-format-nonliteral -Wendif-labels -Wstrict-prototypes -Wdeclaration-after-statement -Wold-style-definition -Wstrict-aliasing=3 -Wcast-align -Wtype-limits -Wold-style-declaration -Wmissing-parameter-type -Wempty-body -Wclobbered -Wignored-qualifiers -Wconversion -Wno-sign-conversion -Wvla -ftree-vrp -Wdouble-promotion -Wformat=2 -Warray-bounds=2 -Wshift-negative-value -Wshift-overflow=2 -Wnull-dereference -fdelete-null-pointer-checks -Wduplicated-cond -Wunused-const-variable -Wduplicated-branches -Wrestrict -Walloc-zero -Wformat-overflow=2 -Wformat-truncation=2 -Wimplicit-fallthrough=4 -Wno-system-headers -pthread
   CPPFLAGS:        
   LDFLAGS:         
   LIBS:            -lnghttp2 -lidn2 -lgsasl -lssl -lcrypto -lssl -lcrypto

  curl version:     7.77.0-DEV
  SSL:              enabled (OpenSSL)
  SSH:              no      (--with-{libssh,libssh2})
  zlib:             no      (--with-zlib)
  brotli:           no      (--with-brotli)
  zstd:             no      (--with-zstd)
  GSS-API:          no      (--with-gssapi)
  GSASL:            enabled
  TLS-SRP:          enabled
  resolver:         POSIX threaded
  IPv6:             enabled
  Unix sockets:     enabled
  IDN:              enabled (libidn2)
  Build libcurl:    Shared=yes, Static=yes
  Built-in manual:  no      (--enable-manual)
  --libcurl option: enabled (--disable-libcurl-option)
  Verbose errors:   enabled (--disable-verbose)
  Code coverage:    disabled
  SSPI:             no      (--enable-sspi)
  ca cert bundle:   /etc/ssl/certs/ca-certificates.crt
  ca cert path:     no
  ca fallback:      no
  LDAP:             no      (--enable-ldap / --with-ldap-lib / --with-lber-lib)
  LDAPS:            no      (--enable-ldaps)
  RTSP:             enabled
  RTMP:             no      (--with-librtmp)
  Metalink:         no      (--with-libmetalink)
  PSL:              no      (libpsl not found)
  Alt-svc:          enabled (--disable-alt-svc)
  HSTS:             enabled (--disable-hsts)
  HTTP1:            enabled (internal)
  HTTP2:            enabled (nghttp2)
  HTTP3:            no      (--with-ngtcp2, --with-quiche)
  ECH:              no      (--enable-ech)
  Protocols:        DICT FILE FTP FTPS GOPHER GOPHERS HTTP HTTPS IMAP IMAPS MQTT POP3 POP3S RTSP SMB SMBS SMTP SMTPS TELNET TFTP
  Features:         AsynchDNS GSASL HSTS HTTP2 HTTPS-proxy IDN IPv6 Largefile NTLM NTLM_WB SSL TLS-SRP UnixSockets alt-svc
Click here for the full test results for case 1700, which is generated from srcdir=. /usr/bin/perl -I. ./runtests.pl -a -p -r 1700 as part of TFLAGS=1700 make test-full.
srcdir=. /usr/bin/perl -I. ./runtests.pl -a -p -r 1700
********* System characteristics ******** 
* curl 7.77.0-DEV (x86_64-pc-linux-gnu) 
* libcurl/7.77.0-DEV OpenSSL/1.1.1f libidn2/2.2.0 nghttp2/1.40.0 libgsasl/1.8.1
* Features: alt-svc AsynchDNS gsasl HSTS HTTP2 HTTPS-proxy IDN IPv6 Largefile NTLM NTLM_WB SSL TLS-SRP UnixSockets
* Disabled: 
* Host: 1a100808e8f5
* System: Linux 1a100808e8f5 5.11.14-arch1-1 #1 SMP PREEMPT Wed, 14 Apr 2021 12:06:34 +0000 x86_64 x86_64 x86_64 GNU/Linux
* OS: linux
* Servers: SSL HTTP-IPv6 HTTP-unix FTP-IPv6 
* Env: Valgrind 
* Seed: 224325
***************************************** 
test 1700...[HTTP/2 GET with Upgrade:]

 1700: stdout FAILED:
--- log/check-expected	2021-05-08 12:14:20.726283240 +0000
+++ log/check-generated	2021-05-08 12:14:20.726283240 +0000
@@ -4,17 +4,6 @@
 [CR][LF]
 HTTP/2 200 [CR][LF]
 date: Tue, 09 Nov 2010 14:49:00 GMT[CR][LF]
-last-modified: Tue, 13 Jun 2000 12:10:00 GMT[CR][LF]
-etag: "21025-dc7-39462498"[CR][LF]
-accept-ranges: bytes[CR][LF]
-content-length: 6[CR][LF]
-content-type: text/html[CR][LF]
-funny-head: yesyes[CR][LF]
-via: 1.1 nghttpx[CR][LF]
-[CR][LF]
--foo-[LF]
-HTTP/2 200 [CR][LF]
-date: Tue, 09 Nov 2010 14:49:00 GMT[CR][LF]
 content-length: 6[CR][LF]
 content-type: text/html[CR][LF]
 via: 1.1 nghttpx[CR][LF]
== Contents of files in the log/ dir after test 1700
=== Start of file check-expected
 HTTP/1.1 101 Switching Protocols[CR][LF]
 Connection: Upgrade[CR][LF]
 Upgrade: h2c[CR][LF]
 [CR][LF]
 HTTP/2 200 [CR][LF]
 date: Tue, 09 Nov 2010 14:49:00 GMT[CR][LF]
 last-modified: Tue, 13 Jun 2000 12:10:00 GMT[CR][LF]
 etag: "21025-dc7-39462498"[CR][LF]
 accept-ranges: bytes[CR][LF]
 content-length: 6[CR][LF]
 content-type: text/html[CR][LF]
 funny-head: yesyes[CR][LF]
 via: 1.1 nghttpx[CR][LF]
 [CR][LF]
 -foo-[LF]
 HTTP/2 200 [CR][LF]
 date: Tue, 09 Nov 2010 14:49:00 GMT[CR][LF]
 content-length: 6[CR][LF]
 content-type: text/html[CR][LF]
 via: 1.1 nghttpx[CR][LF]
 [CR][LF]
 -maa-[LF]
=== End of file check-expected
=== Start of file check-generated
 HTTP/1.1 101 Switching Protocols[CR][LF]
 Connection: Upgrade[CR][LF]
 Upgrade: h2c[CR][LF]
 [CR][LF]
 HTTP/2 200 [CR][LF]
 date: Tue, 09 Nov 2010 14:49:00 GMT[CR][LF]
 content-length: 6[CR][LF]
 content-type: text/html[CR][LF]
 via: 1.1 nghttpx[CR][LF]
 [CR][LF]
 -maa-[LF]
=== End of file check-generated
=== Start of file commands.log
 ../libtool --mode=execute /usr/bin/valgrind --tool=memcheck --quiet --leak-check=yes --suppressions=./valgrind.supp --num-callers=16 --log-file=log/valgrind1700 ../src/curl --include --trace-ascii log/trace1700 --trace-time http://127.0.0.1:23921/1700 --http2 http://127.0.0.1:23921/17000001 >log/stdout1700 2>log/stderr1700
=== End of file commands.log
=== Start of file ftpserver.cmd
 Testnum 1700
=== End of file ftpserver.cmd
=== Start of file http_server.log
 12:14:17.419643 Running HTTP IPv4 version on port 44555
 12:14:17.419955 Wrote pid 15688 to .http_server.pid
 12:14:17.419988 Wrote port 44555 to .http_server.port
 12:14:18.418725 ====> Client connect
 12:14:18.418746 accept_connection 3 returned 4
 12:14:18.418758 accept_connection 3 returned 0
 12:14:18.418770 Read 97 bytes
 12:14:18.418777 Process 97 bytes request
 12:14:18.418790 Got request: GET /verifiedserver HTTP/1.1
 12:14:18.418798 Are-we-friendly question received
 12:14:18.418817 Wrote request (97 bytes) input to log/server.input
 12:14:18.418836 Identifying ourselves as friends
 12:14:18.418886 Response sent (56 bytes) and written to log/server.response
 12:14:18.418897 special request received, no persistency
 12:14:18.418904 ====> Client disconnect 0
 12:14:20.586799 ====> Client connect
 12:14:20.586829 accept_connection 3 returned 4
 12:14:20.586847 accept_connection 3 returned 0
 12:14:20.586966 Read 130 bytes
 12:14:20.587004 Process 130 bytes request
 12:14:20.587047 Got request: GET /1700 HTTP/1.1
 12:14:20.587058 Requested test number 1700 part 0
 12:14:20.587103 - request found to be complete (1700)
 12:14:20.587151 Wrote request (130 bytes) input to log/server.input
 12:14:20.587177 Send response test1700 section <data>
 12:14:20.587328 Response sent (256 bytes) and written to log/server.response
 12:14:20.587342 => persistent connection request ended, awaits new request
 12:14:20.587437 Connection closed by client
 12:14:20.587453 ====> Client disconnect 0
 12:14:20.753007 ====> Client connect
 12:14:20.753054 accept_connection 3 returned 4
 12:14:20.753071 accept_connection 3 returned 0
 12:14:20.753088 Read 132 bytes
 12:14:20.753099 Process 132 bytes request
 12:14:20.753114 Got request: GET /17000001 HTTP/1.1
 12:14:20.753125 Requested test number 1700 part 1
 12:14:20.753160 - request found to be complete (1700)
 12:14:20.753195 Wrote request (132 bytes) input to log/server.input
 12:14:20.753211 Send response test1700 section <data1>
 12:14:20.753356 Response sent (119 bytes) and written to log/server.response
 12:14:20.753371 => persistent connection request ended, awaits new request
 12:14:20.753434 Connection closed by client
 12:14:20.753447 ====> Client disconnect 0
=== End of file http_server.log
=== Start of file http_verify.log
 *   Trying 127.0.0.1:44555...
 * Connected to 127.0.0.1 (127.0.0.1) port 44555 (#0)
 > GET /verifiedserver HTTP/1.1
 > Host: 127.0.0.1:44555
 > User-Agent: curl/7.77.0-DEV
 > Accept: */*
 > 
 * Mark bundle as not supporting multiuse
 < HTTP/1.1 200 OK
 < Content-Length: 17
 < 
 { [17 bytes data]
 * Connection #0 to host 127.0.0.1 left intact
=== End of file http_verify.log
=== Start of file http_verify.out
 WE ROOLZ: 15688
=== End of file http_verify.out
=== Start of file server.input
 GET /1700 HTTP/1.1
 Host: 127.0.0.1:23921
 User-Agent: curl/7.77.0-DEV
 Accept: */*
 X-Forwarded-Proto: http
 Via: 1.1 nghttpx
 GET /17000001 HTTP/1.1
 Host: 127.0.0.1:23921
 User-Agent: curl/7.77.0-DEV
 Accept: */*
 X-Forwarded-Proto: http
 Via: 2 nghttpx
=== End of file server.input
=== Start of file server.response
 HTTP/1.1 200 OK
 Content-Length: 17
 WE ROOLZ: 15688
 HTTP/1.1 200 OK
 Date: Tue, 09 Nov 2010 14:49:00 GMT
 Server: test-server/fake
 Last-Modified: Tue, 13 Jun 2000 12:10:00 GMT
 ETag: "21025-dc7-39462498"
 Accept-Ranges: bytes
 Content-Length: 6
 Connection: close
 Content-Type: text/html
 Funny-head: yesyes
 -foo-
 HTTP/1.1 200 OK
 Date: Tue, 09 Nov 2010 14:49:00 GMT
 Content-Length: 6
 Connection: close
 Content-Type: text/html
 -maa-
=== End of file server.response
=== Start of file stderr1700
   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                  Dload  Upload   Total   Spent    Left  Speed
 
   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
 curl: (52) Empty reply from server
   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                  Dload  Upload   Total   Spent    Left  Speed
 
   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
 100     6  100     6    0     0    123      0 --:--:-- --:--:-- --:--:--   162
=== End of file stderr1700
=== Start of file stdout1700
 HTTP/1.1 101 Switching Protocols
 Connection: Upgrade
 Upgrade: h2c
 HTTP/2 200 
 date: Tue, 09 Nov 2010 14:49:00 GMT
 content-length: 6
 content-type: text/html
 server: nghttpx
 via: 1.1 nghttpx
 -maa-
=== End of file stdout1700
=== Start of file trace1700
 12:14:20.525480 == Info:   Trying 127.0.0.1:23921...
 12:14:20.567961 == Info: Connected to 127.0.0.1 (127.0.0.1) port 23921 (#0)
 12:14:20.586830 => Send header, 180 bytes (0xb4)
 0000: GET /1700 HTTP/1.1
 0014: Host: 127.0.0.1:23921
 002b: User-Agent: curl/7.77.0-DEV
 0048: Accept: */*
 0055: Connection: Upgrade, HTTP2-Settings
 007a: Upgrade: h2c
 0088: HTTP2-Settings: AAMAAABkAAQCAAAAAAIAAAAA
 00b2: 
 12:14:20.602866 == Info: Mark bundle as not supporting multiuse
 12:14:20.606111 <= Recv header, 34 bytes (0x22)
 0000: HTTP/1.1 101 Switching Protocols
 12:14:20.611170 <= Recv header, 21 bytes (0x15)
 0000: Connection: Upgrade
 12:14:20.611825 <= Recv header, 14 bytes (0xe)
 0000: Upgrade: h2c
 12:14:20.612256 == Info: Received 101
 12:14:20.622847 == Info: Using HTTP2, server supports multi-use
 12:14:20.623214 == Info: Connection state changed (HTTP/2 confirmed)
 12:14:20.633714 == Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=172
 12:14:20.699200 == Info: Empty reply from server
 12:14:20.704770 == Info: Connection #0 to host 127.0.0.1 left intact
 12:14:20.722167 == Info: Found bundle for host 127.0.0.1: 0x52b17b0 [can multiplex]
 12:14:20.728961 == Info: Re-using existing connection! (#0) with host 127.0.0.1
 12:14:20.730109 == Info: Connected to 127.0.0.1 (127.0.0.1) port 23921 (#0)
 12:14:20.740895 == Info: Using Stream ID: 3 (easy handle 0x52c86c0)
 12:14:20.755243 => Send header, 89 bytes (0x59)
 0000: GET /17000001 HTTP/2
 0016: Host: 127.0.0.1:23921
 002d: user-agent: curl/7.77.0-DEV
 004a: accept: */*
 0057: 
 12:14:20.760030 <= Recv header, 13 bytes (0xd)
 0000: HTTP/2 200 
 12:14:20.760548 <= Recv header, 37 bytes (0x25)
 0000: date: Tue, 09 Nov 2010 14:49:00 GMT
 12:14:20.761717 <= Recv header, 19 bytes (0x13)
 0000: content-length: 6
 12:14:20.762964 <= Recv header, 25 bytes (0x19)
 0000: content-type: text/html
 12:14:20.763158 <= Recv header, 17 bytes (0x11)
 0000: server: nghttpx
 12:14:20.763299 <= Recv header, 18 bytes (0x12)
 0000: via: 1.1 nghttpx
 12:14:20.764487 <= Recv header, 2 bytes (0x2)
 0000: 
 12:14:20.765634 <= Recv data, 6 bytes (0x6)
 0000: -maa-.
 12:14:20.769602 == Info: Connection #0 to host 127.0.0.1 left intact
=== End of file trace1700

Test suite total running time breakdown per task...

Spent 0002.021 seconds starting and verifying test harness servers.
Spent 0000.004 seconds reading definitions and doing test preparations.
Spent 0001.407 seconds actually running test tools.
Spent 0000.000 seconds awaiting server logs lock removal.
Spent 0000.001 seconds verifying test results.
Spent 0003.432 seconds doing all of the above.

Test server starting and verification time per test (top 25)...

-time-  test
------  ----
02.021  1700

Test definition reading and preparation time per test (top 10)...

-time-  test
------  ----
00.004  1700

Test tool execution time per test (top 25)...

-time-  test
------  ----
01.407  1700

Test server logs lock removal time per test (top 15)...

-time-  test
------  ----
00.000  1700

Test results verification time per test (top 10)...

-time-  test
------  ----
00.001  1700

Total time per test (top 50)...

-time-  test
------  ----
03.432  1700

TESTDONE: 1 tests were considered during 3 seconds.
TESTDONE: 0 tests out of 1 reported OK: 0%

TESTFAIL: These test cases failed: 1700

The raw testing logs for case 1700 (as from the ./tests/log/ directory) have been pulled from the built image (using docker cp $(docker create $IMAGE_NAME):/curl/tests/log .) and uploaded to a temporary git repository for further inspection in case that's needed: https://github.com/starrify/curl-test-failure-1700

The temporary git repository also contains all three pieces of raw texts shared above.

Observations from online CI runs

However I'm yet unable to observe the exact failure on these three cases (1700 / 1701 / 1702) from recent online CI runs, although they often fail due to other reasons.

In all recent CI runs that I randomly picked and manually checked, the outcome of test case 1700 is observed to belong to two categories:

  1. Where the test case finishes successfully. (example 1, example 2)
  2. Where the test case is skipped at all. (example 1, example 2)

Further steps

Further triage may be needed for locating the exact cause of issue (curl code / test case / upstream tools like nghttp2 / etc.)

I would like to spend some more time on further understanding the reasons behind the failure. However given my lack of familiarity with this project, that might take some time.

Therefore I'm filing this issue in advance, so that the community may be aware of the failures (or maybe someone may come and tell me that the issue was merely caused by some silly mistake of mine 😅).

@bagder
Copy link
Member

bagder commented May 8, 2021

Those tests are seriously flaky. On my dev machine at home they fail reliably if I run them with valgrind enabled, but work if I run without valgrind!

fails

./runtests.pl 1700 1701 1702

works

./runtests.pl -n 1700 1701 1702

@starrify
Copy link
Contributor Author

starrify commented May 10, 2021

TD;DR: What's known so far

The observed issue is believed to have been caused by nghttp2's reverse proxy (used in the HTTP/2 tests) which sends the response payload immediately following the h2c-upgrade protocol switch, other than waiting for the client-side connection preface.

Although curl is aware of such residual data and attempts to feed it to nghttp2 for parsing, such data may be eventually lost at a later stage in http2_recv due to the HTTP stream state.

The role of valgrind here is for timing. Without valgrind, the client-side connection preface is sent fast enough, therefore the frames are still in a good order. With valgrind's presence, the client-side connection preface gets delayed and the rfc-incompliant response arrives early, thus triggering the issue.

Sharing some raw debugging data from my local runs

In the earlier mentioned temporary repository https://github.com/starrify/curl-test-failure-1700 I have added further raw data recorded during local investigations:

(the captured traffic and debugging output come from different runs)

Observation: captured traffic for the succeeded and failed tests

Inspection of curl's TCP connection to nghttpx during the tests suggests significant differences.

When running without valgrind, the traffic looks good. (click here for details)
$ tshark -r test1700_without_valgrind.pcap 'tcp.stream == 1'
   15   1.031336    127.0.0.1 35058 127.0.0.1    23859 1 TCP 74 35058 → 23859 [SYN] Seq=0 Win=65495 [TCP CHECKSUM INCORRECT] Len=0 MSS=65495 SACK_PERM=1 TSval=259857891 TSecr=0 WS=128
   16   1.031352    127.0.0.1 23859 127.0.0.1    35058 1 TCP 74 23859 → 35058 [SYN, ACK] Seq=0 Ack=1 Win=65483 [TCP CHECKSUM INCORRECT] Len=0 MSS=65495 SACK_PERM=1 TSval=259857891 TSecr=259857891 WS=128
   17   1.031363    127.0.0.1 35058 127.0.0.1    23859 1 TCP 66 35058 → 23859 [ACK] Seq=1 Ack=1 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857891 TSecr=259857891
   18   1.031795    127.0.0.1 35058 127.0.0.1    23859 1 HTTP 246 GET /1700 HTTP/1.1 
   19   1.031806    127.0.0.1 23859 127.0.0.1    35058 1 TCP 66 23859 → 35058 [ACK] Seq=1 Ack=181 Win=65408 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857892 TSecr=259857892
   25   1.032187    127.0.0.1 23859 127.0.0.1    35058 1 HTTP2 164 HTTP/1.1 101 Switching Protocols , SETTINGS[0]
   26   1.032196    127.0.0.1 35058 127.0.0.1    23859 1 TCP 66 35058 → 23859 [ACK] Seq=181 Ack=99 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857892 TSecr=259857892
   27   1.032306    127.0.0.1 35058 127.0.0.1    23859 1 HTTP2 90 Magic
   28   1.032310    127.0.0.1 23859 127.0.0.1    35058 1 TCP 66 23859 → 35058 [ACK] Seq=99 Ack=205 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857892 TSecr=259857892
   29   1.032321    127.0.0.1 35058 127.0.0.1    23859 1 HTTP2 93 SETTINGS[0]
   30   1.032325    127.0.0.1 23859 127.0.0.1    35058 1 TCP 66 23859 → 35058 [ACK] Seq=99 Ack=232 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857892 TSecr=259857892
   31   1.032332    127.0.0.1 35058 127.0.0.1    23859 1 HTTP2 75 SETTINGS[0]
   33   1.032337    127.0.0.1 35058 127.0.0.1    23859 1 HTTP2 79 WINDOW_UPDATE[0]
   35   1.032337    127.0.0.1 23859 127.0.0.1    35058 1 HTTP2 75 SETTINGS[0]
   36   1.032342    127.0.0.1 35058 127.0.0.1    23859 1 TCP 66 35058 → 23859 [ACK] Seq=254 Ack=108 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857892 TSecr=259857892
   37   1.032347    127.0.0.1 23859 127.0.0.1    35058 1 TCP 66 23859 → 35058 [ACK] Seq=108 Ack=241 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857892 TSecr=259857892
   40   1.032352    127.0.0.1 23859 127.0.0.1    35058 1 TCP 66 23859 → 35058 [ACK] Seq=108 Ack=254 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857892 TSecr=259857892
   64   1.032559    127.0.0.1 23859 127.0.0.1    35058 1 HTTP2 211 HEADERS[1]: 200 OK, DATA[1] (text/html)
   65   1.032564    127.0.0.1 35058 127.0.0.1    23859 1 TCP 66 35058 → 23859 [ACK] Seq=254 Ack=253 Win=65408 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857893 TSecr=259857893
   68   1.033416    127.0.0.1 35058 127.0.0.1    23859 1 HTTP2 117 HEADERS[3]: GET /17000001
   69   1.033423    127.0.0.1 23859 127.0.0.1    35058 1 TCP 66 23859 → 35058 [ACK] Seq=253 Ack=305 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857893 TSecr=259857893
   88   1.034039    127.0.0.1 23859 127.0.0.1    35058 1 HTTP2 99 HEADERS[3]: 200 OK, DATA[3] (text/html)
   89   1.034056    127.0.0.1 35058 127.0.0.1    23859 1 TCP 66 35058 → 23859 [ACK] Seq=305 Ack=286 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857894 TSecr=259857894
   92   1.034336    127.0.0.1 35058 127.0.0.1    23859 1 TCP 66 35058 → 23859 [FIN, ACK] Seq=305 Ack=286 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857894 TSecr=259857894
   93   1.034392    127.0.0.1 23859 127.0.0.1    35058 1 TCP 66 23859 → 35058 [FIN, ACK] Seq=286 Ack=306 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857894 TSecr=259857894
   94   1.034399    127.0.0.1 35058 127.0.0.1    23859 1 TCP 66 35058 → 23859 [ACK] Seq=306 Ack=287 Win=65536 [TCP CHECKSUM INCORRECT] Len=0 TSval=259857894 TSecr=259857894
When running with valgrind, the traffic looks suspicious where the server has the initial HEADERS and DATA frames before receiving the client-side connection preface. (click here for details)
$ tshark -r test1700_with_valgrind.pcap -o "tcp.check_checksum:False" 'tcp.stream == 1'
   15   1.882244    127.0.0.1 34954 127.0.0.1    23859 1 TCP 74 34954 → 23859 [SYN] Seq=0 Win=65495 Len=0 MSS=65495 SACK_PERM=1 TSval=259612162 TSecr=0 WS=128
   16   1.882255    127.0.0.1 23859 127.0.0.1    34954 1 TCP 74 23859 → 34954 [SYN, ACK] Seq=0 Ack=1 Win=65483 Len=0 MSS=65495 SACK_PERM=1 TSval=259612162 TSecr=259612162 WS=128
   17   1.882264    127.0.0.1 34954 127.0.0.1    23859 1 TCP 66 34954 → 23859 [ACK] Seq=1 Ack=1 Win=65536 Len=0 TSval=259612162 TSecr=259612162
   18   1.915319    127.0.0.1 34954 127.0.0.1    23859 1 HTTP 246 GET /1700 HTTP/1.1 
   19   1.915338    127.0.0.1 23859 127.0.0.1    34954 1 TCP 66 23859 → 34954 [ACK] Seq=1 Ack=181 Win=65408 Len=0 TSval=259612195 TSecr=259612195
   25   1.915801    127.0.0.1 23859 127.0.0.1    34954 1 HTTP2 164 HTTP/1.1 101 Switching Protocols , SETTINGS[0]
   26   1.915806    127.0.0.1 34954 127.0.0.1    23859 1 TCP 66 34954 → 23859 [ACK] Seq=181 Ack=99 Win=65536 Len=0 TSval=259612196 TSecr=259612196
   54   1.916160    127.0.0.1 23859 127.0.0.1    34954 1 HTTP2 211 HEADERS[1]: 200 OK, DATA[1] (text/html)
   55   1.916165    127.0.0.1 34954 127.0.0.1    23859 1 TCP 66 34954 → 23859 [ACK] Seq=181 Ack=244 Win=65408 Len=0 TSval=259612196 TSecr=259612196
   58   2.002747    127.0.0.1 34954 127.0.0.1    23859 1 HTTP2 90 Magic
   59   2.002758    127.0.0.1 23859 127.0.0.1    34954 1 TCP 66 23859 → 34954 [ACK] Seq=244 Ack=205 Win=65536 Len=0 TSval=259612283 TSecr=259612283
   60   2.005614    127.0.0.1 34954 127.0.0.1    23859 1 HTTP2 93 SETTINGS[0]
   61   2.005618    127.0.0.1 23859 127.0.0.1    34954 1 TCP 66 23859 → 34954 [ACK] Seq=244 Ack=232 Win=65536 Len=0 TSval=259612286 TSecr=259612286
   62   2.005670    127.0.0.1 23859 127.0.0.1    34954 1 HTTP2 75 SETTINGS[0]
   63   2.005675    127.0.0.1 34954 127.0.0.1    23859 1 TCP 66 34954 → 23859 [ACK] Seq=232 Ack=253 Win=65536 Len=0 TSval=259612286 TSecr=259612286
   64   2.007539    127.0.0.1 34954 127.0.0.1    23859 1 HTTP2 75 SETTINGS[0]
   65   2.007544    127.0.0.1 23859 127.0.0.1    34954 1 TCP 66 23859 → 34954 [ACK] Seq=253 Ack=241 Win=65536 Len=0 TSval=259612287 TSecr=259612287
   66   2.008695    127.0.0.1 34954 127.0.0.1    23859 1 HTTP2 79 WINDOW_UPDATE[0]
   67   2.008698    127.0.0.1 23859 127.0.0.1    34954 1 TCP 66 23859 → 34954 [ACK] Seq=253 Ack=254 Win=65536 Len=0 TSval=259612289 TSecr=259612289
   68   2.073544    127.0.0.1 34954 127.0.0.1    23859 1 HTTP2 117 HEADERS[3]: GET /17000001
   69   2.073553    127.0.0.1 23859 127.0.0.1    34954 1 TCP 66 23859 → 34954 [ACK] Seq=253 Ack=305 Win=65536 Len=0 TSval=259612353 TSecr=259612353
   88   2.074081    127.0.0.1 23859 127.0.0.1    34954 1 HTTP2 99 HEADERS[3]: 200 OK, DATA[3] (text/html)
   89   2.074086    127.0.0.1 34954 127.0.0.1    23859 1 TCP 66 34954 → 23859 [ACK] Seq=305 Ack=286 Win=65536 Len=0 TSval=259612354 TSecr=259612354
   92   2.098971    127.0.0.1 34954 127.0.0.1    23859 1 TCP 66 34954 → 23859 [FIN, ACK] Seq=305 Ack=286 Win=65536 Len=0 TSval=259612379 TSecr=259612354
   93   2.099060    127.0.0.1 23859 127.0.0.1    34954 1 TCP 66 23859 → 34954 [FIN, ACK] Seq=286 Ack=306 Win=65536 Len=0 TSval=259612379 TSecr=259612379
   94   2.099067    127.0.0.1 34954 127.0.0.1    23859 1 TCP 66 34954 → 23859 [ACK] Seq=306 Ack=287 Win=65536 Len=0 TSval=259612379 TSecr=259612379

Analysis: RFC-incompliant behavior of nghttpx suggested

As per RFC 7540, each end shall send a connection preface before any other payload, while the client may be allowed to keep sending payloads without waiting for receiving the other end's connection preface (section 3.5). Also in the case of h2c-upgrade, both sides still need to send the connection preface (section 3.2).

Therefore the observed traffic in the above section suggests that nghttpx's behavior does not seem to follow the RFC strictly.

(I'm no HTTP/2 expert myself so don't take my comment too serious..)

Observation: the initial HTTP/2 payload dropped and empty reply reported

From the two curl debug output files shared above, there is an "Empty reply from server" message reported from the failed case (with valgrind):
 

$ grep -C 5 "Empty reply from server" test1700_{with,without}_valgrind_curl_debug.txt
test1700_with_valgrind_curl_debug.txt-11:45:00.343409 * Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=172
test1700_with_valgrind_curl_debug.txt-
test1700_with_valgrind_curl_debug.txt-11:45:00.412177 * STATE: PERFORMING => DONE handle 0x57d1f18; line 2359 (connection #0)
test1700_with_valgrind_curl_debug.txt-11:45:00.412655 * multi changed, check CONNECT_PEND queue!
test1700_with_valgrind_curl_debug.txt-11:45:00.413784 * multi_done
test1700_with_valgrind_curl_debug.txt:11:45:00.418142 * Empty reply from server
test1700_with_valgrind_curl_debug.txt-11:45:00.425353 * Connection #0 to host 127.0.0.1 left intact
test1700_with_valgrind_curl_debug.txt-11:45:00.428265 * Expire cleared (transfer 0x57d1f18)
test1700_with_valgrind_curl_debug.txt:curl: (52) Empty reply from server
test1700_with_valgrind_curl_debug.txt-11:45:00.449621 * STATE: INIT => CONNECT handle 0x5806178; line 1753 (connection #-5000)
test1700_with_valgrind_curl_debug.txt-11:45:00.450929 * Found bundle for host 127.0.0.1: 0x57f15e8 [can multiplex]
test1700_with_valgrind_curl_debug.txt-11:45:00.460109 * Re-using existing connection! (#0) with host 127.0.0.1
test1700_with_valgrind_curl_debug.txt-11:45:00.461550 * Connected to 127.0.0.1 (127.0.0.1) port 23859 (#0)
test1700_with_valgrind_curl_debug.txt-11:45:00.462085 * STATE: CONNECT => DO handle 0x5806178; line 1807 (connection #0)

Given the relative position within the logs, this suggests that curl failed to recognize the first response in HTTP/2.

It is worth noticing that the above logs also suggest a payload of 172 bytes that was carried-over to HTTP/2 upon receiving the HTTP/1.1 switch protocol response. The number 172 matches the combined size of the initial 3 frames from the server: a SETTINGS then an HEADERS then a DATA.

Analysis: curl seems not picking up the parsed HTTP/2 payload although aware of that

(sorry I don't have the raw testing results prepared for descriptions in this section)

curl is aware of the possible non-empty receiving buffer at the point of protocol switch, and handles that properly by having the data copied to the connection buffer and fed to nghttp2 for parsing:

curl/lib/http2.c

Lines 2331 to 2339 in 1763ace

if(nread)
memcpy(httpc->inbuf, mem, nread);
httpc->inbuflen = nread;
DEBUGASSERT(httpc->nread_inbuf == 0);
if(-1 == h2_process_pending_input(data, httpc, &result))
return CURLE_HTTP2;

By further debugging practices, I also observed that the corresponding callbacks (e.g. on_frame_recv and on_header) were properly invoked when the residual payload was parsed by nghttp2.

By linking my local debugging build of curl to a local debugging build of nghttp2 I was able to further examine the nghttp2 debugging output, which did not look weird to me.

Further inspections suggested that the parsed HTTP/2 response was dropped (or more like ignored) at the entrance of http2_recv, as the HTTP stream is already deemed as closed when the below code is reached:

curl/lib/http2.c

Lines 1622 to 1624 in 1763ace

if(stream->closed)
/* closed overrides paused */
return http2_handle_stream_close(conn, data, stream, err);

starrify added a commit to starrify/curl that referenced this issue May 10, 2021
This may be deemed necessary since some servers (e.g. nghttp2's reverse
proxy) may start sending the response payload immediately following the
server-side connection preface, other than waiting for the client's
connection preface and possible setting negotiations.

Resolves curl#7036. Please refer to this issue for further details.
@starrify
Copy link
Contributor Author

It is confirmed that 252790c is the revision in which this issue may be first triggered.

Click here for debugging output (passing -v than --trace*) with -DDEBUG_HTTP2 at 252790c~1 on test case 1700: residual payload drained and picked up, thus the output is complete (issue not reproduced).
$ /usr/sbin/valgrind --tool=memcheck --leak-check=yes --suppressions=./valgrind.supp --num-callers=16 ../src/curl --include -v --trace-time http://127.0.0.1:23859/1700 --http2 http://127.0.0.1:23859/17000001
==3065573== Memcheck, a memory error detector
==3065573== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==3065573== Using Valgrind-3.16.1 and LibVEX; rerun with -h for copyright info
==3065573== Command: ../src/curl --include -v --trace-time http://127.0.0.1:23859/1700 --http2 http://127.0.0.1:23859/17000001
==3065573== 
21:52:01.217538 *   Trying 127.0.0.1:23859...
21:52:01.254122 * Connected to 127.0.0.1 (127.0.0.1) port 23859 (#0)
21:52:01.271917 > GET /1700 HTTP/1.1
21:52:01.271917 > Host: 127.0.0.1:23859
21:52:01.271917 > User-Agent: curl/7.77.0-DEV
21:52:01.271917 > Accept: */*
21:52:01.271917 > Connection: Upgrade, HTTP2-Settings
21:52:01.271917 > Upgrade: h2c
21:52:01.271917 > HTTP2-Settings: AAMAAABkAAQCAAAAAAIAAAAA
21:52:01.271917 > 
21:52:01.286979 * Mark bundle as not supporting multiuse
21:52:01.289620 < HTTP/1.1 101 Switching Protocols
HTTP/1.1 101 Switching Protocols
21:52:01.294271 < Connection: Upgrade
Connection: Upgrade
21:52:01.296483 < Upgrade: h2c
Upgrade: h2c
21:52:01.297040 * Received 101
21:52:01.306151 * Using HTTP2, server supports multi-use
21:52:01.306775 * Connection state changed (HTTP/2 confirmed)
21:52:01.317752 * Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=172
21:52:01.327813 * Got SETTINGS
21:52:01.328925 * MAX_CONCURRENT_STREAMS == 100
21:52:01.329382 * ENABLE_PUSH == TRUE
21:52:01.333053 * on_begin_headers() was called
21:52:01.341940 * h2 status: HTTP/2 200 (easy 0x56d0c70)
21:52:01.349076 * h2 header: date: Tue, 09 Nov 2010 14:49:00 GMT
21:52:01.349653 * h2 header: last-modified: Tue, 13 Jun 2000 12:10:00 GMT
21:52:01.350489 * h2 header: etag: "21025-dc7-39462498"
21:52:01.350723 * h2 header: accept-ranges: bytes
21:52:01.352063 * h2 header: content-length: 6
21:52:01.352272 * h2 header: content-type: text/html
21:52:01.355007 * h2 header: funny-head: yesyes
21:52:01.355265 * h2 header: server: nghttpx
21:52:01.355626 * h2 header: via: 1.1 nghttpx
21:52:01.358080 * on_frame_recv() header 1 stream 1
21:52:01.359116 * Store 247 bytes headers from stream 1 at 0x56d4140
21:52:01.363975 * 6 data received for stream 1 (102147 left in buffer 0x56d4140, total 253)
21:52:01.365216 * on_frame_recv() header 0 stream 1
21:52:01.366739 * on_stream_close(), NO_ERROR (err 0), stream 1
21:52:01.367931 * Removed stream 1 hash!
21:52:01.371077 * h2_process_pending_input: All data in connection buffer processed

21:52:01.384924 * http2_recv: easy 0x56d0c70 (stream 0) win 33554426/4294967295
21:52:01.385409 * http2_recv: DRAIN 253 bytes stream 0!! (0x56d4140 => 0x56d4140)
21:52:01.385816 * h2_process_pending_input: All data in connection buffer processed
21:52:01.386310 * http2_recv: returns 253 for stream 0
21:52:01.386750 * Data returned for PAUSED stream 0
21:52:01.390059 < HTTP/2 200 
HTTP/2 200 
21:52:01.390328 < date: Tue, 09 Nov 2010 14:49:00 GMT
date: Tue, 09 Nov 2010 14:49:00 GMT
21:52:01.390684 < last-modified: Tue, 13 Jun 2000 12:10:00 GMT
last-modified: Tue, 13 Jun 2000 12:10:00 GMT
21:52:01.390907 < etag: "21025-dc7-39462498"
etag: "21025-dc7-39462498"
21:52:01.391159 < accept-ranges: bytes
accept-ranges: bytes
21:52:01.392494 < content-length: 6
content-length: 6
21:52:01.394045 < content-type: text/html
content-type: text/html
21:52:01.394307 < funny-head: yesyes
funny-head: yesyes
21:52:01.394589 < server: nghttpx
server: nghttpx
21:52:01.394773 < via: 1.1 nghttpx
via: 1.1 nghttpx

21:52:01.396169 < 
-foo-
21:52:01.399618 * http2_recv: easy 0x56d0c70 (stream 0) win 33554426/4294967295
21:52:01.400307 * nread=9
21:52:01.402585 * Got SETTINGS
21:52:01.402806 * MAX_CONCURRENT_STREAMS == 100
21:52:01.403018 * ENABLE_PUSH == TRUE
21:52:01.403274 * h2_process_pending_input: All data in connection buffer processed
21:52:01.413163 * Connection #0 to host 127.0.0.1 left intact
21:52:01.430130 * Found bundle for host 127.0.0.1: 0x56ee290 [can multiplex]
21:52:01.436799 * Re-using existing connection! (#0) with host 127.0.0.1
21:52:01.438082 * Connected to 127.0.0.1 (127.0.0.1) port 23859 (#0)
21:52:01.438971 * http2_send len=89
21:52:01.442643 * h2 header: :method:GET
21:52:01.443128 * h2 header: :path:/17000001
21:52:01.443300 * h2 header: :scheme:http
21:52:01.443493 * h2 header: :authority:127.0.0.1:23859
21:52:01.443699 * h2 header: user-agent:curl/7.77.0-DEV
21:52:01.443915 * h2 header: accept:*/*
21:52:01.444827 * http2_send request allowed 1 (easy handle 0x5705350)
21:52:01.448947 * Using Stream ID: 3 (easy handle 0x5705350)
21:52:01.463310 > GET /17000001 HTTP/2
21:52:01.463310 > Host: 127.0.0.1:23859
21:52:01.463310 > user-agent: curl/7.77.0-DEV
21:52:01.463310 > accept: */*
21:52:01.463310 > 
21:52:01.464960 * http2_recv: easy 0x5705350 (stream 3) win 33554426/33554432
21:52:01.465176 * nread=33
21:52:01.465432 * on_begin_headers() was called
21:52:01.465654 * h2 status: HTTP/2 200 (easy 0x5705350)
21:52:01.466045 * h2 header: date: Tue, 09 Nov 2010 14:49:00 GMT
21:52:01.466234 * h2 header: content-length: 6
21:52:01.466426 * h2 header: content-type: text/html
21:52:01.466654 * h2 header: server: nghttpx
21:52:01.466899 * h2 header: via: 1.1 nghttpx
21:52:01.467152 * on_frame_recv() header 1 stream 3
21:52:01.467339 * Store 131 bytes headers from stream 3 at 0x5708820
21:52:01.467565 * 6 data received for stream 3 (102263 left in buffer 0x5708820, total 137)
21:52:01.467935 * on_frame_recv() header 0 stream 3
21:52:01.468138 * on_stream_close(), NO_ERROR (err 0), stream 3
21:52:01.468323 * Removed stream 3 hash!
21:52:01.468536 * h2_process_pending_input: All data in connection buffer processed
21:52:01.468740 * http2_recv: returns 137 for stream 0
21:52:01.468993 * Data returned for PAUSED stream 0
21:52:01.469231 < HTTP/2 200 
HTTP/2 200 
21:52:01.469494 < date: Tue, 09 Nov 2010 14:49:00 GMT
date: Tue, 09 Nov 2010 14:49:00 GMT
21:52:01.469696 < content-length: 6
content-length: 6
21:52:01.470053 < content-type: text/html
content-type: text/html
21:52:01.470342 < server: nghttpx
server: nghttpx
21:52:01.470538 < via: 1.1 nghttpx
via: 1.1 nghttpx

21:52:01.470781 < 
-maa-
21:52:01.471060 * http2_recv: easy 0x5705350 (stream 0) win 33554420/4294967295
21:52:01.472155 * h2_process_pending_input: All data in connection buffer processed
21:52:01.472852 * http2_recv returns 0, http2_handle_stream_close
21:52:01.473373 * Connection #0 to host 127.0.0.1 left intact
==3065573== 
==3065573== HEAP SUMMARY:
==3065573==     in use at exit: 0 bytes in 0 blocks
==3065573==   total heap usage: 5,455 allocs, 5,455 frees, 602,392 bytes allocated
==3065573== 
==3065573== All heap blocks were freed -- no leaks are possible
==3065573== 
==3065573== For lists of detected and suppressed errors, rerun with: -s
==3065573== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
Click here for debugging output (passing -v than --trace*) with -DDEBUG_HTTP2 at 252790c on test case 1700: residual payload ignored, thus the output is missing (issue reproduced).
$ /usr/sbin/valgrind --tool=memcheck --leak-check=yes --suppressions=./valgrind.supp --num-callers=16 ../src/curl --include -v --trace-time http://127.0.0.1:23859/1700 --http2 http://127.0.0.1:23859/17000001
==3071609== Memcheck, a memory error detector
==3071609== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==3071609== Using Valgrind-3.16.1 and LibVEX; rerun with -h for copyright info
==3071609== Command: ../src/curl --include -v --trace-time http://127.0.0.1:23859/1700 --http2 http://127.0.0.1:23859/17000001
==3071609== 
21:54:07.617404 *   Trying 127.0.0.1:23859...
21:54:07.655020 * Connected to 127.0.0.1 (127.0.0.1) port 23859 (#0)
21:54:07.673475 > GET /1700 HTTP/1.1
21:54:07.673475 > Host: 127.0.0.1:23859
21:54:07.673475 > User-Agent: curl/7.77.0-DEV
21:54:07.673475 > Accept: */*
21:54:07.673475 > Connection: Upgrade, HTTP2-Settings
21:54:07.673475 > Upgrade: h2c
21:54:07.673475 > HTTP2-Settings: AAMAAABkAAQCAAAAAAIAAAAA
21:54:07.673475 > 
21:54:07.688477 * Mark bundle as not supporting multiuse
21:54:07.691220 < HTTP/1.1 101 Switching Protocols
HTTP/1.1 101 Switching Protocols
21:54:07.695587 < Connection: Upgrade
Connection: Upgrade
21:54:07.697504 < Upgrade: h2c
Upgrade: h2c
21:54:07.698414 * Received 101
21:54:07.707435 * Using HTTP2, server supports multi-use
21:54:07.707959 * Connection state changed (HTTP/2 confirmed)
21:54:07.718672 * Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=172
21:54:07.726584 * Got SETTINGS
21:54:07.727365 * MAX_CONCURRENT_STREAMS == 100
21:54:07.727781 * ENABLE_PUSH == TRUE
21:54:07.731702 * on_begin_headers() was called
21:54:07.740354 * h2 status: HTTP/2 200 (easy 0x56d0c70)
21:54:07.747663 * h2 header: date: Tue, 09 Nov 2010 14:49:00 GMT
21:54:07.748171 * h2 header: last-modified: Tue, 13 Jun 2000 12:10:00 GMT
21:54:07.749078 * h2 header: etag: "21025-dc7-39462498"
21:54:07.749396 * h2 header: accept-ranges: bytes
21:54:07.750739 * h2 header: content-length: 6
21:54:07.750973 * h2 header: content-type: text/html
21:54:07.753539 * h2 header: funny-head: yesyes
21:54:07.753751 * h2 header: server: nghttpx
21:54:07.754044 * h2 header: via: 1.1 nghttpx
21:54:07.756515 * on_frame_recv() header 1 stream 1
21:54:07.757456 * Store 247 bytes headers from stream 1 at 0x56d4140
21:54:07.761926 * 6 data received for stream 1 (102147 left in buffer 0x56d4140, total 253)
21:54:07.763190 * on_frame_recv() header 0 stream 1
21:54:07.764755 * on_stream_close(), NO_ERROR (err 0), stream 1
21:54:07.765849 * Removed stream 1 hash!
21:54:07.768979 * h2_process_pending_input: All data in connection buffer processed

21:54:07.782025 * h2_process_pending_input: All data in connection buffer processed
21:54:07.782974 * http2_recv returns 0, http2_handle_stream_close
21:54:07.784733 * http2_recv: easy 0x56d0c70 (stream 0) win 33554426/4294967295
21:54:07.785554 * nread=9
21:54:07.787622 * Got SETTINGS
21:54:07.787888 * MAX_CONCURRENT_STREAMS == 100
21:54:07.788176 * ENABLE_PUSH == TRUE
21:54:07.788439 * h2_process_pending_input: All data in connection buffer processed
21:54:07.789023 * http2_recv returns AGAIN for stream 0
21:54:07.795843 * Empty reply from server
21:54:07.800358 * Connection #0 to host 127.0.0.1 left intact
curl: (52) Empty reply from server
21:54:07.817389 * Found bundle for host 127.0.0.1: 0x56ee290 [can multiplex]
21:54:07.824584 * Re-using existing connection! (#0) with host 127.0.0.1
21:54:07.825833 * Connected to 127.0.0.1 (127.0.0.1) port 23859 (#0)
21:54:07.826817 * http2_send len=89
21:54:07.830644 * h2 header: :method:GET
21:54:07.831164 * h2 header: :path:/17000001
21:54:07.831393 * h2 header: :scheme:http
21:54:07.831632 * h2 header: :authority:127.0.0.1:23859
21:54:07.831817 * h2 header: user-agent:curl/7.77.0-DEV
21:54:07.832053 * h2 header: accept:*/*
21:54:07.832929 * http2_send request allowed 1 (easy handle 0x5704e60)
21:54:07.837321 * Using Stream ID: 3 (easy handle 0x5704e60)
21:54:07.851057 > GET /17000001 HTTP/2
21:54:07.851057 > Host: 127.0.0.1:23859
21:54:07.851057 > user-agent: curl/7.77.0-DEV
21:54:07.851057 > accept: */*
21:54:07.851057 > 
21:54:07.852585 * http2_recv: easy 0x5704e60 (stream 3) win 33554426/33554432
21:54:07.852867 * nread=33
21:54:07.853042 * on_begin_headers() was called
21:54:07.853279 * h2 status: HTTP/2 200 (easy 0x5704e60)
21:54:07.853714 * h2 header: date: Tue, 09 Nov 2010 14:49:00 GMT
21:54:07.854021 * h2 header: content-length: 6
21:54:07.854257 * h2 header: content-type: text/html
21:54:07.854583 * h2 header: server: nghttpx
21:54:07.854809 * h2 header: via: 1.1 nghttpx
21:54:07.855039 * on_frame_recv() header 1 stream 3
21:54:07.855258 * Store 131 bytes headers from stream 3 at 0x5708330
21:54:07.855508 * 6 data received for stream 3 (102263 left in buffer 0x5708330, total 137)
21:54:07.855821 * on_frame_recv() header 0 stream 3
21:54:07.856053 * on_stream_close(), NO_ERROR (err 0), stream 3
21:54:07.856265 * Removed stream 3 hash!
21:54:07.856478 * h2_process_pending_input: All data in connection buffer processed
21:54:07.856883 * http2_recv: returns 137 for stream 0
21:54:07.857305 * Data returned for PAUSED stream 0
21:54:07.860547 < HTTP/2 200 
HTTP/2 200 
21:54:07.860850 < date: Tue, 09 Nov 2010 14:49:00 GMT
date: Tue, 09 Nov 2010 14:49:00 GMT
21:54:07.862318 < content-length: 6
content-length: 6
21:54:07.863759 < content-type: text/html
content-type: text/html
21:54:07.864011 < server: nghttpx
server: nghttpx
21:54:07.864249 < via: 1.1 nghttpx
via: 1.1 nghttpx

21:54:07.865711 < 
-maa-
21:54:07.869174 * h2_process_pending_input: All data in connection buffer processed
21:54:07.869454 * http2_recv returns 0, http2_handle_stream_close
21:54:07.870141 * Connection #0 to host 127.0.0.1 left intact
==3071609== 
==3071609== HEAP SUMMARY:
==3071609==     in use at exit: 0 bytes in 0 blocks
==3071609==   total heap usage: 5,439 allocs, 5,439 frees, 602,102 bytes allocated
==3071609== 
==3071609== All heap blocks were freed -- no leaks are possible
==3071609== 
==3071609== For lists of detected and suppressed errors, rerun with: -s
==3071609== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

starrify added a commit to starrify/curl that referenced this issue May 10, 2021
This is considered not harmful as a following http2_recv shall be
called very soon.

This is considered helpful in the specific situation where some
servers (e.g. nghttpx v1.43.0) may fulfill stream 1 immediately
following the return of HTTP status 101, other than waiting for
the client-side connection preface to arrive.

Resolves curl#7036.
@bagder bagder closed this as completed in 455a63c May 11, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
2 participants