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

Connection is retried via HTTP/2 after HTTP_1_1_REQUIRED is received in some cases #6862

Closed
ngg opened this issue Apr 7, 2021 · 23 comments
Closed
Assignees

Comments

@ngg
Copy link
Contributor

ngg commented Apr 7, 2021

I did this

We have a server, where some endpoints require TLS client cert authentication. As HTTP/2 does not support TLS renegotiation, when this endpoint is called, the server replies with HTTP_1_1_REQUIRED and a new connection is necessary.

In curl 7.76.0, there was a fix for the simplest case by closing the connection: #6793
However, if there is another multiplexed connection which uses the same HTTP/2 connection, this solution does not work.

To reproduce with an Apache server, use the following Dockerfile:

FROM httpd:2.4
RUN apt-get -y update && apt-get install -y openssl && rm -rf /var/lib/apt/lists/*
RUN yes '' | openssl req -x509 -newkey rsa:4096 -keyout conf/server.key -out conf/server.crt -days 365 -nodes
RUN \
echo Include conf/extra/httpd-ssl.conf >> conf/httpd.conf && \
echo LoadModule http2_module modules/mod_http2.so >> conf/httpd.conf && \
echo LoadModule ssl_module modules/mod_ssl.so >> conf/httpd.conf && \
echo LoadModule socache_shmcb_module modules/mod_socache_shmcb.so >> conf/httpd.conf && \
echo Protocols h2 http/1.1 >> conf/httpd.conf && \
echo "<Location /secure>" >> conf/httpd.conf && \
echo SSLVerifyClient require >> conf/httpd.conf && \
echo "</Location>" >> conf/httpd.conf
RUN dd if=/dev/zero of=htdocs/largefile count=128 bs=1M

If this Dockerfile is saved to an empty directory, run the following command in that directory to start the server:

docker build -t tlsrenego . && docker run --rm -it -p 8443:443 tlsrenego

When the server is running, call curl with:

curl -k -v -Z -o x -o x2 https://localhost:8443/largefile https://localhost:8443/secure

Around 50% of the time on my machine (but it's timing dependant, the size of the largefile might need to be modified in the Dockerfile above) the call is retried over HTTP/2.

Click here for example curl output when it went wrong!
* Found bundle for host localhost: 0x55940b5fcab0 [serially]
* Server doesn't support multiplex yet, wait
* No connections available.
DL% UL%  Dled  Uled  Xfers  Live   Qd Total     Current  Left    Speed

--  --      0     0     2     2     0 --:--:-- --:--:-- --:--:-- -9223      *   Trying ::1:8443...
* Connected to localhost (::1) port 8443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [1404 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [520 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x55940b609d10)
} [5 bytes data]
> GET /largefile HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.0-DEV
> accept: */*
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* Found bundle for host localhost: 0x55940b5fcab0 [can multiplex]
* Multiplexed connection found!
* Re-using existing connection! (#0) with host localhost
* Transfer was pending, now try another
* Using Stream ID: 3 (easy handle 0x55940b60b1a0)
} [5 bytes data]
> GET /secure HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.0-DEV
> accept: */*
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
} [5 bytes data]
< HTTP/2 200 
< date: Wed, 07 Apr 2021 13:51:32 GMT
< server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
< last-modified: Wed, 07 Apr 2021 13:51:15 GMT
< etag: "40000000-5bf6239719ac0"
< accept-ranges: bytes
< content-length: 1073741824
< 
{ [1154 bytes data]
* Connection died, retrying a fresh connect(retry count: 1)
* Issue another request to this URL: 'https://localhost:8443/secure'
* Found bundle for host localhost: 0x55940b5fcab0 [can multiplex]
* Hostname localhost was found in DNS cache
*   Trying ::1:8443...
* Transfer was pending, now try another
* Connected to localhost (::1) port 8443 (#1)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL re-using session ID
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [631 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [128 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x55940b60b1a0)
} [5 bytes data]
> GET /secure HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.0-DEV
> accept: */*
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
} [5 bytes data]
* HTTP/2 stream 0 was not closed cleanly: HTTP_1_1_REQUIRED (err 13)
* Downgrades to HTTP/1.1!
* Empty reply from server
* Closing connection 1
} [5 bytes data]
* TLSv1.3 (OUT), TLS alert, close notify (256):
} [2 bytes data]
* Issue another request to this URL: 'https://localhost:8443/secure'
* Found bundle for host localhost: 0x55940b5fcab0 [can multiplex]
* Hostname localhost was found in DNS cache
*   Trying ::1:8443...
* Transfer was pending, now try another
* Connected to localhost (::1) port 8443 (#2)
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL re-using session ID
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [628 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [128 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [21 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
} [5 bytes data]
> GET /secure HTTP/1.1
> Host: localhost:8443
> User-Agent: curl/7.76.0-DEV
> Accept: */*
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Request CERT (13):
{ [77 bytes data]
* TLSv1.3 (OUT), TLS handshake, Certificate (11):
} [40 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* TLSv1.3 (IN), TLS alert, unknown (628):
{ [2 bytes data]
* OpenSSL SSL_read: error:1409445C:SSL routines:ssl3_read_bytes:tlsv13 alert certificate required, errno 0
* Closing connection 2
curl: (56) Empty reply from server
{ [5 bytes data]

 23 --   237M     0     2     1     0  0:00:02 --:--:--  0:00:01  474M      
 47 --   489M     0     2     1     0  0:00:02  0:00:01  0:00:01  488M      

I expected the following

Curl should have retried the connection via HTTP/1.1, but it's retried with HTTP/2. It seems like that the HTTP/2 connection can stay in the pool (which is actually not a problem because further requests might be able to use that), and when that happen, the retry is done over HTTP/2. I think the proper solution would be to check the wanted HTTP version when choosing a connection to re-use.

curl/libcurl version

I've compiled curl from the 7.76 tag (https://github.com/curl/curl/tree/curl-7_76_0)

> curl -V                                 
curl 7.76.0-DEV (x86_64-pc-linux-gnu) libcurl/7.76.0-DEV OpenSSL/1.1.1k zlib/1.2.11 brotli/1.0.9 zstd/1.4.9 libidn2/2.3.0 libpsl/0.21.0 (+libidn2/2.3.0) nghttp2/1.41.0
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp 
Features: alt-svc AsynchDNS brotli HTTP2 HTTPS-proxy IDN IPv6 Largefile libz NTLM NTLM_WB PSL SSL TLS-SRP UnixSockets zstd

operating system

> uname -a                                                                                                                                                                                                                                    
Linux bp1-dsklin-3010 5.10.27-gentoo #3 SMP Mon Apr 5 18:40:24 CEST 2021 x86_64 Intel(R) Core(TM) i7-8700K CPU @ 3.70GHz GenuineIntel GNU/Linux
@bagder bagder self-assigned this Apr 7, 2021
@bagder
Copy link
Member

bagder commented Apr 7, 2021

I haven't worked on reproducing this yet, but I could imagine a fix could maybe be done something like this?

My idea is to make sure connection reuse isn't done if the existing connection uses HTTP version 2 or higher while the wanted HTTP version is lower than 2.

diff --git a/lib/url.c b/lib/url.c
index 19fcfb842..e576a7eb9 100644
--- a/lib/url.c
+++ b/lib/url.c
@@ -1313,10 +1313,15 @@ ConnectionExists(struct Curl_easy *data,
           /* one of them was different */
           continue;
         }
       }
 
+      if((needle->handler->protocol & PROTO_FAMILY_HTTP) &&
+         (check->httpversion >= 20) &&
+         (data->state.httpwant < CURL_HTTP_VERSION_2_0))
+        continue;
+
       if((needle->handler->flags&PROTOPT_SSL)
 #ifndef CURL_DISABLE_PROXY
          || !needle->bits.httpproxy || needle->bits.tunnel_proxy
 #endif
         ) {

@bagder
Copy link
Member

bagder commented Apr 10, 2021

@ngg any chance you can try this?

@ngg
Copy link
Contributor Author

ngg commented Apr 10, 2021

@ngg any chance you can try this?

This patch is not working for me, the same reproduction case still retries it with HTTP/2. I'll try to find out why.

@ngg
Copy link
Contributor Author

ngg commented Apr 10, 2021

I think that this new condition is ok, the connection reusing logic will work better this way, but it does not solve this exact problem because of another issue:

It looks like the first retry doesn't have the connection downgraded, because after calling Curl_readwrite(data->conn, data, &done, &comeback) from multi_runsingle, done will be true, so the if(done || (result == CURLE_RECV_ERROR)) branch will be taken instead of the next branch which would actually downgrade the connection.
done is true, result is CURLE_OK and Curl_h2_http_1_1_error(data->conn) would return true if it would be called in this case, but it is skipped.

I think the ordering of these branches is wrong, probably checking Curl_h2_http_1_1_error(data->conn) first would be the better choice even if result is CURLE_OK.

@bagder
Copy link
Member

bagder commented Apr 10, 2021

I'm not sure I see how that can work if HTTP_1_1_REQUIRED is actually what the server responds. If so, it seems to suggest that curl is already doing something wrong in an earlier step.

@bagder
Copy link
Member

bagder commented Apr 17, 2021

Is there a way to reproduce this issue against a public URL? Getting that thing up in a docker installation is a bit of a hurdle for me but if we can verify against something out there it would become a smaller effort.

@bagder bagder removed their assignment Apr 17, 2021
@ngg
Copy link
Contributor Author

ngg commented Apr 17, 2021

I started that docker image on a public server https://13.74.64.165. To make it easier to reproduce there are multiple large files hosted, named 1mb, 2mb, 4mb, 8mb, 16mb, 32mb, 64mb, 128mb.

Somehow it seems easier to reproduce with 3 connections instead of 2 if the server is remote.
I can reliably (2 out of 3 times) reproduce the issue after applying the patch with the following command:

curl -k -v -Z -o x -o x2 -o x3 https://13.74.64.165/1mb https://13.74.64.165/1mb https://13.74.64.165/secure 2>&1 | grep GET          
> GET /1mb HTTP/2
> GET /1mb HTTP/2
> GET /secure HTTP/2
> GET /secure HTTP/2
> GET /secure HTTP/1.1

As you can see, there are 3 connections to /secure, and only the third one uses HTTP 1.1

@bagder
Copy link
Member

bagder commented Apr 17, 2021

Thanks! With this I'll be able to get a better understanding of what's going on...

bagder added a commit that referenced this issue Apr 18, 2021
The data_pending() function is otherwise designed to let the logic
always drain the incoming socket before ending, but this is not a good
idea when the currennt transfer (when it is a h2 stream) ends before the
"drain" is done.

Reported-by: Gergely Nagy
Fixes #6862
@bagder bagder self-assigned this Apr 18, 2021
bagder added a commit that referenced this issue Apr 19, 2021
The data_pending() function is otherwise designed to let the logic
always drain the incoming socket before ending, but this is not a good
idea when the currennt transfer (when it is a h2 stream) ends before the
"drain" is done.

Reported-by: Gergely Nagy
Fixes #6862
@ngg
Copy link
Contributor Author

ngg commented Apr 19, 2021

Hi!
I applied both of these patches and I couldn't reproduce a case where there were a retry via HTTP2, so it's definitely better.

I've tried with different number of connections, different file sizes and I found that it still does not work in some cases, but it might be caused by another bug, because it can happen both when the patches are applied and without them.

It seems that in some cases, there is no retry at all after HTTP_1_1_REQUIRED is received, but unfortunately, I couldn't reproduce this with a remote server, only locally. With my original docker-based reproduction case, I've shrinked largefile to 16KB to have shorter outputs (but larger files can have this error as well). The command I'm running is:
curl -k -v -Z -o x -o x2 -o x3 https://localhost:8443/largefile https://localhost:8443/largefile https://localhost:8443/secure

Around 1 times out of 4, the retry is missing.

Output when there is (correctly) a retry
* STATE: INIT => CONNECT handle 0x55c9cb1f5de8; line 1634 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x55c9cb1f5de8; line 1680 (connection #0)
* STATE: INIT => CONNECT handle 0x55c9cb1f72b8; line 1634 (connection #-5000)
* Found bundle for host localhost: 0x55c9cb1e5d08 [serially]
* Server doesn't support multiplex yet, wait
* No connections available.
* STATE: CONNECT => PENDING handle 0x55c9cb1f72b8; line 1663 (connection #-5000)
* STATE: INIT => CONNECT handle 0x55c9cb1f8788; line 1634 (connection #-5000)
* Found bundle for host localhost: 0x55c9cb1e5d08 [serially]
* Server doesn't support multiplex yet, wait
* No connections available.
* STATE: CONNECT => PENDING handle 0x55c9cb1f8788; line 1663 (connection #-5000)
DL% UL%  Dled  Uled  Xfers  Live   Qd Total     Current  Left    Speed

--  --      0     0     3     3     0 --:--:-- --:--:-- --:--:-- -9223      * family0 == v6, family1 == v4
*   Trying ::1:8443...
* STATE: RESOLVING => CONNECTING handle 0x55c9cb1f5de8; line 1762 (connection #0)
* Connected to localhost (::1) port 8443 (#0)
* STATE: CONNECTING => PROTOCONNECT handle 0x55c9cb1f5de8; line 1825 (connection #0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x55c9cb1f5de8; line 1845 (connection #0)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [1404 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [520 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* STATE: PENDING => CONNECT handle 0x55c9cb1f72b8; line 3337 (connection #-5000)
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* STATE: PROTOCONNECTING => DO handle 0x55c9cb1f5de8; line 1864 (connection #0)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x55c9cb1f5de8)
} [5 bytes data]
> GET /largefile HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x55c9cb1f5de8; line 1922 (connection #0)
* multi changed, check CONNECT_PEND queue!
* STATE: PENDING => CONNECT handle 0x55c9cb1f8788; line 3337 (connection #-5000)
* STATE: DID => PERFORMING handle 0x55c9cb1f5de8; line 2041 (connection #0)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
* Found bundle for host localhost: 0x55c9cb1e5d08 [can multiplex]
* Multiplexed connection found!
* Re-using existing connection! (#0) with host localhost
* Transfer was pending, now try another
* STATE: CONNECT => DO handle 0x55c9cb1f72b8; line 1688 (connection #0)
* Using Stream ID: 3 (easy handle 0x55c9cb1f72b8)
} [5 bytes data]
> GET /largefile HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x55c9cb1f72b8; line 1922 (connection #0)
* STATE: DID => PERFORMING handle 0x55c9cb1f72b8; line 2041 (connection #0)
{ [5 bytes data]
* Found bundle for host localhost: 0x55c9cb1e5d08 [can multiplex]
* Multiplexed connection found!
* Re-using existing connection! (#0) with host localhost
* Transfer was pending, now try another
* STATE: CONNECT => DO handle 0x55c9cb1f8788; line 1688 (connection #0)
* Using Stream ID: 5 (easy handle 0x55c9cb1f8788)
} [5 bytes data]
> GET /secure HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x55c9cb1f8788; line 1922 (connection #0)
* STATE: DID => PERFORMING handle 0x55c9cb1f8788; line 2041 (connection #0)
{ [5 bytes data]
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
< date: Mon, 19 Apr 2021 07:27:50 GMT
< server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
< last-modified: Mon, 19 Apr 2021 06:59:24 GMT
< etag: "4000-5c04ddea62b00"
< accept-ranges: bytes
< content-length: 16384
< 
{ [1173 bytes data]
* STATE: PERFORMING => DONE handle 0x55c9cb1f5de8; line 2242 (connection #0)
* multi_done
* Connection still in use 2, no more multi_done now!
* Expire cleared (transfer 0x55c9cb1f5de8)
{ [5 bytes data]
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
< date: Mon, 19 Apr 2021 07:27:50 GMT
< server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
< last-modified: Mon, 19 Apr 2021 06:59:24 GMT
< etag: "4000-5c04ddea62b00"
< accept-ranges: bytes
< content-length: 16384
< 
{ [1252 bytes data]
* STATE: PERFORMING => DONE handle 0x55c9cb1f72b8; line 2242 (connection #0)
* multi_done
* Connection still in use 1, no more multi_done now!
* Expire cleared (transfer 0x55c9cb1f72b8)
* Curl_readwrite: forcibly told to drain data
* HTTP/2 stream 0 was not closed cleanly: HTTP_1_1_REQUIRED (err 13)
* Connection died, retrying a fresh connect(retry count: 1)
* Downgrades to HTTP/1.1!
* multi_done
* The cache now contains 0 members
* Closing connection 0
} [5 bytes data]
* TLSv1.3 (OUT), TLS alert, close notify (256):
} [2 bytes data]
* Issue another request to this URL: 'https://localhost:8443/secure'
* STATE: PERFORMING => CONNECT handle 0x55c9cb1f8788; line 2219 (connection #-5000)
* Added connection 1. The cache now contains 1 members
* Hostname localhost was found in DNS cache
* family0 == v6, family1 == v4
*   Trying ::1:8443...
* Transfer was pending, now try another
* STATE: CONNECT => CONNECTING handle 0x55c9cb1f8788; line 1695 (connection #1)
* Connected to localhost (::1) port 8443 (#1)
* STATE: CONNECTING => PROTOCONNECT handle 0x55c9cb1f8788; line 1825 (connection #1)
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL re-using session ID
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [628 bytes data]
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x55c9cb1f8788; line 1845 (connection #1)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [128 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [21 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* STATE: PROTOCONNECTING => DO handle 0x55c9cb1f8788; line 1864 (connection #1)
} [5 bytes data]
> GET /secure HTTP/1.1
> Host: localhost:8443
> User-Agent: curl/7.76.1-DEV
> Accept: */*
> 
* STATE: DO => DID handle 0x55c9cb1f8788; line 1922 (connection #1)
* STATE: DID => PERFORMING handle 0x55c9cb1f8788; line 2041 (connection #1)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Request CERT (13):
{ [77 bytes data]
* TLSv1.3 (OUT), TLS handshake, Certificate (11):
} [40 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* TLSv1.3 (IN), TLS alert, unknown (628):
{ [2 bytes data]
* OpenSSL SSL_read: error:1409445C:SSL routines:ssl3_read_bytes:tlsv13 alert certificate required, errno 0
* multi_done
* The cache now contains 0 members
* Closing connection 1
* Expire cleared (transfer 0x55c9cb1f8788)
curl: (56) OpenSSL SSL_read: error:1409445C:SSL routines:ssl3_read_bytes:tlsv13 alert certificate required, errno 0

100 --  32768     0     3     0     0 --:--:-- --:--:-- --:--:-- 1882k     
Output when the retry is missing
* STATE: INIT => CONNECT handle 0x559942393de8; line 1634 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x559942393de8; line 1680 (connection #0)
* STATE: INIT => CONNECT handle 0x5599423952b8; line 1634 (connection #-5000)
* Found bundle for host localhost: 0x559942383d08 [serially]
* Server doesn't support multiplex yet, wait
* No connections available.
* STATE: CONNECT => PENDING handle 0x5599423952b8; line 1663 (connection #-5000)
* STATE: INIT => CONNECT handle 0x559942396788; line 1634 (connection #-5000)
* Found bundle for host localhost: 0x559942383d08 [serially]
* Server doesn't support multiplex yet, wait
* No connections available.
* STATE: CONNECT => PENDING handle 0x559942396788; line 1663 (connection #-5000)
DL% UL%  Dled  Uled  Xfers  Live   Qd Total     Current  Left    Speed

--  --      0     0     3     3     0 --:--:-- --:--:-- --:--:-- -9223      * family0 == v6, family1 == v4
*   Trying ::1:8443...
* STATE: RESOLVING => CONNECTING handle 0x559942393de8; line 1762 (connection #0)
* Connected to localhost (::1) port 8443 (#0)
* STATE: CONNECTING => PROTOCONNECT handle 0x559942393de8; line 1825 (connection #0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x559942393de8; line 1845 (connection #0)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [1404 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [520 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* STATE: PENDING => CONNECT handle 0x5599423952b8; line 3337 (connection #-5000)
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* STATE: PROTOCONNECTING => DO handle 0x559942393de8; line 1864 (connection #0)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x559942393de8)
} [5 bytes data]
> GET /largefile HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x559942393de8; line 1922 (connection #0)
* multi changed, check CONNECT_PEND queue!
* STATE: PENDING => CONNECT handle 0x559942396788; line 3337 (connection #-5000)
* STATE: DID => PERFORMING handle 0x559942393de8; line 2041 (connection #0)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* Found bundle for host localhost: 0x559942383d08 [can multiplex]
* Multiplexed connection found!
* Re-using existing connection! (#0) with host localhost
* Transfer was pending, now try another
* STATE: CONNECT => DO handle 0x5599423952b8; line 1688 (connection #0)
* Using Stream ID: 3 (easy handle 0x5599423952b8)
} [5 bytes data]
> GET /largefile HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x5599423952b8; line 1922 (connection #0)
* STATE: DID => PERFORMING handle 0x5599423952b8; line 2041 (connection #0)
* Found bundle for host localhost: 0x559942383d08 [can multiplex]
* Multiplexed connection found!
* Re-using existing connection! (#0) with host localhost
* Transfer was pending, now try another
* STATE: CONNECT => DO handle 0x559942396788; line 1688 (connection #0)
* Using Stream ID: 5 (easy handle 0x559942396788)
} [5 bytes data]
> GET /secure HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x559942396788; line 1922 (connection #0)
* STATE: DID => PERFORMING handle 0x559942396788; line 2041 (connection #0)
{ [5 bytes data]
* Curl_readwrite: forcibly told to drain data
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
< date: Mon, 19 Apr 2021 07:28:12 GMT
< server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
< last-modified: Mon, 19 Apr 2021 06:59:24 GMT
< etag: "4000-5c04ddea62b00"
< accept-ranges: bytes
< content-length: 16384
< 
{ [1173 bytes data]
* STATE: PERFORMING => DONE handle 0x559942393de8; line 2242 (connection #0)
* multi_done
* Connection still in use 2, no more multi_done now!
* Expire cleared (transfer 0x559942393de8)
{ [5 bytes data]
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
< date: Mon, 19 Apr 2021 07:28:12 GMT
< server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
< last-modified: Mon, 19 Apr 2021 06:59:24 GMT
< etag: "4000-5c04ddea62b00"
< accept-ranges: bytes
< content-length: 16384
< 
{ [1252 bytes data]
* STATE: PERFORMING => DONE handle 0x5599423952b8; line 2242 (connection #0)
* multi_done
* Connection still in use 1, no more multi_done now!
* Expire cleared (transfer 0x5599423952b8)
* Curl_readwrite: forcibly told to drain data
* HTTP/2 stream 0 was closed cleanly, but before getting  all response header fields, treated as error
* multi_done
* stopped the pause stream!
* Connection #0 to host localhost left intact
* Expire cleared (transfer 0x559942396788)
curl: (92) HTTP/2 stream 0 was closed cleanly, but before getting  all response header fields, treated as error

100 --  32768     0     3     0     0 --:--:-- --:--:-- --:--:-- 2909k     

When there is no retry, this line is output which does not appear when it's working correctly: HTTP/2 stream 0 was closed cleanly, but before getting all response header fields, treated as error

@ngg
Copy link
Contributor Author

ngg commented Apr 19, 2021

After the new "fixup" commit (4fe8d00) it became worse, now the retries are sometimes happening over HTTP/2 again.

Output when the retry is over HTTP/2
* STATE: INIT => CONNECT handle 0x559ac481cde8; line 1634 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x559ac481cde8; line 1680 (connection #0)
* STATE: INIT => CONNECT handle 0x559ac481e2b8; line 1634 (connection #-5000)
* Found bundle for host localhost: 0x559ac480cd08 [serially]
* Server doesn't support multiplex yet, wait
* No connections available.
* STATE: CONNECT => PENDING handle 0x559ac481e2b8; line 1663 (connection #-5000)
* STATE: INIT => CONNECT handle 0x559ac481f788; line 1634 (connection #-5000)
* Found bundle for host localhost: 0x559ac480cd08 [serially]
* Server doesn't support multiplex yet, wait
* No connections available.
* STATE: CONNECT => PENDING handle 0x559ac481f788; line 1663 (connection #-5000)
DL% UL%  Dled  Uled  Xfers  Live   Qd Total     Current  Left    Speed

--  --      0     0     3     3     0 --:--:-- --:--:-- --:--:-- -9223      * family0 == v6, family1 == v4
*   Trying ::1:8443...
* STATE: RESOLVING => CONNECTING handle 0x559ac481cde8; line 1762 (connection #0)
* Connected to localhost (::1) port 8443 (#0)
* STATE: CONNECTING => PROTOCONNECT handle 0x559ac481cde8; line 1825 (connection #0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x559ac481cde8; line 1845 (connection #0)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [1404 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [520 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* STATE: PENDING => CONNECT handle 0x559ac481e2b8; line 3337 (connection #-5000)
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* STATE: PROTOCONNECTING => DO handle 0x559ac481cde8; line 1864 (connection #0)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x559ac481cde8)
} [5 bytes data]
> GET /largefile HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x559ac481cde8; line 1922 (connection #0)
* multi changed, check CONNECT_PEND queue!
* STATE: PENDING => CONNECT handle 0x559ac481f788; line 3337 (connection #-5000)
* STATE: DID => PERFORMING handle 0x559ac481cde8; line 2041 (connection #0)
* Found bundle for host localhost: 0x559ac480cd08 [can multiplex]
* Multiplexed connection found!
* Re-using existing connection! (#0) with host localhost
* Transfer was pending, now try another
* STATE: CONNECT => DO handle 0x559ac481e2b8; line 1688 (connection #0)
* Using Stream ID: 3 (easy handle 0x559ac481e2b8)
} [5 bytes data]
> GET /largefile HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x559ac481e2b8; line 1922 (connection #0)
* STATE: DID => PERFORMING handle 0x559ac481e2b8; line 2041 (connection #0)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
* Found bundle for host localhost: 0x559ac480cd08 [can multiplex]
* Multiplexed connection found!
* Re-using existing connection! (#0) with host localhost
* Transfer was pending, now try another
* STATE: CONNECT => DO handle 0x559ac481f788; line 1688 (connection #0)
* Using Stream ID: 5 (easy handle 0x559ac481f788)
} [5 bytes data]
> GET /secure HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x559ac481f788; line 1922 (connection #0)
* STATE: DID => PERFORMING handle 0x559ac481f788; line 2041 (connection #0)
{ [5 bytes data]
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
< date: Mon, 19 Apr 2021 07:38:25 GMT
< server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
< last-modified: Mon, 19 Apr 2021 06:59:24 GMT
< etag: "4000-5c04ddea62b00"
< accept-ranges: bytes
< content-length: 16384
< 
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
< date: Mon, 19 Apr 2021 07:38:25 GMT
< server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
< last-modified: Mon, 19 Apr 2021 06:59:24 GMT
< etag: "4000-5c04ddea62b00"
< accept-ranges: bytes
< content-length: 16384
< 
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1134 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1291 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
* Connection died, retrying a fresh connect(retry count: 1)
* multi_done
* Connection still in use 2, no more multi_done now!
* Issue another request to this URL: 'https://localhost:8443/secure'
* STATE: PERFORMING => CONNECT handle 0x559ac481f788; line 2219 (connection #-5000)
* Found bundle for host localhost: 0x559ac480cd08 [can multiplex]
* Added connection 1. The cache now contains 2 members
* Hostname localhost was found in DNS cache
* family0 == v6, family1 == v4
*   Trying ::1:8443...
* Transfer was pending, now try another
* STATE: CONNECT => CONNECTING handle 0x559ac481f788; line 1695 (connection #1)
* Connected to localhost (::1) port 8443 (#1)
* STATE: CONNECTING => PROTOCONNECT handle 0x559ac481f788; line 1825 (connection #1)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL re-using session ID
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [631 bytes data]
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x559ac481f788; line 1845 (connection #1)
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [1278 bytes data]
* Curl_readwrite: forcibly told to drain data
{ [892 bytes data]
* nread == 0, stream closed, bailing
* STATE: PERFORMING => DONE handle 0x559ac481cde8; line 2242 (connection #0)
* multi_done
* Connection still in use 1, no more multi_done now!
* Expire cleared (transfer 0x559ac481cde8)
* Curl_readwrite: forcibly told to drain data
{ [892 bytes data]
* nread == 0, stream closed, bailing
* STATE: PERFORMING => DONE handle 0x559ac481e2b8; line 2242 (connection #0)
* multi_done
* The cache now contains 1 members
* Closing connection 0
} [5 bytes data]
* TLSv1.3 (OUT), TLS alert, close notify (256):
} [2 bytes data]
* Expire cleared (transfer 0x559ac481e2b8)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [128 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* STATE: PROTOCONNECTING => DO handle 0x559ac481f788; line 1864 (connection #1)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x559ac481f788)
} [5 bytes data]
> GET /secure HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.1-DEV
> accept: */*
> 
* STATE: DO => DID handle 0x559ac481f788; line 1922 (connection #1)
* multi changed, check CONNECT_PEND queue!
* STATE: DID => PERFORMING handle 0x559ac481f788; line 2041 (connection #1)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* STATE: PERFORMING => DONE handle 0x559ac481f788; line 2242 (connection #1)
* multi_done
* Empty reply from server
* Connection #1 to host localhost left intact
* Expire cleared (transfer 0x559ac481f788)
curl: (52) Empty reply from server

100 --  32768     0     3     0     0 --:--:-- --:--:-- --:--:-- 1882k     

@bagder
Copy link
Member

bagder commented Apr 19, 2021

The initial patch broke ordinary HTTP tests. The second try wasn't done properly either since it re-used the is_empty_data boolean wrongly. Now there's a third one.

@bagder
Copy link
Member

bagder commented Apr 19, 2021

The retry was and is (probably) still missing because curl fails to store return the correct reason back. If you can reproduce the problem, then an even more useful log of it would be to add --trace-ascii dump to the command line to get everything stored and adding this little debug this for added h2 detail:

diff --git a/lib/http2.c b/lib/http2.c
index ce9a0d393..faf87b4e3 100644
--- a/lib/http2.c
+++ b/lib/http2.c
@@ -56,10 +56,11 @@
 #define NGHTTP2_HAS_SET_LOCAL_WINDOW_SIZE 1
 #endif
 
 #define HTTP2_HUGE_WINDOW_SIZE (32 * 1024 * 1024) /* 32 MB */
 
+#define DEBUG_HTTP2
 #ifdef DEBUG_HTTP2
 #define H2BUGF(x) x
 #else
 #define H2BUGF(x) do { } while(0)
 #endif
daniel@storebror:~/src/curl [bagder/h1-reuse-not-h2]$ 

@ngg
Copy link
Contributor Author

ngg commented Apr 19, 2021

With the third version of the patch (6c4007e), it's still does the same as the second one.

curl --trace-ascii dump -k -Z -o x -o x2 -o x3 https://localhost:8443/largefile https://localhost:8443/largefile https://localhost:8443/secure

Here are the dump files of the 3 different outcomes:

Output when the retry is correctly done via HTTP/1.1
== Info: STATE: INIT => CONNECT handle 0x56312e132de8; line 1634 (connection #-5000)
== Info: Added connection 0. The cache now contains 1 members
== Info: STATE: CONNECT => RESOLVING handle 0x56312e132de8; line 1680 (connection #0)
== Info: STATE: INIT => CONNECT handle 0x56312e1342b8; line 1634 (connection #-5000)
== Info: Found bundle for host localhost: 0x56312e122d08 [serially]
== Info: Server doesn't support multiplex yet, wait
== Info: No connections available.
== Info: STATE: CONNECT => PENDING handle 0x56312e1342b8; line 1663 (connection #-5000)
== Info: STATE: INIT => CONNECT handle 0x56312e135788; line 1634 (connection #-5000)
== Info: Found bundle for host localhost: 0x56312e122d08 [serially]
== Info: Server doesn't support multiplex yet, wait
== Info: No connections available.
== Info: STATE: CONNECT => PENDING handle 0x56312e135788; line 1663 (connection #-5000)
== Info: family0 == v6, family1 == v4
== Info:   Trying ::1:8443...
== Info: STATE: RESOLVING => CONNECTING handle 0x56312e132de8; line 1762 (connection #0)
== Info: Connected to localhost (::1) port 8443 (#0)
== Info: STATE: CONNECTING => PROTOCONNECT handle 0x56312e132de8; line 1825 (connection #0)
== Info: ALPN, offering h2
== Info: ALPN, offering http/1.1
== Info: successfully set certificate verify locations:
== Info:  CAfile: /etc/ssl/certs/ca-certificates.crt
== Info:  CApath: none
=> Send SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (OUT), TLS handshake, Client hello (1):
=> Send SSL data, 512 bytes (0x200)
0000: ......).w.sg|.W..'.f.RU.&..S.YJ.....r  C..W...l..w^B.)..?..x....
0040: ..7.m...>.......,.0.........+./...$.(.k.#.'.g.....9.....3.....=.
0080: <.5./.....u.........localhost........................3t.........
00c0: h2.http/1.1.........1.....0.....................................
0100: ............+............-.....3.&.$... 'gC<..8...7/..=.......'G
0140: #..o...T........................................................
0180: ................................................................
01c0: ................................................................
== Info: STATE: PROTOCONNECT => PROTOCONNECTING handle 0x56312e132de8; line 1845 (connection #0)
<= Recv SSL data, 5 bytes (0x5)
0000: ....z
== Info: TLSv1.3 (IN), TLS handshake, Server hello (2):
<= Recv SSL data, 122 bytes (0x7a)
0000: ...v..i+R.q..%K..{......1...Z.0.ih.r.. C..W...l..w^B.)..?..x....
0040: ..7.m........+.....3.$... eV.......V=...*/hE.!...azLv..M.~
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 5 bytes (0x5)
0000: .... 
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
<= Recv SSL data, 15 bytes (0xf)
0000: .............h2
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Certificate (11):
<= Recv SSL data, 1404 bytes (0x57c)
0000: ...x...t..o0..k0..S.......x;.XU....z......e.s.0...*.H........0E1
0040: .0...U....AU1.0...U....Some-State1!0...U....Internet Widgits Pty
0080:  Ltd0...210407130405Z..220407130405Z0E1.0...U....AU1.0...U....So
00c0: me-State1!0...U....Internet Widgits Pty Ltd0.."0...*.H..........
0100: ...0...........M..h..@.zi1....j.L_$.(6. ....p..*....x..3....P4..
0140: i..G.n.2....`...<...6....I...R.&uKN..x......m...P.?..|..M..4)...
0180: ..Lw......-<Jy..Nz#......=....H4..d.3..+:.g.....�..z......+.L.y}
01c0: o...6..+s..vdL/.~=~_b*.}...@+f..s..1......+?..Rf>..|(.A.."...0..
0200: .Vl.f.h.C...z....G.'v.........e.z..I.~....`..6_3H...*.fZ/K..F.~.
0240: N~.L%.w$|R@...m..H....nJ.X..'........`.E....8Nk.c=.4......fi..4.
0280: ...P]..)k....N....j.|W....[1......$[7.......s.1.mB.>.& r_N......
02c0: .....u4..I....K!0w..QM...0..f.O.e[. ...;..........X...e...c..z..
0300: ......|R...u......S0Q0...U......M!.a.t...J.q.l{.....0...U.#..0..
0340: .M!.a.t...J.q.l{.....0...U.......0....0...*.H...............i�}.
0380: 8..FK..F,Y......|'$..e0..VB...Q...=C....{{{.Pe^...w..f..%.......
03c0: ...`/..l...........s..A.[ySH.X....Q(.i!....+..=+..n..2n.0j.U..y.
0400: ...I{czj..#.74j ...k....}):...K..2..H..I/T.S&}.P.(.....l.u.O.i.&
0440: `..Bf.x0]).#....].(j.h....}...T..r.......%%..*J...........B.....
0480: jK:w....~:f._.Bc.q..*.�-...4.........}..~T..}......gJ..A.]......
04c0: .n....[.../...."t"....Q..O.......8\.~.3t.};..|....h......eo...*.
0500: ...%*U....x...$...q.c$m.....5D\..$.P.4..D-..^h........o......%Qy
0540: ...ucqg{..ZC.6.Le&.$zQ..�... M..S............x...c.{l<e(....
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, CERT verify (15):
<= Recv SSL data, 520 bytes (0x208)
0000: ........#ba..w....u,u"......x.....p......./[.6p.....K...D....H.o
0040: .Y.4...0....Q 3g'.^f.. `...G..%Z....W0..yY.......H.&B.y_HI....H.
0080: .!M.=...v..v9_...^..ynK.........E....@W.B./._..j...T_......i.b).
00c0: E....R..........N..Y8S.$g.�.._...... ...3...:.....9.......P..QY.
0100: ..Qd"b....:0...G..�.N.........+~..'..4..Q..5..)L.~.f.�Wceg..[...
0140: ../...S...J...f.3..\*....T...1..i..3y..r.s./^.......M.2.....*...
0180: Z.......1..L.i...y-..[h.A1.:.TVSE....`..C...`..?....V..9..Z...m.
01c0: .........~..-.... .$.=.N9L..f..x.ZUr....<.<...L..il=.C.!...[.k..
0200: ..A.....
<= Recv SSL data, 5 bytes (0x5)
0000: ....E
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Finished (20):
<= Recv SSL data, 52 bytes (0x34)
0000: ...0jy.$../t...|.iC.z.1|....f.NO.N...'..a........$R.
=> Send SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....E
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS handshake, Finished (20):
=> Send SSL data, 52 bytes (0x34)
0000: ...0.g...{..sR;L.....t.WT...D0g.{7.[c..3..S\.[....N1
== Info: SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
== Info: ALPN, server accepted to use h2
== Info: STATE: PENDING => CONNECT handle 0x56312e1342b8; line 3339 (connection #-5000)
== Info: Server certificate:
== Info:  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  start date: Apr  7 13:04:05 2021 GMT
== Info:  expire date: Apr  7 13:04:05 2022 GMT
== Info:  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  SSL certificate verify result: self signed certificate (18), continuing anyway.
== Info: STATE: PROTOCONNECTING => DO handle 0x56312e132de8; line 1864 (connection #0)
== Info: Using HTTP2, server supports multi-use
== Info: Connection state changed (HTTP/2 confirmed)
== Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
== Info: h2_process_pending_input: All data in connection buffer processed
=> Send SSL data, 5 bytes (0x5)
0000: ....)
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....,
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: http2_send len=89
== Info: h2 header: :method:GET
== Info: h2 header: :path:/largefile
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x56312e132de8)
== Info: Using Stream ID: 1 (easy handle 0x56312e132de8)
=> Send SSL data, 5 bytes (0x5)
0000: ....D
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 89 bytes (0x59)
0000: GET /largefile HTTP/2
0017: Host: localhost:8443
002d: user-agent: curl/7.76.1-DEV
004a: accept: */*
0057: 
== Info: STATE: DO => DID handle 0x56312e132de8; line 1922 (connection #0)
== Info: multi changed, check CONNECT_PEND queue!
== Info: STATE: PENDING => CONNECT handle 0x56312e135788; line 3339 (connection #-5000)
== Info: STATE: DID => PERFORMING handle 0x56312e132de8; line 2041 (connection #0)
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33554432/65535
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
<= Recv SSL data, 265 bytes (0x109)
0000: .......,=..v.............{1....i....^".M..,..=%.Vp........\.....
0040: ..'..|{.x.....4=.Q.t<~.....}(..#.2.......C@.(...|...T...8=-.hu..
0080: ...gF=....1..-].....|..*.x..L2.....i.3"..1~.s`i.p...tz....y..QCy
00c0: .._.{.jI6..p.W....%U;..|.BK.....p.d..Y......u.'....�.......z..e.
0100: ....E(...
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
<= Recv SSL data, 265 bytes (0x109)
0000: .......,K................{1....i....^"........6..4...u......>..)
0040: ..ua.......*O?..x'A...H...h..v.x..@..F]Q......R.#...ZFN...\W....
0080: d..GA....@.X%.....y....4.W...+.G..v....5AO>....+..f..2#T"....e..
00c0: .W.k7^.).......h.%.8.U,.=v.%B..:...Q.....BJ5l)..5I.......Gnq..I.
0100: ....,....
== Info: old SSL session ID is stale, removing
== Info: Found bundle for host localhost: 0x56312e122d08 [can multiplex]
== Info: Multiplexed connection found!
== Info: Re-using existing connection! (#0) with host localhost
== Info: Transfer was pending, now try another
== Info: STATE: CONNECT => DO handle 0x56312e1342b8; line 1688 (connection #0)
== Info: http2_send len=89
== Info: h2 header: :method:GET
== Info: h2 header: :path:/largefile
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x56312e1342b8)
== Info: Using Stream ID: 3 (easy handle 0x56312e1342b8)
=> Send SSL data, 5 bytes (0x5)
0000: ....(
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 89 bytes (0x59)
0000: GET /largefile HTTP/2
0017: Host: localhost:8443
002d: user-agent: curl/7.76.1-DEV
004a: accept: */*
0057: 
== Info: STATE: DO => DID handle 0x56312e1342b8; line 1922 (connection #0)
== Info: STATE: DID => PERFORMING handle 0x56312e1342b8; line 2041 (connection #0)
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33554432/65535
<= Recv SSL data, 5 bytes (0x5)
0000: ....6
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=37
== Info: Got SETTINGS
== Info: MAX_CONCURRENT_STREAMS == 100
== Info: ENABLE_PUSH == TRUE
== Info: Got SETTINGS
== Info: MAX_CONCURRENT_STREAMS == 100
== Info: ENABLE_PUSH == TRUE
== Info: h2_process_pending_input: All data in connection buffer processed
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: http2_recv returns AGAIN for stream 3
== Info: Found bundle for host localhost: 0x56312e122d08 [can multiplex]
== Info: Multiplexed connection found!
== Info: Re-using existing connection! (#0) with host localhost
== Info: Transfer was pending, now try another
== Info: STATE: CONNECT => DO handle 0x56312e135788; line 1688 (connection #0)
== Info: http2_send len=86
== Info: h2 header: :method:GET
== Info: h2 header: :path:/secure
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x56312e135788)
== Info: Using Stream ID: 5 (easy handle 0x56312e135788)
=> Send SSL data, 5 bytes (0x5)
0000: ....&
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 86 bytes (0x56)
0000: GET /secure HTTP/2
0014: Host: localhost:8443
002a: user-agent: curl/7.76.1-DEV
0047: accept: */*
0054: 
== Info: STATE: DO => DID handle 0x56312e135788; line 1922 (connection #0)
== Info: STATE: DID => PERFORMING handle 0x56312e135788; line 2041 (connection #0)
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33554432/33554432
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: on_begin_headers() was called
== Info: h2 status: HTTP/2 200 (easy 0x56312e132de8)
== Info: h2 header: date: Mon, 19 Apr 2021 08:20:38 GMT
== Info: h2 header: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
== Info: h2 header: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
== Info: h2 header: etag: "4000-5c04ddea62b00"
== Info: h2 header: accept-ranges: bytes
== Info: h2 header: content-length: 16384
== Info: on_frame_recv() header 1 stream 1
== Info: Store 216 bytes headers from stream 1 at 0x56312e136c58
== Info: 1173 data received for stream 1 (101011 left in buffer 0x56312e136c58, total 1389)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1389 for stream 1
== Info: HTTP/2 found, allow multiplexing
<= Recv header, 13 bytes (0xd)
0000: HTTP/2 200 
<= Recv header, 37 bytes (0x25)
0000: date: Mon, 19 Apr 2021 08:20:38 GMT
<= Recv header, 45 bytes (0x2d)
0000: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
<= Recv header, 46 bytes (0x2e)
0000: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
<= Recv header, 28 bytes (0x1c)
0000: etag: "4000-5c04ddea62b00"
<= Recv header, 22 bytes (0x16)
0000: accept-ranges: bytes
<= Recv header, 23 bytes (0x17)
0000: content-length: 16384
<= Recv header, 2 bytes (0x2)
0000: 
<= Recv data, 1173 bytes (0x495)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: .....................
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33553259/33553259
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33551968/33551968
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33550677/33550677
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33549386/33549386
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33548095/33548095
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33546804/33546804
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33545513/33545513
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33544222/33544222
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33542931/33542931
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33541640/33541640
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33540349/33540349
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=118
== Info: 118 data received for stream 1 (102282 left in buffer 0x56312e136c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 118 for stream 1
<= Recv data, 118 bytes (0x76)
0000: ................................................................
0040: ......................................................
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33540231/33540231
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 1 (101109 left in buffer 0x56312e136c58, total 1291)
== Info: on_frame_recv() header 0 stream 1
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33538940/33538940
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: on_begin_headers() was called
== Info: h2 status: HTTP/2 200 (easy 0x56312e1342b8)
== Info: h2 header: date: Mon, 19 Apr 2021 08:20:38 GMT
== Info: h2 header: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
== Info: h2 header: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
== Info: h2 header: etag: "4000-5c04ddea62b00"
== Info: h2 header: accept-ranges: bytes
== Info: h2 header: content-length: 16384
== Info: on_frame_recv() header 1 stream 3
== Info: Store 216 bytes headers from stream 3 at 0x56312e14fc78
== Info: 1252 data received for stream 3 (100932 left in buffer 0x56312e14fc78, total 1468)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv returns AGAIN for stream 1
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33537688/33553180
== Info: http2_recv: DRAIN 1468 bytes stream 3!! (0x56312e14fc78 => 0x56312e14fc78)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1468 for stream 3
== Info: HTTP/2 found, allow multiplexing
<= Recv header, 13 bytes (0xd)
0000: HTTP/2 200 
<= Recv header, 37 bytes (0x25)
0000: date: Mon, 19 Apr 2021 08:20:38 GMT
<= Recv header, 45 bytes (0x2d)
0000: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
<= Recv header, 46 bytes (0x2e)
0000: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
<= Recv header, 28 bytes (0x1c)
0000: etag: "4000-5c04ddea62b00"
<= Recv header, 22 bytes (0x16)
0000: accept-ranges: bytes
<= Recv header, 23 bytes (0x17)
0000: content-length: 16384
<= Recv header, 2 bytes (0x2)
0000: 
<= Recv data, 1252 bytes (0x4e4)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ....................................
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33537688/33553180
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=940
== Info: 39 data received for stream 3 (102361 left in buffer 0x56312e14fc78, total 39)
== Info: on_frame_recv() header 0 stream 3
== Info: 892 data received for stream 1 (101508 left in buffer 0x56312e136c58, total 892)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 39 for stream 3
<= Recv data, 39 bytes (0x27)
0000: .......................................
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33536757/33553141
== Info: stream 3 is paused, pause id: 1
== Info: http2_recv: easy 0x56312e135788 (stream 5) win 33536757/33554432
== Info: stream 5 is paused, pause id: 1
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x56312e132de8 (stream 1) win 33536757/33538048
== Info: http2_recv: DRAIN 892 bytes stream 1!! (0x56312e136c58 => 0x56312e136c58)
== Info: on_frame_recv() header 0 stream 1
== Info: on_stream_close(), NO_ERROR (err 0), stream 1
== Info: Removed stream 1 hash!
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 892 for stream 0
== Info: Data returned for PAUSED stream 0
<= Recv data, 892 bytes (0x37c)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ............................................................
== Info: http2_recv: easy 0x56312e132de8 (stream 0) win 33536757/4294967295
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101070 left in buffer 0x56312e14fc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: nread == 0, stream closed, bailing
== Info: STATE: PERFORMING => DONE handle 0x56312e132de8; line 2244 (connection #0)
== Info: multi_done
== Info: Connection still in use 2, no more multi_done now!
== Info: Expire cleared (transfer 0x56312e132de8)
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33535466/33551850
== Info: http2_recv: DRAIN 1291 bytes stream 3!! (0x56312e14fc78 => 0x56312e14fc78)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33535466/33551850
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33534175/33550559
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33532884/33549268
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33531593/33547977
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33530302/33546686
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33529011/33545395
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33527720/33544104
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33526429/33542813
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33525138/33541522
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33523847/33540231
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x56312e14fc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x56312e1342b8 (stream 3) win 33522556/33538940
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=901
== Info: 892 data received for stream 3 (101508 left in buffer 0x56312e14fc78, total 892)
== Info: on_frame_recv() header 0 stream 3
== Info: on_stream_close(), NO_ERROR (err 0), stream 3
== Info: Removed stream 3 hash!
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 892 for stream 0
== Info: Data returned for PAUSED stream 0
<= Recv data, 892 bytes (0x37c)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ............................................................
== Info: http2_recv: easy 0x56312e1342b8 (stream 0) win 33521664/4294967295
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=13
== Info: on_frame_recv() header 3 stream 5
== Info: Got frame type 3 for stream 5!
== Info: on_stream_close(), HTTP_1_1_REQUIRED (err 13), stream 5
== Info: Removed stream 5 hash!
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: nread == 0, stream closed, bailing
== Info: STATE: PERFORMING => DONE handle 0x56312e1342b8; line 2244 (connection #0)
== Info: multi_done
== Info: Connection still in use 1, no more multi_done now!
== Info: Expire cleared (transfer 0x56312e1342b8)
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x56312e135788 (stream 0) win 33521664/4294967295
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: HTTP/2 stream 0 was not closed cleanly: HTTP_1_1_REQUIRED (err 13)
== Info: Connection died, retrying a fresh connect(retry count: 1)
== Info: Downgrades to HTTP/1.1!
== Info: multi_done
== Info: The cache now contains 0 members
== Info: HTTP/2 DISCONNECT starts now
== Info: HTTP/2 DISCONNECT done
== Info: Closing connection 0
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS alert, close notify (256):
=> Send SSL data, 2 bytes (0x2)
0000: ..
== Info: Issue another request to this URL: 'https://localhost:8443/secure'
== Info: STATE: PERFORMING => CONNECT handle 0x56312e135788; line 2221 (connection #-5000)
== Info: Added connection 1. The cache now contains 1 members
== Info: Hostname localhost was found in DNS cache
== Info: family0 == v6, family1 == v4
== Info:   Trying ::1:8443...
== Info: Transfer was pending, now try another
== Info: STATE: CONNECT => CONNECTING handle 0x56312e135788; line 1695 (connection #1)
== Info: Connected to localhost (::1) port 8443 (#1)
== Info: STATE: CONNECTING => PROTOCONNECT handle 0x56312e135788; line 1825 (connection #1)
== Info: ALPN, offering http/1.1
== Info: successfully set certificate verify locations:
== Info:  CAfile: /etc/ssl/certs/ca-certificates.crt
== Info:  CApath: none
== Info: SSL re-using session ID
=> Send SSL data, 5 bytes (0x5)
0000: ....t
== Info: TLSv1.3 (OUT), TLS handshake, Client hello (1):
=> Send SSL data, 628 bytes (0x274)
0000: ...p...q..?.......a@N..Z$I=Q../...E.e. .....8..b....5A...7|\....
0040: ....R...>.......,.0.........+./...$.(.k.#.'.g.....9.....3.....=.
0080: <.5./...............localhost........................3t.........
00c0: http/1.1.........1.....0........................................
0100: .........+............-.....3.&.$... p.,1.....]..Z.5.t4uU...<:..
0140: .z..^.).+......{1....i....^"........6..4...u......>..)..ua......
0180: .*O?..x'A...H...h..v.x..@..F]Q......R.#...ZFN...\W....d..GA....@
01c0: .X%.....y....4.W...+.G..v....5AO>....+..f..2#T"....e...W.k7^.)..
0200: .....h.%.8.U,.=v.%B..:...Q.....BJ5l)..5I.......Gnq..I.....,..K..
0240: ..10?.c...[m.x.X..F..............U.. .Uz...%........
== Info: STATE: PROTOCONNECT => PROTOCONNECTING handle 0x56312e135788; line 1845 (connection #1)
<= Recv SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (IN), TLS handshake, Server hello (2):
<= Recv SSL data, 128 bytes (0x80)
0000: ...|...y1.7*..`......[.Q...S.....A.... .....8..b....5A...7|\....
0040: ....R......4.+.....3.$... a.....YV,.�...5..%Z..'........IS.)....
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 5 bytes (0x5)
0000: ....&
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
<= Recv SSL data, 21 bytes (0x15)
0000: .............http/1.1
<= Recv SSL data, 5 bytes (0x5)
0000: ....E
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Finished (20):
<= Recv SSL data, 52 bytes (0x34)
0000: ...0...+....t.D........b...5.n..0.....:.}P.r...q..97
=> Send SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....E
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS handshake, Finished (20):
=> Send SSL data, 52 bytes (0x34)
0000: ...0..vk...p.g...OJf...Rw..+.s...M.]e.U..<.....Hs1a.
== Info: SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
== Info: ALPN, server accepted to use http/1.1
== Info: Server certificate:
== Info:  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  start date: Apr  7 13:04:05 2021 GMT
== Info:  expire date: Apr  7 13:04:05 2022 GMT
== Info:  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  SSL certificate verify result: self signed certificate (18), continuing anyway.
== Info: STATE: PROTOCONNECTING => DO handle 0x56312e135788; line 1864 (connection #1)
=> Send SSL data, 5 bytes (0x5)
0000: ....i
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 88 bytes (0x58)
0000: GET /secure HTTP/1.1
0016: Host: localhost:8443
002c: User-Agent: curl/7.76.1-DEV
0049: Accept: */*
0056: 
== Info: STATE: DO => DID handle 0x56312e135788; line 1922 (connection #1)
== Info: STATE: DID => PERFORMING handle 0x56312e135788; line 2041 (connection #1)
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
<= Recv SSL data, 265 bytes (0x109)
0000: .......,...4.............{1....i....^"......,...)o?..........>..
0040: ..k...<....U.....@.......b........]4z..).:t.2......|{.RD1TEp/...
0080: =..Vq...NKB..(Vb.L..-...r...`.....ER..C....`....h.k.h.H=.(......
00c0: 9..'A....y..~.6....*...x..z{.O......4,EPx..!....%I....6....N..Ir
0100: .........
== Info: old SSL session ID is stale, removing
<= Recv SSL data, 5 bytes (0x5)
0000: ....^
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Request CERT (13):
<= Recv SSL data, 77 bytes (0x4d)
0000: ...I I].k.t......0.k.C.$&.4..y........&...". ...................
0040: .............
=> Send SSL data, 5 bytes (0x5)
0000: ....9
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS handshake, Certificate (11):
=> Send SSL data, 40 bytes (0x28)
0000: ...$ I].k.t......0.k.C.$&.4..y..........
=> Send SSL data, 5 bytes (0x5)
0000: ....E
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS handshake, Finished (20):
=> Send SSL data, 52 bytes (0x34)
0000: ...0...3....V..n2d..'.y......C.lR.....fV.....*.Z..M.
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS alert, unknown (628):
<= Recv SSL data, 2 bytes (0x2)
0000: .t
== Info: OpenSSL SSL_read: error:1409445C:SSL routines:ssl3_read_bytes:tlsv13 alert certificate required, errno 0
== Info: multi_done
== Info: The cache now contains 0 members
== Info: Closing connection 1
== Info: Expire cleared (transfer 0x56312e135788)
Output when the retry is done via HTTP/2
== Info: STATE: INIT => CONNECT handle 0x55fc53698de8; line 1634 (connection #-5000)
== Info: Added connection 0. The cache now contains 1 members
== Info: STATE: CONNECT => RESOLVING handle 0x55fc53698de8; line 1680 (connection #0)
== Info: STATE: INIT => CONNECT handle 0x55fc5369a2b8; line 1634 (connection #-5000)
== Info: Found bundle for host localhost: 0x55fc53688d08 [serially]
== Info: Server doesn't support multiplex yet, wait
== Info: No connections available.
== Info: STATE: CONNECT => PENDING handle 0x55fc5369a2b8; line 1663 (connection #-5000)
== Info: STATE: INIT => CONNECT handle 0x55fc5369b788; line 1634 (connection #-5000)
== Info: Found bundle for host localhost: 0x55fc53688d08 [serially]
== Info: Server doesn't support multiplex yet, wait
== Info: No connections available.
== Info: STATE: CONNECT => PENDING handle 0x55fc5369b788; line 1663 (connection #-5000)
== Info: family0 == v6, family1 == v4
== Info:   Trying ::1:8443...
== Info: STATE: RESOLVING => CONNECTING handle 0x55fc53698de8; line 1762 (connection #0)
== Info: Connected to localhost (::1) port 8443 (#0)
== Info: STATE: CONNECTING => PROTOCONNECT handle 0x55fc53698de8; line 1825 (connection #0)
== Info: ALPN, offering h2
== Info: ALPN, offering http/1.1
== Info: successfully set certificate verify locations:
== Info:  CAfile: /etc/ssl/certs/ca-certificates.crt
== Info:  CApath: none
=> Send SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (OUT), TLS handshake, Client hello (1):
=> Send SSL data, 512 bytes (0x200)
0000: ........N|..Ct6.6..f1j..m..S>....A.rv. ..b*@.u....Db-..M.[...+..
0040: ....X...>.......,.0.........+./...$.(.k.#.'.g.....9.....3.....=.
0080: <.5./.....u.........localhost........................3t.........
00c0: h2.http/1.1.........1.....0.....................................
0100: ............+............-.....3.&.$... .-........*...8\N.'5.;..
0140: .}....=.........................................................
0180: ................................................................
01c0: ................................................................
== Info: STATE: PROTOCONNECT => PROTOCONNECTING handle 0x55fc53698de8; line 1845 (connection #0)
<= Recv SSL data, 5 bytes (0x5)
0000: ....z
== Info: TLSv1.3 (IN), TLS handshake, Server hello (2):
<= Recv SSL data, 122 bytes (0x7a)
0000: ...v....k....^..q..2!!........ll_.p.6. ..b*@.u....Db-..M.[...+..
0040: ....X........+.....3.$... N.&..G ................M......o$
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 5 bytes (0x5)
0000: .... 
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
<= Recv SSL data, 15 bytes (0xf)
0000: .............h2
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Certificate (11):
<= Recv SSL data, 1404 bytes (0x57c)
0000: ...x...t..o0..k0..S.......x;.XU....z......e.s.0...*.H........0E1
0040: .0...U....AU1.0...U....Some-State1!0...U....Internet Widgits Pty
0080:  Ltd0...210407130405Z..220407130405Z0E1.0...U....AU1.0...U....So
00c0: me-State1!0...U....Internet Widgits Pty Ltd0.."0...*.H..........
0100: ...0...........M..h..@.zi1....j.L_$.(6. ....p..*....x..3....P4..
0140: i..G.n.2....`...<...6....I...R.&uKN..x......m...P.?..|..M..4)...
0180: ..Lw......-<Jy..Nz#......=....H4..d.3..+:.g.....�..z......+.L.y}
01c0: o...6..+s..vdL/.~=~_b*.}...@+f..s..1......+?..Rf>..|(.A.."...0..
0200: .Vl.f.h.C...z....G.'v.........e.z..I.~....`..6_3H...*.fZ/K..F.~.
0240: N~.L%.w$|R@...m..H....nJ.X..'........`.E....8Nk.c=.4......fi..4.
0280: ...P]..)k....N....j.|W....[1......$[7.......s.1.mB.>.& r_N......
02c0: .....u4..I....K!0w..QM...0..f.O.e[. ...;..........X...e...c..z..
0300: ......|R...u......S0Q0...U......M!.a.t...J.q.l{.....0...U.#..0..
0340: .M!.a.t...J.q.l{.....0...U.......0....0...*.H...............i�}.
0380: 8..FK..F,Y......|'$..e0..VB...Q...=C....{{{.Pe^...w..f..%.......
03c0: ...`/..l...........s..A.[ySH.X....Q(.i!....+..=+..n..2n.0j.U..y.
0400: ...I{czj..#.74j ...k....}):...K..2..H..I/T.S&}.P.(.....l.u.O.i.&
0440: `..Bf.x0]).#....].(j.h....}...T..r.......%%..*J...........B.....
0480: jK:w....~:f._.Bc.q..*.�-...4.........}..~T..}......gJ..A.]......
04c0: .n....[.../...."t"....Q..O.......8\.~.3t.};..|....h......eo...*.
0500: ...%*U....x...$...q.c$m.....5D\..$.P.4..D-..^h........o......%Qy
0540: ...ucqg{..ZC.6.Le&.$zQ..�... M..S............x...c.{l<e(....
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, CERT verify (15):
<= Recv SSL data, 520 bytes (0x208)
0000: ............d....N.].v."...........+.j..Q....i!.D.p...E.......D.
0040: ....`..X,.=i.:......A.v..x...T=F....~.O.0%....e.............?..[
0080: ..T.^.w.`.G.%...S_Qn..S.f....[...*..f.....c......!.+...a^}..K..<
00c0: ....)f..._........%F...Isif..G.:.F...$.....\.c.C!<...n..1....D..
0100: w....$.U8.k....3).3.).!..[......<....A.'/nkPw.....?....N......`.
0140: .....m..6L........,."<-...X....r....k4Z.&........3...fjS...*H...
0180: a..P....AQ.W......OqS.._(.A.m/..kE3...A..H..1$.O.~.`|o..z......p
01c0: ..........w... N.......D.z....�H*.n.a..e?...�x...j...<.8%.. }.F.
0200: v..../.Q
<= Recv SSL data, 5 bytes (0x5)
0000: ....E
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Finished (20):
<= Recv SSL data, 52 bytes (0x34)
0000: ...00......$.l..H[...D......W....s`C..&g..1...ln..__
=> Send SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....E
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS handshake, Finished (20):
=> Send SSL data, 52 bytes (0x34)
0000: ...0.....f.....$7...b.........IqD......0.l.U=|.el...
== Info: SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
== Info: ALPN, server accepted to use h2
== Info: STATE: PENDING => CONNECT handle 0x55fc5369a2b8; line 3339 (connection #-5000)
== Info: Server certificate:
== Info:  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  start date: Apr  7 13:04:05 2021 GMT
== Info:  expire date: Apr  7 13:04:05 2022 GMT
== Info:  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  SSL certificate verify result: self signed certificate (18), continuing anyway.
== Info: STATE: PROTOCONNECTING => DO handle 0x55fc53698de8; line 1864 (connection #0)
== Info: Using HTTP2, server supports multi-use
== Info: Connection state changed (HTTP/2 confirmed)
== Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
== Info: h2_process_pending_input: All data in connection buffer processed
=> Send SSL data, 5 bytes (0x5)
0000: ....)
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....,
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: http2_send len=89
== Info: h2 header: :method:GET
== Info: h2 header: :path:/largefile
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x55fc53698de8)
== Info: Using Stream ID: 1 (easy handle 0x55fc53698de8)
=> Send SSL data, 5 bytes (0x5)
0000: ....D
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 89 bytes (0x59)
0000: GET /largefile HTTP/2
0017: Host: localhost:8443
002d: user-agent: curl/7.76.1-DEV
004a: accept: */*
0057: 
== Info: STATE: DO => DID handle 0x55fc53698de8; line 1922 (connection #0)
== Info: multi changed, check CONNECT_PEND queue!
== Info: STATE: PENDING => CONNECT handle 0x55fc5369b788; line 3339 (connection #-5000)
== Info: STATE: DID => PERFORMING handle 0x55fc53698de8; line 2041 (connection #0)
== Info: Found bundle for host localhost: 0x55fc53688d08 [can multiplex]
== Info: Multiplexed connection found!
== Info: Re-using existing connection! (#0) with host localhost
== Info: Transfer was pending, now try another
== Info: STATE: CONNECT => DO handle 0x55fc5369a2b8; line 1688 (connection #0)
== Info: http2_send len=89
== Info: h2 header: :method:GET
== Info: h2 header: :path:/largefile
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x55fc5369a2b8)
== Info: Using Stream ID: 3 (easy handle 0x55fc5369a2b8)
=> Send SSL data, 5 bytes (0x5)
0000: ....(
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 89 bytes (0x59)
0000: GET /largefile HTTP/2
0017: Host: localhost:8443
002d: user-agent: curl/7.76.1-DEV
004a: accept: */*
0057: 
== Info: STATE: DO => DID handle 0x55fc5369a2b8; line 1922 (connection #0)
== Info: STATE: DID => PERFORMING handle 0x55fc5369a2b8; line 2041 (connection #0)
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33554432/65535
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
<= Recv SSL data, 265 bytes (0x109)
0000: .......,..9(.............{1....i....^"..`..........k.l*U)V.....I
0040: -n.r...K._..K....).U."ru...lg...s......+..85v.%8\...-5..�.t.}...
0080: ...S66.v.w..:.NM.r3...2..".^.3.1.K.t.t.+.,.v5-...CF......)h.P.r.
00c0: P...&b.."...]...}...Om.c.y;]g.p.Hg......I..O.. 4#......1.-.....k
0100: \>....e..
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
<= Recv SSL data, 265 bytes (0x109)
0000: .......,...^.............{1....i....^"..@.P.e./3.d..o[........E#
0040: .W.8H"......E..Vuc.....b.U.i.f.jBj.N.ZlE....._.....g.>.7%....N.m
0080: 6.._....Z..........r..D.D@.N^V..t...=..y..y&.S.'.....O..g..Y...p
00c0: .|.........N.....7.7...s...~yM..n.......%%n..*.m.C...a%+..T.?/T~
0100: q...).9..
== Info: old SSL session ID is stale, removing
== Info: Found bundle for host localhost: 0x55fc53688d08 [can multiplex]
== Info: Multiplexed connection found!
== Info: Re-using existing connection! (#0) with host localhost
== Info: Transfer was pending, now try another
== Info: STATE: CONNECT => DO handle 0x55fc5369b788; line 1688 (connection #0)
== Info: http2_send len=86
== Info: h2 header: :method:GET
== Info: h2 header: :path:/secure
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x55fc5369b788)
== Info: Using Stream ID: 5 (easy handle 0x55fc5369b788)
=> Send SSL data, 5 bytes (0x5)
0000: ....&
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 86 bytes (0x56)
0000: GET /secure HTTP/2
0014: Host: localhost:8443
002a: user-agent: curl/7.76.1-DEV
0047: accept: */*
0054: 
== Info: STATE: DO => DID handle 0x55fc5369b788; line 1922 (connection #0)
== Info: STATE: DID => PERFORMING handle 0x55fc5369b788; line 2041 (connection #0)
== Info: http2_recv: easy 0x55fc5369b788 (stream 5) win 33554432/65535
<= Recv SSL data, 5 bytes (0x5)
0000: ....6
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=37
== Info: Got SETTINGS
== Info: MAX_CONCURRENT_STREAMS == 100
== Info: ENABLE_PUSH == TRUE
== Info: Got SETTINGS
== Info: MAX_CONCURRENT_STREAMS == 100
== Info: ENABLE_PUSH == TRUE
== Info: h2_process_pending_input: All data in connection buffer processed
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: http2_recv returns AGAIN for stream 5
== Info: http2_recv: easy 0x55fc53698de8 (stream 1) win 33554432/33554432
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: on_begin_headers() was called
== Info: h2 status: HTTP/2 200 (easy 0x55fc5369a2b8)
== Info: h2 header: date: Mon, 19 Apr 2021 08:20:14 GMT
== Info: h2 header: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
== Info: h2 header: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
== Info: h2 header: etag: "4000-5c04ddea62b00"
== Info: h2 header: accept-ranges: bytes
== Info: h2 header: content-length: 16384
== Info: on_frame_recv() header 1 stream 3
== Info: Store 216 bytes headers from stream 3 at 0x55fc536b5c78
== Info: on_begin_headers() was called
== Info: h2 status: HTTP/2 200 (easy 0x55fc53698de8)
== Info: h2 header: date: Mon, 19 Apr 2021 08:20:14 GMT
== Info: h2 header: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
== Info: h2 header: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
== Info: h2 header: etag: "4000-5c04ddea62b00"
== Info: h2 header: accept-ranges: bytes
== Info: h2 header: content-length: 16384
== Info: on_frame_recv() header 1 stream 1
== Info: Store 216 bytes headers from stream 1 at 0x55fc5369cc58
== Info: 1134 data received for stream 3 (101050 left in buffer 0x55fc536b5c78, total 1350)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 216 for stream 1
== Info: HTTP/2 found, allow multiplexing
<= Recv header, 13 bytes (0xd)
0000: HTTP/2 200 
<= Recv header, 37 bytes (0x25)
0000: date: Mon, 19 Apr 2021 08:20:14 GMT
<= Recv header, 45 bytes (0x2d)
0000: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
<= Recv header, 46 bytes (0x2e)
0000: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
<= Recv header, 28 bytes (0x1c)
0000: etag: "4000-5c04ddea62b00"
<= Recv header, 22 bytes (0x16)
0000: accept-ranges: bytes
<= Recv header, 23 bytes (0x17)
0000: content-length: 16384
<= Recv header, 2 bytes (0x2)
0000: 
== Info: transfer closed with 16384 bytes remaining to read
== Info: multi_done
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: on_stream_close(), STREAM_CLOSED (err 5), stream 1
== Info: Removed stream 1 hash!
== Info: Connection still in use 2, no more multi_done now!
== Info: Expire cleared (transfer 0x55fc53698de8)
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33553298/33553298
== Info: http2_recv: DRAIN 1350 bytes stream 3!! (0x55fc536b5c78 => 0x55fc536b5c78)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1350 for stream 3
== Info: HTTP/2 found, allow multiplexing
<= Recv header, 13 bytes (0xd)
0000: HTTP/2 200 
<= Recv header, 37 bytes (0x25)
0000: date: Mon, 19 Apr 2021 08:20:14 GMT
<= Recv header, 45 bytes (0x2d)
0000: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
<= Recv header, 46 bytes (0x2e)
0000: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
<= Recv header, 28 bytes (0x1c)
0000: etag: "4000-5c04ddea62b00"
<= Recv header, 22 bytes (0x16)
0000: accept-ranges: bytes
<= Recv header, 23 bytes (0x17)
0000: content-length: 16384
<= Recv header, 2 bytes (0x2)
0000: 
<= Recv data, 1134 bytes (0x46e)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ..............................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33553298/33553298
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 157 data received for stream 3 (102243 left in buffer 0x55fc536b5c78, total 157)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 157 for stream 3
<= Recv data, 157 bytes (0x9d)
0000: ................................................................
0040: ................................................................
0080: .............................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33552007/33553141
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1134 data received for stream 3 (101266 left in buffer 0x55fc536b5c78, total 1134)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1134 for stream 3
<= Recv data, 1134 bytes (0x46e)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ..............................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33550716/33552007
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 157 data received for stream 3 (102243 left in buffer 0x55fc536b5c78, total 157)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 157 for stream 3
<= Recv data, 157 bytes (0x9d)
0000: ................................................................
0040: ................................................................
0080: .............................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33549425/33551850
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1134 data received for stream 3 (101266 left in buffer 0x55fc536b5c78, total 1134)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1134 for stream 3
<= Recv data, 1134 bytes (0x46e)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ..............................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33548134/33550716
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 157 data received for stream 3 (102243 left in buffer 0x55fc536b5c78, total 157)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 157 for stream 3
<= Recv data, 157 bytes (0x9d)
0000: ................................................................
0040: ................................................................
0080: .............................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33546843/33550559
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1134 data received for stream 3 (101266 left in buffer 0x55fc536b5c78, total 1134)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1134 for stream 3
<= Recv data, 1134 bytes (0x46e)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ..............................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33545552/33549425
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 157 data received for stream 3 (102243 left in buffer 0x55fc536b5c78, total 157)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 157 for stream 3
<= Recv data, 157 bytes (0x9d)
0000: ................................................................
0040: ................................................................
0080: .............................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33544261/33549268
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1134 data received for stream 3 (101266 left in buffer 0x55fc536b5c78, total 1134)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1134 for stream 3
<= Recv data, 1134 bytes (0x46e)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ..............................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33542970/33548134
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 157 data received for stream 3 (102243 left in buffer 0x55fc536b5c78, total 157)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 157 for stream 3
<= Recv data, 157 bytes (0x9d)
0000: ................................................................
0040: ................................................................
0080: .............................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33541679/33547977
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1134 data received for stream 3 (101266 left in buffer 0x55fc536b5c78, total 1134)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1134 for stream 3
<= Recv data, 1134 bytes (0x46e)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ..............................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33540388/33546843
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=157
== Info: 157 data received for stream 3 (102243 left in buffer 0x55fc536b5c78, total 157)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 157 for stream 3
<= Recv data, 157 bytes (0x9d)
0000: ................................................................
0040: ................................................................
0080: .............................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33540231/33546686
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv returns AGAIN for stream 3
== Info: http2_recv: easy 0x55fc5369b788 (stream 5) win 33538940/33554432
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: on_frame_recv() header 3 stream 5
== Info: Got frame type 3 for stream 5!
== Info: on_stream_close(), HTTP_1_1_REQUIRED (err 13), stream 5
== Info: Removed stream 5 hash!
== Info: 1278 data received for stream 3 (101122 left in buffer 0x55fc536b5c78, total 1278)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: Connection died, retrying a fresh connect(retry count: 1)
== Info: multi_done
== Info: Connection still in use 1, no more multi_done now!
== Info: Issue another request to this URL: 'https://localhost:8443/secure'
== Info: STATE: PERFORMING => CONNECT handle 0x55fc5369b788; line 2221 (connection #-5000)
== Info: Found bundle for host localhost: 0x55fc53688d08 [can multiplex]
== Info: Added connection 1. The cache now contains 2 members
== Info: Hostname localhost was found in DNS cache
== Info: family0 == v6, family1 == v4
== Info:   Trying ::1:8443...
== Info: Transfer was pending, now try another
== Info: STATE: CONNECT => CONNECTING handle 0x55fc5369b788; line 1695 (connection #1)
== Info: Connected to localhost (::1) port 8443 (#1)
== Info: STATE: CONNECTING => PROTOCONNECT handle 0x55fc5369b788; line 1825 (connection #1)
== Info: ALPN, offering h2
== Info: ALPN, offering http/1.1
== Info: successfully set certificate verify locations:
== Info:  CAfile: /etc/ssl/certs/ca-certificates.crt
== Info:  CApath: none
== Info: SSL re-using session ID
=> Send SSL data, 5 bytes (0x5)
0000: ....w
== Info: TLSv1.3 (OUT), TLS handshake, Client hello (1):
=> Send SSL data, 631 bytes (0x277)
0000: ...s.........2.....j.&-+g.`..$~.,R.7M. F%.....q.W+.j..O.....|.T.
0040: A....3R.>.......,.0.........+./...$.(.k.#.'.g.....9.....3.....=.
0080: <.5./...............localhost........................3t.........
00c0: h2.http/1.1.........1.....0.....................................
0100: ............+............-.....3.&.$... jF......g.2`..QeV...#.z.
0140: .....p\h.).+......{1....i....^"..@.P.e./3.d..o[........E#.W.8H".
0180: .....E..Vuc.....b.U.i.f.jBj.N.ZlE....._.....g.>.7%....N.m6.._...
01c0: .Z..........r..D.D@.N^V..t...=..y..y&.S.'.....O..g..Y...p.|.....
0200: ....N.....7.7...s...~yM..n.......%%n..*.m.C...a%+..T.?/T~q...).9
0240: ...^.10...h..CF.H.5a.H.b.0...dS ..._.Im..*^..B....s...#
== Info: STATE: PROTOCONNECT => PROTOCONNECTING handle 0x55fc5369b788; line 1845 (connection #1)
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33537662/33545408
== Info: http2_recv: DRAIN 1278 bytes stream 3!! (0x55fc536b5c78 => 0x55fc536b5c78)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1278 for stream 3
<= Recv data, 1278 bytes (0x4fe)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ..............................................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33537662/33545408
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x55fc536b5c78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 13 for stream 3
<= Recv data, 13 bytes (0xd)
0000: .............
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33536371/33545395
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1278 data received for stream 3 (101122 left in buffer 0x55fc536b5c78, total 1278)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1278 for stream 3
<= Recv data, 1278 bytes (0x4fe)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ..............................................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33535080/33544117
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x55fc536b5c78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 13 for stream 3
<= Recv data, 13 bytes (0xd)
0000: .............
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33533789/33544104
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1278 data received for stream 3 (101122 left in buffer 0x55fc536b5c78, total 1278)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1278 for stream 3
<= Recv data, 1278 bytes (0x4fe)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ..............................................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33532498/33542826
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x55fc536b5c78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 13 for stream 3
<= Recv data, 13 bytes (0xd)
0000: .............
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33531207/33542813
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1278 data received for stream 3 (101122 left in buffer 0x55fc536b5c78, total 1278)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1278 for stream 3
<= Recv data, 1278 bytes (0x4fe)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ..............................................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33529916/33541535
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x55fc536b5c78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 13 for stream 3
<= Recv data, 13 bytes (0xd)
0000: .............
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33528625/33541522
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1278 data received for stream 3 (101122 left in buffer 0x55fc536b5c78, total 1278)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1278 for stream 3
<= Recv data, 1278 bytes (0x4fe)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ..............................................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33527334/33540244
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x55fc536b5c78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 13 for stream 3
<= Recv data, 13 bytes (0xd)
0000: .............
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33526043/33540231
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1278 data received for stream 3 (101122 left in buffer 0x55fc536b5c78, total 1278)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1278 for stream 3
<= Recv data, 1278 bytes (0x4fe)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ..............................................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33524752/33538953
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x55fc536b5c78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 13 for stream 3
<= Recv data, 13 bytes (0xd)
0000: .............
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 3) win 33523461/33538940
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=914
== Info: 892 data received for stream 3 (101508 left in buffer 0x55fc536b5c78, total 892)
== Info: on_frame_recv() header 0 stream 3
== Info: on_stream_close(), NO_ERROR (err 0), stream 3
== Info: Removed stream 3 hash!
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 892 for stream 0
== Info: Data returned for PAUSED stream 0
<= Recv data, 892 bytes (0x37c)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ............................................................
== Info: http2_recv: easy 0x55fc5369a2b8 (stream 0) win 33522556/4294967295
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=901
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: nread == 0, stream closed, bailing
== Info: STATE: PERFORMING => DONE handle 0x55fc5369a2b8; line 2244 (connection #0)
== Info: multi_done
== Info: The cache now contains 1 members
== Info: HTTP/2 DISCONNECT starts now
== Info: HTTP/2 DISCONNECT done
== Info: Closing connection 0
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS alert, close notify (256):
=> Send SSL data, 2 bytes (0x2)
0000: ..
== Info: Expire cleared (transfer 0x55fc5369a2b8)
<= Recv SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (IN), TLS handshake, Server hello (2):
<= Recv SSL data, 128 bytes (0x80)
0000: ...|........h....vM....J..l\.$.u.=g/S. F%.....q.W+.j..O.....|.T.
0040: A....3R....4.+.....3.$... .]|m.w......m7U9....Z.[\.......".)....
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 5 bytes (0x5)
0000: .... 
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
<= Recv SSL data, 15 bytes (0xf)
0000: .............h2
<= Recv SSL data, 5 bytes (0x5)
0000: ....E
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Finished (20):
<= Recv SSL data, 52 bytes (0x34)
0000: ...0J.(..}+.<.^.......+.....T..c.6.Q....5<.n.#@mt&.c
=> Send SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....E
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS handshake, Finished (20):
=> Send SSL data, 52 bytes (0x34)
0000: ...0....�.E...OX...S>.V!.....O...X.'6?K8A....H~:..*.
== Info: SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
== Info: ALPN, server accepted to use h2
== Info: Server certificate:
== Info:  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  start date: Apr  7 13:04:05 2021 GMT
== Info:  expire date: Apr  7 13:04:05 2022 GMT
== Info:  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  SSL certificate verify result: self signed certificate (18), continuing anyway.
== Info: STATE: PROTOCONNECTING => DO handle 0x55fc5369b788; line 1864 (connection #1)
== Info: Using HTTP2, server supports multi-use
== Info: Connection state changed (HTTP/2 confirmed)
== Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
== Info: h2_process_pending_input: All data in connection buffer processed
=> Send SSL data, 5 bytes (0x5)
0000: ....)
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....,
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: http2_send len=86
== Info: h2 header: :method:GET
== Info: h2 header: :path:/secure
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x55fc5369b788)
== Info: Using Stream ID: 1 (easy handle 0x55fc5369b788)
=> Send SSL data, 5 bytes (0x5)
0000: ....B
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 86 bytes (0x56)
0000: GET /secure HTTP/2
0014: Host: localhost:8443
002a: user-agent: curl/7.76.1-DEV
0047: accept: */*
0054: 
== Info: STATE: DO => DID handle 0x55fc5369b788; line 1922 (connection #1)
== Info: multi changed, check CONNECT_PEND queue!
== Info: STATE: DID => PERFORMING handle 0x55fc5369b788; line 2041 (connection #1)
== Info: http2_recv: easy 0x55fc5369b788 (stream 1) win 33554432/65535
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
<= Recv SSL data, 265 bytes (0x109)
0000: .......,._eZ.............{1....i....^"..............1;#1.o.j...Z
0040: `_..b...Y..4..@p......}t......M....)O....H..4.E..KUc.AW.p&..0uA.
0080: Q..t(....rF>........Qo.t..KU.8.M....uW......[=.\.2.f...O..+..xd.
00c0: mj\rdI6.z5~......cL?..kz.|..9.u=... .H..H<...NT..�(.J.p.=4!.....
0100: VE.KN....
== Info: old SSL session ID is stale, removing
== Info: http2_recv: easy 0x55fc5369b788 (stream 1) win 33554432/65535
<= Recv SSL data, 5 bytes (0x5)
0000: ....6
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=37
== Info: Got SETTINGS
== Info: MAX_CONCURRENT_STREAMS == 100
== Info: ENABLE_PUSH == TRUE
== Info: Got SETTINGS
== Info: MAX_CONCURRENT_STREAMS == 100
== Info: ENABLE_PUSH == TRUE
== Info: h2_process_pending_input: All data in connection buffer processed
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: http2_recv returns AGAIN for stream 1
== Info: http2_recv: easy 0x55fc5369b788 (stream 1) win 33554432/33554432
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=13
== Info: on_frame_recv() header 3 stream 1
== Info: Got frame type 3 for stream 1!
== Info: on_stream_close(), HTTP_1_1_REQUIRED (err 13), stream 1
== Info: Removed stream 1 hash!
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: STATE: PERFORMING => DONE handle 0x55fc5369b788; line 2244 (connection #1)
== Info: multi_done
== Info: Empty reply from server
== Info: Connection #1 to host localhost left intact
== Info: Expire cleared (transfer 0x55fc5369b788)
Output when there is no retry
== Info: STATE: INIT => CONNECT handle 0x562ec81a2de8; line 1634 (connection #-5000)
== Info: Added connection 0. The cache now contains 1 members
== Info: STATE: CONNECT => RESOLVING handle 0x562ec81a2de8; line 1680 (connection #0)
== Info: STATE: INIT => CONNECT handle 0x562ec81a42b8; line 1634 (connection #-5000)
== Info: Found bundle for host localhost: 0x562ec8192d08 [serially]
== Info: Server doesn't support multiplex yet, wait
== Info: No connections available.
== Info: STATE: CONNECT => PENDING handle 0x562ec81a42b8; line 1663 (connection #-5000)
== Info: STATE: INIT => CONNECT handle 0x562ec81a5788; line 1634 (connection #-5000)
== Info: Found bundle for host localhost: 0x562ec8192d08 [serially]
== Info: Server doesn't support multiplex yet, wait
== Info: No connections available.
== Info: STATE: CONNECT => PENDING handle 0x562ec81a5788; line 1663 (connection #-5000)
== Info: family0 == v6, family1 == v4
== Info:   Trying ::1:8443...
== Info: STATE: RESOLVING => CONNECTING handle 0x562ec81a2de8; line 1762 (connection #0)
== Info: Connected to localhost (::1) port 8443 (#0)
== Info: STATE: CONNECTING => PROTOCONNECT handle 0x562ec81a2de8; line 1825 (connection #0)
== Info: ALPN, offering h2
== Info: ALPN, offering http/1.1
== Info: successfully set certificate verify locations:
== Info:  CAfile: /etc/ssl/certs/ca-certificates.crt
== Info:  CApath: none
=> Send SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (OUT), TLS handshake, Client hello (1):
=> Send SSL data, 512 bytes (0x200)
0000: ......l>GMlTB...o..�..b....[`..V.Pdp>. .....{...v......u....(<..
0040: .�d.y...>.......,.0.........+./...$.(.k.#.'.g.....9.....3.....=.
0080: <.5./.....u.........localhost........................3t.........
00c0: h2.http/1.1.........1.....0.....................................
0100: ............+............-.....3.&.$... ;.IB .w%R.......t/]7....
0140: .9..q.K.........................................................
0180: ................................................................
01c0: ................................................................
== Info: STATE: PROTOCONNECT => PROTOCONNECTING handle 0x562ec81a2de8; line 1845 (connection #0)
<= Recv SSL data, 5 bytes (0x5)
0000: ....z
== Info: TLSv1.3 (IN), TLS handshake, Server hello (2):
<= Recv SSL data, 122 bytes (0x7a)
0000: ...v..u&...h...Q;>'.f9..>.;.R...5L!.*b .....{...v......u....(<..
0040: .�d.y........+.....3.$... ..>.....R.Dj j./.;^....0.a......
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 5 bytes (0x5)
0000: .... 
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
<= Recv SSL data, 15 bytes (0xf)
0000: .............h2
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Certificate (11):
<= Recv SSL data, 1404 bytes (0x57c)
0000: ...x...t..o0..k0..S.......x;.XU....z......e.s.0...*.H........0E1
0040: .0...U....AU1.0...U....Some-State1!0...U....Internet Widgits Pty
0080:  Ltd0...210407130405Z..220407130405Z0E1.0...U....AU1.0...U....So
00c0: me-State1!0...U....Internet Widgits Pty Ltd0.."0...*.H..........
0100: ...0...........M..h..@.zi1....j.L_$.(6. ....p..*....x..3....P4..
0140: i..G.n.2....`...<...6....I...R.&uKN..x......m...P.?..|..M..4)...
0180: ..Lw......-<Jy..Nz#......=....H4..d.3..+:.g.....�..z......+.L.y}
01c0: o...6..+s..vdL/.~=~_b*.}...@+f..s..1......+?..Rf>..|(.A.."...0..
0200: .Vl.f.h.C...z....G.'v.........e.z..I.~....`..6_3H...*.fZ/K..F.~.
0240: N~.L%.w$|R@...m..H....nJ.X..'........`.E....8Nk.c=.4......fi..4.
0280: ...P]..)k....N....j.|W....[1......$[7.......s.1.mB.>.& r_N......
02c0: .....u4..I....K!0w..QM...0..f.O.e[. ...;..........X...e...c..z..
0300: ......|R...u......S0Q0...U......M!.a.t...J.q.l{.....0...U.#..0..
0340: .M!.a.t...J.q.l{.....0...U.......0....0...*.H...............i�}.
0380: 8..FK..F,Y......|'$..e0..VB...Q...=C....{{{.Pe^...w..f..%.......
03c0: ...`/..l...........s..A.[ySH.X....Q(.i!....+..=+..n..2n.0j.U..y.
0400: ...I{czj..#.74j ...k....}):...K..2..H..I/T.S&}.P.(.....l.u.O.i.&
0440: `..Bf.x0]).#....].(j.h....}...T..r.......%%..*J...........B.....
0480: jK:w....~:f._.Bc.q..*.�-...4.........}..~T..}......gJ..A.]......
04c0: .n....[.../...."t"....Q..O.......8\.~.3t.};..|....h......eo...*.
0500: ...%*U....x...$...q.c$m.....5D\..$.P.4..D-..^h........o......%Qy
0540: ...ucqg{..ZC.6.Le&.$zQ..�... M..S............x...c.{l<e(....
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, CERT verify (15):
<= Recv SSL data, 520 bytes (0x208)
0000: ..........J.X..........._.+..3...}...zP.\...E.g.Ip=...>..n.v.o)c
0040: .9..............r...[...&q..0.r...P"oWl...>.A...{..s#_..).......
0080: [`.K.u....*3TV.....a`.....X.*..s.d.�.q..LgY{... c..L.�U9.L...CI.
00c0: .Ro....@9q'.p_.1C..s.O%..tA..'....K.vu.f.......x.h%...'....VE3.=
0100: ,.3~.Kmk.......\e.........u......../..s.......2.l...4....).....Q
0140: 4...B].nF.Fb..o.f.Z.Z.~........KOL.2...G./..CA..9.\...j6$..8#.5.
0180: ...7.......N..UH.....gP.ee..t..a<...=Hk..|...h.>.@[..%..O..2l.GT
01c0: .47.Y.NC..1.Z..8@?Um.7..r.z.$&....Z,a..�K.7.B<.x...u..k..5"..y..
0200: e.0....Q
<= Recv SSL data, 5 bytes (0x5)
0000: ....E
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Finished (20):
<= Recv SSL data, 52 bytes (0x34)
0000: ...0G.XK....V.z.I.o..'...^S.^.......b[.8..nkPs..7..{
=> Send SSL data, 5 bytes (0x5)
0000: .....
== Info: TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....E
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (OUT), TLS handshake, Finished (20):
=> Send SSL data, 52 bytes (0x34)
0000: ...0l.J..J....3)Qv.8.d..g.K>.`D...K..5...d'uB.A[...*
== Info: SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
== Info: ALPN, server accepted to use h2
== Info: STATE: PENDING => CONNECT handle 0x562ec81a42b8; line 3339 (connection #-5000)
== Info: Server certificate:
== Info:  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  start date: Apr  7 13:04:05 2021 GMT
== Info:  expire date: Apr  7 13:04:05 2022 GMT
== Info:  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
== Info:  SSL certificate verify result: self signed certificate (18), continuing anyway.
== Info: STATE: PROTOCONNECTING => DO handle 0x562ec81a2de8; line 1864 (connection #0)
== Info: Using HTTP2, server supports multi-use
== Info: Connection state changed (HTTP/2 confirmed)
== Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
== Info: h2_process_pending_input: All data in connection buffer processed
=> Send SSL data, 5 bytes (0x5)
0000: ....)
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: ....,
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: http2_send len=89
== Info: h2 header: :method:GET
== Info: h2 header: :path:/largefile
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x562ec81a2de8)
== Info: Using Stream ID: 1 (easy handle 0x562ec81a2de8)
=> Send SSL data, 5 bytes (0x5)
0000: ....D
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 89 bytes (0x59)
0000: GET /largefile HTTP/2
0017: Host: localhost:8443
002d: user-agent: curl/7.76.1-DEV
004a: accept: */*
0057: 
== Info: STATE: DO => DID handle 0x562ec81a2de8; line 1922 (connection #0)
== Info: multi changed, check CONNECT_PEND queue!
== Info: STATE: PENDING => CONNECT handle 0x562ec81a5788; line 3339 (connection #-5000)
== Info: STATE: DID => PERFORMING handle 0x562ec81a2de8; line 2041 (connection #0)
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33554432/65535
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
<= Recv SSL data, 265 bytes (0x109)
0000: .......,...z.............{1....i....^"...X....h.N..Z....r.ZC..K.
0040: ..,QN..............|.s..PV.K...'.....*..JL..c. ..S^sM.;_....%]a.
0080: #..j.g.1..j[N..<P...^...........p47.f...e.1...Q..b...J.d..#V.x35
00c0: =.Rio..7..[.).?;....E.^... )..OWRZ.4....:n.{.....3...{.�.X......
0100: H:iL.....
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
<= Recv SSL data, 265 bytes (0x109)
0000: .......,.1...............{1....i....^".T.f.7....U....2.p.@9...W&
0040: o.m<..d...3%..u.v`]..i_.�....5.o.....+.........}..t...?.....[S..
0080: .BF...?|!.Iu./!.O....DEm......%...WT..u..,.x~.{..e.m...tJ...q*..
00c0: 8L..;.)8...n..4P.d....?n........!.er../L..;!'R..d..8...sR..].^..
0100: qD.dm....
== Info: old SSL session ID is stale, removing
== Info: Found bundle for host localhost: 0x562ec8192d08 [can multiplex]
== Info: Multiplexed connection found!
== Info: Re-using existing connection! (#0) with host localhost
== Info: Transfer was pending, now try another
== Info: STATE: CONNECT => DO handle 0x562ec81a42b8; line 1688 (connection #0)
== Info: http2_send len=89
== Info: h2 header: :method:GET
== Info: h2 header: :path:/largefile
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x562ec81a42b8)
== Info: Using Stream ID: 3 (easy handle 0x562ec81a42b8)
=> Send SSL data, 5 bytes (0x5)
0000: ....(
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 89 bytes (0x59)
0000: GET /largefile HTTP/2
0017: Host: localhost:8443
002d: user-agent: curl/7.76.1-DEV
004a: accept: */*
0057: 
== Info: STATE: DO => DID handle 0x562ec81a42b8; line 1922 (connection #0)
== Info: STATE: DID => PERFORMING handle 0x562ec81a42b8; line 2041 (connection #0)
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33554432/65535
<= Recv SSL data, 5 bytes (0x5)
0000: ....6
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=37
== Info: Got SETTINGS
== Info: MAX_CONCURRENT_STREAMS == 100
== Info: ENABLE_PUSH == TRUE
== Info: Got SETTINGS
== Info: MAX_CONCURRENT_STREAMS == 100
== Info: ENABLE_PUSH == TRUE
== Info: h2_process_pending_input: All data in connection buffer processed
=> Send SSL data, 5 bytes (0x5)
0000: .....
=> Send SSL data, 1 bytes (0x1)
0000: .
== Info: http2_recv returns AGAIN for stream 3
== Info: Found bundle for host localhost: 0x562ec8192d08 [can multiplex]
== Info: Multiplexed connection found!
== Info: Re-using existing connection! (#0) with host localhost
== Info: Transfer was pending, now try another
== Info: STATE: CONNECT => DO handle 0x562ec81a5788; line 1688 (connection #0)
== Info: http2_send len=86
== Info: h2 header: :method:GET
== Info: h2 header: :path:/secure
== Info: h2 header: :scheme:https
== Info: h2 header: :authority:localhost:8443
== Info: h2 header: user-agent:curl/7.76.1-DEV
== Info: h2 header: accept:*/*
== Info: http2_send request allowed 1 (easy handle 0x562ec81a5788)
== Info: Using Stream ID: 5 (easy handle 0x562ec81a5788)
=> Send SSL data, 5 bytes (0x5)
0000: ....&
=> Send SSL data, 1 bytes (0x1)
0000: .
=> Send header, 86 bytes (0x56)
0000: GET /secure HTTP/2
0014: Host: localhost:8443
002a: user-agent: curl/7.76.1-DEV
0047: accept: */*
0054: 
== Info: STATE: DO => DID handle 0x562ec81a5788; line 1922 (connection #0)
== Info: STATE: DID => PERFORMING handle 0x562ec81a5788; line 2041 (connection #0)
== Info: http2_recv: easy 0x562ec81a5788 (stream 5) win 33554432/33554432
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: on_begin_headers() was called
== Info: h2 status: HTTP/2 200 (easy 0x562ec81a2de8)
== Info: h2 header: date: Mon, 19 Apr 2021 08:21:22 GMT
== Info: h2 header: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
== Info: h2 header: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
== Info: h2 header: etag: "4000-5c04ddea62b00"
== Info: h2 header: accept-ranges: bytes
== Info: h2 header: content-length: 16384
== Info: on_frame_recv() header 1 stream 1
== Info: Store 216 bytes headers from stream 1 at 0x562ec81a6c58
== Info: 1173 data received for stream 1 (101011 left in buffer 0x562ec81a6c58, total 1389)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv returns AGAIN for stream 5
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33553259/33553259
== Info: http2_recv: DRAIN 1389 bytes stream 1!! (0x562ec81a6c58 => 0x562ec81a6c58)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1389 for stream 1
== Info: HTTP/2 found, allow multiplexing
<= Recv header, 13 bytes (0xd)
0000: HTTP/2 200 
<= Recv header, 37 bytes (0x25)
0000: date: Mon, 19 Apr 2021 08:21:22 GMT
<= Recv header, 45 bytes (0x2d)
0000: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
<= Recv header, 46 bytes (0x2e)
0000: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
<= Recv header, 28 bytes (0x1c)
0000: etag: "4000-5c04ddea62b00"
<= Recv header, 22 bytes (0x16)
0000: accept-ranges: bytes
<= Recv header, 23 bytes (0x17)
0000: content-length: 16384
<= Recv header, 2 bytes (0x2)
0000: 
<= Recv data, 1173 bytes (0x495)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: .....................
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33553259/33553259
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33551968/33551968
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33550677/33550677
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33549386/33549386
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33548095/33548095
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33546804/33546804
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33545513/33545513
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33544222/33544222
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33542931/33542931
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33541640/33541640
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33540349/33540349
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 1173 data received for stream 1 (101109 left in buffer 0x562ec81a6c58, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 1
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a2de8 (stream 1) win 33539058/33539058
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1019
== Info: 118 data received for stream 1 (102282 left in buffer 0x562ec81a6c58, total 118)
== Info: on_frame_recv() header 0 stream 1
== Info: 892 data received for stream 1 (101390 left in buffer 0x562ec81a6c58, total 1010)
== Info: on_frame_recv() header 0 stream 1
== Info: on_stream_close(), NO_ERROR (err 0), stream 1
== Info: Removed stream 1 hash!
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1010 for stream 0
== Info: Data returned for PAUSED stream 0
<= Recv data, 1010 bytes (0x3f2)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ..................................................
== Info: http2_recv: easy 0x562ec81a2de8 (stream 0) win 33538048/4294967295
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: on_begin_headers() was called
== Info: h2 status: HTTP/2 200 (easy 0x562ec81a42b8)
== Info: h2 header: date: Mon, 19 Apr 2021 08:21:22 GMT
== Info: h2 header: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
== Info: h2 header: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
== Info: h2 header: etag: "4000-5c04ddea62b00"
== Info: h2 header: accept-ranges: bytes
== Info: h2 header: content-length: 16384
== Info: on_frame_recv() header 1 stream 3
== Info: Store 216 bytes headers from stream 3 at 0x562ec81bfc78
== Info: 1252 data received for stream 3 (100932 left in buffer 0x562ec81bfc78, total 1468)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: nread == 0, stream closed, bailing
== Info: STATE: PERFORMING => DONE handle 0x562ec81a2de8; line 2244 (connection #0)
== Info: multi_done
== Info: Connection still in use 2, no more multi_done now!
== Info: Expire cleared (transfer 0x562ec81a2de8)
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33536796/33553180
== Info: http2_recv: DRAIN 1468 bytes stream 3!! (0x562ec81bfc78 => 0x562ec81bfc78)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1468 for stream 3
== Info: HTTP/2 found, allow multiplexing
<= Recv header, 13 bytes (0xd)
0000: HTTP/2 200 
<= Recv header, 37 bytes (0x25)
0000: date: Mon, 19 Apr 2021 08:21:22 GMT
<= Recv header, 45 bytes (0x2d)
0000: server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
<= Recv header, 46 bytes (0x2e)
0000: last-modified: Mon, 19 Apr 2021 06:59:24 GMT
<= Recv header, 28 bytes (0x1c)
0000: etag: "4000-5c04ddea62b00"
<= Recv header, 22 bytes (0x16)
0000: accept-ranges: bytes
<= Recv header, 23 bytes (0x17)
0000: content-length: 16384
<= Recv header, 2 bytes (0x2)
0000: 
<= Recv data, 1252 bytes (0x4e4)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ....................................
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33536796/33553180
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 39 data received for stream 3 (102361 left in buffer 0x562ec81bfc78, total 39)
== Info: on_frame_recv() header 0 stream 3
== Info: 1252 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33535505/33551889
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 39 data received for stream 3 (102361 left in buffer 0x562ec81bfc78, total 39)
== Info: on_frame_recv() header 0 stream 3
== Info: 1252 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33534214/33550598
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 39 data received for stream 3 (102361 left in buffer 0x562ec81bfc78, total 39)
== Info: on_frame_recv() header 0 stream 3
== Info: 1252 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33532923/33549307
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 39 data received for stream 3 (102361 left in buffer 0x562ec81bfc78, total 39)
== Info: on_frame_recv() header 0 stream 3
== Info: 1252 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33531632/33548016
<= Recv SSL data, 5 bytes (0x5)
0000: ....8
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=39
== Info: 39 data received for stream 3 (102361 left in buffer 0x562ec81bfc78, total 39)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 39 for stream 3
<= Recv data, 39 bytes (0x27)
0000: .......................................
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33531593/33547977
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 1291 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: on_frame_recv() header 0 stream 3
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33530302/33546686
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: on_frame_recv() header 3 stream 5
== Info: Got frame type 3 for stream 5!
== Info: on_stream_close(), HTTP_1_1_REQUIRED (err 13), stream 5
== Info: Removed stream 5 hash!
== Info: 1278 data received for stream 3 (101122 left in buffer 0x562ec81bfc78, total 1278)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1278 for stream 3
<= Recv data, 1278 bytes (0x4fe)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ..............................................................
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33529024/33545408
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x562ec81bfc78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: 1278 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33527733/33544117
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x562ec81bfc78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: 1278 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33526442/33542826
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x562ec81bfc78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: 1278 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33525151/33541535
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x562ec81bfc78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: 1278 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33523860/33540244
<= Recv SSL data, 5 bytes (0x5)
0000: ....%
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=1300
== Info: 13 data received for stream 3 (102387 left in buffer 0x562ec81bfc78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: 1278 data received for stream 3 (101109 left in buffer 0x562ec81bfc78, total 1291)
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 1291 for stream 3
<= Recv data, 1291 bytes (0x50b)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: ................................................................
03c0: ................................................................
0400: ................................................................
0440: ................................................................
0480: ................................................................
04c0: ................................................................
0500: ...........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 3) win 33522569/33538953
<= Recv SSL data, 5 bytes (0x5)
0000: .....
<= Recv SSL data, 1 bytes (0x1)
0000: .
== Info: nread=914
== Info: 13 data received for stream 3 (102387 left in buffer 0x562ec81bfc78, total 13)
== Info: on_frame_recv() header 0 stream 3
== Info: 892 data received for stream 3 (101495 left in buffer 0x562ec81bfc78, total 905)
== Info: on_frame_recv() header 0 stream 3
== Info: on_stream_close(), NO_ERROR (err 0), stream 3
== Info: Removed stream 3 hash!
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv: returns 905 for stream 0
== Info: Data returned for PAUSED stream 0
<= Recv data, 905 bytes (0x389)
0000: ................................................................
0040: ................................................................
0080: ................................................................
00c0: ................................................................
0100: ................................................................
0140: ................................................................
0180: ................................................................
01c0: ................................................................
0200: ................................................................
0240: ................................................................
0280: ................................................................
02c0: ................................................................
0300: ................................................................
0340: ................................................................
0380: .........
== Info: http2_recv: easy 0x562ec81a42b8 (stream 0) win 33521664/4294967295
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: http2_recv returns 0, http2_handle_stream_close
== Info: nread == 0, stream closed, bailing
== Info: STATE: PERFORMING => DONE handle 0x562ec81a42b8; line 2244 (connection #0)
== Info: multi_done
== Info: Connection still in use 1, no more multi_done now!
== Info: Expire cleared (transfer 0x562ec81a42b8)
== Info: Curl_readwrite: forcibly told to drain data
== Info: http2_recv: easy 0x562ec81a5788 (stream 0) win 33521664/4294967295
== Info: h2_process_pending_input: All data in connection buffer processed
== Info: HTTP/2 stream 0 was closed cleanly, but before getting  all response header fields, treated as error
== Info: multi_done
== Info: stopped the pause stream!
== Info: Connection #0 to host localhost left intact
== Info: Expire cleared (transfer 0x562ec81a5788)

bagder added a commit that referenced this issue Apr 19, 2021
This was this one condition where the stream could be closed due to an
error and the function would still wrongly just return 0 for it.

Reported-by: Gergely Nagy
Fixes #6862
Closes #6910
@bagder
Copy link
Member

bagder commented Apr 19, 2021

Thanks for your patience. I kept banging on this and I got a better understanding of what happened, so the forth take is different but also feels like I better found the root cause and addressed it. It did reveal a rather embarrassing oversight in the h2 code as the stream error was stored per-connection and not per-stream which made it sensitive for race conditions. The PR has been updated.

@ngg
Copy link
Contributor Author

ngg commented Apr 19, 2021

Thanks, this seems to solve this issue, now the retry seems to be always happening and always over HTTP/1.1.

What's interesting to me (and probably it's one more bug) that I think this shouldn't work without the connection pool fix, but it does, the HTTP/2 connection is not reused. I think the stream error closes the whole HTTP/2 connection and that's why it's not reused, I don't think this should happen. I tried to find out why the connection is not reused, and it seems to me that sometimes it's fully closed before the retry looks for a connection, and sometimes it's skipped because the check->bits.close flag is set.

@bagder
Copy link
Member

bagder commented Apr 19, 2021

Yeah, that's a result of what I did in #6793 for #6788 - the entire connection is marked for closure after the HTTP_1_1_REQUIRED. It is for sure an area to improve further: if we have the HTTP version check properly in ConnectionExists() then the h2 connection should indeed be left alone.

Let me see if I can give that a stab as well while in here toying around...

@bagder
Copy link
Member

bagder commented Apr 19, 2021

I pushed a removal of the forced closing of the connection. The want-http1.1 setting will then make ConnectionExists reject connections that are multiplexed because the new connection cannot be multiplexed, which then gets us the result and effect we want without providing that specific version check I originally proposed.

@ngg
Copy link
Contributor Author

ngg commented Apr 19, 2021

The connection is still closed in Curl_retry_request() after Connection died, retrying a fresh connect(retry count: 1) is printed.

@bagder
Copy link
Member

bagder commented Apr 19, 2021

Right, but that's for another reason. That too can be improved but then we're really going away from what this issue is about so I won't try that now in this PR.

@ngg
Copy link
Contributor Author

ngg commented Apr 19, 2021

Alright, the fix in the PR looks good to me. I'd suggest to also merge the connection reuse fix from #6862 (comment)

@bagder bagder linked a pull request Apr 19, 2021 that will close this issue
@bagder
Copy link
Member

bagder commented Apr 19, 2021

Why? it doesn't add anything. As I tried to explain, a request for a HTTP/1.1 connection can't get a HTTP/2 connection with the existing code.

@ngg
Copy link
Contributor Author

ngg commented Apr 19, 2021

I think it's still possible to get a HTTP/2 connection that way, if a currently unused HTTP/2 connection is in the pool. canmultiplex will be false because httpwant contains HTTP/1.1, but multiplexed = CONN_INUSE(check) will also be false. In that case, I think the code will try to reuse that HTTP/2 connection.

I couldn't reproduce this case without modifying the curl tool, but it was easy to demonstrate it by disabling multiplexing
.

diff --git a/src/tool_operate.c b/src/tool_operate.c
index 942643290..c308f5033 100644
--- a/src/tool_operate.c
+++ b/src/tool_operate.c
@@ -2268,6 +2268,7 @@ static CURLcode parallel_transfers(struct GlobalConfig *global,
   multi = curl_multi_init();
   if(!multi)
     return CURLE_OUT_OF_MEMORY;
+  curl_multi_setopt(multi, CURLMOPT_PIPELINING, CURLPIPE_NOTHING);
 
   result = add_parallel_transfers(global, multi, share,
                                   &more_transfers, &added_transfers);

Running the same command as before, the retry is done over HTTP/2 once again if the connection re-use logic is not patched.

curl -v -k -Z -o x -o x2 -o x3 https://localhost:8443/largefile https://localhost:8443/largefile https://localhost:8443/secure 2>&1 | grep GET
* h2 header: :method:GET
> GET /largefile HTTP/2
* h2 header: :method:GET
> GET /largefile HTTP/2
* h2 header: :method:GET
> GET /secure HTTP/2
* h2 header: :method:GET
> GET /secure HTTP/2
> GET /secure HTTP/1.1

Patching the connection re-use fixes these cases as well.

@bagder
Copy link
Member

bagder commented Apr 19, 2021

Ah... thanks for explaining. I'll take another look in the morning and probably proceed and get that patched merged as well.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

Successfully merging a pull request may close this issue.

2 participants