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

SSL session closes with RST #10290

Closed
dfdity opened this issue Jan 13, 2023 · 34 comments
Closed

SSL session closes with RST #10290

dfdity opened this issue Jan 13, 2023 · 34 comments

Comments

@dfdity
Copy link

dfdity commented Jan 13, 2023

I did this

curl -v -H "Connection: close" https://httpd.apache.org/ > /dev/null

On latest 7.87 curl and before

In the tcpdump of the conversation I have observed race condition on session closure both server and client are trying
to close simultaneously which causes RST instead of clean session closing (whomever first started the session close will send the RST to the other party). Usually curl tries to close the session before the server. This only affects SSL; workaround used in FTPS issue --tls-max 1.2 doesn't help. Examples from separate machines (note the adjastent FIN-ACKs from server(151.101.2.132) and client(192.x) and final RSTs from client):
image
and
image

I think this is related to #7095

I expected the following

Clean session closure with 4 packets. FIN-ACK, FIN-ACK, ACK, ACK

curl/libcurl version

Tried following:
curl 7.87.0-DEV (x86_64-pc-linux-gnu) libcurl/7.87.0-DEV OpenSSL/1.1.1n zlib/1.2.8
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HSTS HTTPS-proxy IPv6 Largefile libz NTLM NTLM_WB SSL threadsafe TLS-SRP UnixSockets

curl 7.52.1 (x86_64-pc-linux-gnu) libcurl/7.52.1 OpenSSL/1.0.2u zlib/1.2.8 libidn2/2.0.5 libpsl/0.21.0 (+libidn2/2.0.5) libssh2/1.7.0 nghttp2/1.36.0 librtm
p/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL

curl 7.78.0 (x86_64-pc-linux-gnu) libcurl/7.78.0 OpenSSL/1.1.1n zlib/1.2.8
Release-Date: 2021-07-21
Protocols: dict file ftp ftps gopher gophers http https imap imaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HSTS HTTPS-proxy IPv6 Largefile libz NTLM NTLM_WB SSL TLS-SRP UnixSockets

operating system

Linux 5.16.0 SMP Debian 5.16.7 (2022-02-10) x86_64 GNU/Linux
Linux 5.10.0-1057-hardened SMP Wed Jul 20 13:08:44 UTC 2022 x86_64 GNU/Linux

this might be related to

#6149
#7095

@dfdity dfdity changed the title Race condition upon ssl session closure that causes RST SSL session closes with RST Jan 13, 2023
@bagder bagder added the TLS label Jan 13, 2023
@bagder
Copy link
Member

bagder commented Jan 13, 2023

So you don't see any actual negative effects other than that this is not correct when looking at the network capture?

@dfdity
Copy link
Author

dfdity commented Jan 13, 2023

Well under load, which is our case. Session closing via RST causes more packets and longer time. It also generates errors as session is reset. There is no data loss if this is the question.

@bagder
Copy link
Member

bagder commented Jan 13, 2023

I was trying to assess the impact of the problem.

@dfdity
Copy link
Author

dfdity commented Jan 14, 2023

I see. Impact is small as this causes issue only if curl or libcurl used in heavy and intesive applications with high rps

@bagder
Copy link
Member

bagder commented Jan 14, 2023

Right, but that's also a created example that isn't the normal path. Are you saying it always does this or at least in more standard use cases?

@dfdity
Copy link
Author

dfdity commented Jan 19, 2023

Ok so we've done investigation but still not 100% that something is wrong with curl, although RST signifies an issues:

  1. curl for some reason over ssl starts closing connection with FIN-ACK, while server does the same(this is the error I would like fixed). Not sure how well this part is implemented - https://www.rfc-editor.org/rfc/rfc2246#section-7.2.1 and not sure why such behaviour

  2. such behaviour causes server to be in TIME_WAIT as it started closing without seeing the client attempt first

  3. Server stays in the the TIME_WAIT according to the 2MSL rule .

  4. under high load (client outgoing port reuse every 50-60 seconds) this causes a port exaustion on server side and time outs in connecting to server.

Desired behaviour:
Curl should close ssl sessions itself (may be ask ssl server to wait for it, or may be close_notify from curl would allow server to wait or may be some other way). This avoids TIME_WAIT on server side. This would allow for port exaustion to happen later and higher server resource usage. It is also expected that normal FIN-ACK sequence would be followed in such case.

The test above does show the closure with RST on this specific ssl server, same is observed with a standard go https rest client (curl sends RST).

see "Linux port exaustion" in https://www.cyberpunk.rs/tuning-network-performance-linux-apache
This also somewhat resembles this one - openssl/openssl#6262

@bagder
Copy link
Member

bagder commented Jan 28, 2023

I don't understand your answer.

Are you saying it always does this or at least does it in more standard use cases? IOW: how often does this occur?

@frehberg
Copy link

frehberg commented Mar 23, 2023

Hi, taking a look at the trace 1 and trace 2, in both cases the client (192.x.x.x) is sending the initial FIN/ACK and server takes ca 40ms to respond with FIN/ACK. Please check the implementation of the server. it seems to respond to FIN/ACK with huge delay of ca 40ms.

Trace 1:
message 32: the client sends the initial FIN/ACK,
message 33-35: the server is repeating ACKs 3 times (identical serial number) (maybe network congestion ??)
message 37: after 40ms the server responds with FIN/ACK
message 38: almost same instant the client-side is sending RST, maybe the client did terminate already and the socket-resource is not available anymore.

Trace 2:
message 36: the client sends the initial FIN/ACK,
message 40: the server does not respond with FIN/ACK in time, therefor the client gives up after ca 40ms and is resetting the connection (RST in message 40). EDIT the client is terminating and all further messages will be responded by operating system using RST
message 42 and 44: EDIT these RSTs are sent by the client-site OS, as the client did terminate and teh socket-resource is no longer available

PS: I would expect . (clt: FIN-ACK), (srv: FIN-ACK), (clt: ACK)
but the responds of server is too late!

PPS: IMHO, this is not an issue of curl and ticket can be closed

@cuu508
Copy link

cuu508 commented Apr 10, 2023

I found this issue while investigating RST packets on my server. Several aspects are similar, perhaps I'm seeing the same issue (if it is an issue).

I'm seeing the RST packets on relatively busy production servers, but can also reproduce the issue on idle client and server.

Client: curl 7.68.0 on otherwise idle system, running in a loop like so:

for  i in {1..1000}
do
  echo $i
  curl --tls-max 1.2 --ciphers AES128-GCM-SHA256 https://my-url-here
done

(I've specifed TLS version and cipher so I can decrypt packets in Wireshark, but the same issue is present with TLS1.3)

Server: haproxy 2.6.12 on otherwise idle server.

Trace, captured on server:

image

  • server sends FIN,ACK
  • client sends FIN,ACK
  • server sends ACK
  • client sends two RST packets (instead of the expected ACK)

Trace from a different request, captured on client:

image

When using plain HTTP between the same client and server, the connection gets closed cleanly with FIN-ACK, FIN-ACK, ACK, ACK.

Ping between the client and the server is 25ms.


A trace from a different client running curl 7.81.0:

image

Here, client sends FIN-ACK before the server has sent TLS Close Notify ("Encrypted Alert" in the screenshot).


And here's a trace, captured on client, using curl 8.0.1-DEV:

image

@cuu508
Copy link

cuu508 commented Apr 10, 2023

Here's a script that fetches Google's favicon in a loop:

for  i in {1..1000}
do
  echo $i
  curl http://www.google.com/favicon.ico
done

Trace of one of the requests:

image

Same script, but curl replaced with wget:

for  i in {1..1000}
do
  echo $i
  wget https://www.google.com/favicon.ico
done

Trace:

image

Edit: in the first example, I forgot to use https:// (I was testing many variations), but the results are similar with http:// as Google redirects to https:// anyway, and curl follows the redirect.

@dfdity
Copy link
Author

dfdity commented Apr 11, 2023

Here's a script that fetches Google's favicon in a loop:

for  i in {1..1000}
do
  echo $i
  curl http://www.google.com/favicon.ico
done

Trace of one of the requests:

image

Same script, but curl replaced with wget:

for  i in {1..1000}
do
  echo $i
  wget https://www.google.com/favicon.ico
done

Trace:

image

@bagder this seems as a much simpler description and also reproduction steps of the same issue. @cuu508 thank you!

@xquery
Copy link
Member

xquery commented Dec 3, 2023

A further test minimisation I attempted was replicating this behaviour against local http server instance ... without any inteceding proxies/cdn (which presumably apache.org and google have) ... I was not able to repro.

@bagder
Copy link
Member

bagder commented Mar 3, 2024

Is this still a problem?

@cuu508
Copy link

cuu508 commented Mar 4, 2024

Looks like yes, I just ran the same experiment as before, with fetching Google's favicon in a loop, using curl and wget.

Wireshark capture of one TCP stream when using wget:

image

Wireshark capture of one TCP stream when using curl (8.6.0, binary build from https://github.com/stunnel/static-curl/releases/tag/8.6.0-1):

Screenshot from 2024-03-04 18-53-41

@dorrogeray
Copy link

Hi, we are encountering issue which might be related, apologies if its not, I can create a separate issue.

We are using Curl 8.5 in our PHP 8.2 application. We are pushing data to a AWS kinesis stream. The AWS service behaves in a way that it kills the TCP connection after 5 seconds of inactivity, where the inactivity is measured as not pushing new data - it does not care about tcp keepalives.

So what happens is that after 5 seconds, we receive FIN, ACK from the AWS service, but instead of Curl sending FIN, ACK back and closing the connection, it sends back ACK and then tries to push additional application data.

application-does-not-fin-ack

Is this a bug? Or is there something misconfigured on our side? The TCP goes over SSL using CURL_SSLVERSION_TLSv1_3.

@bagder
Copy link
Member

bagder commented Mar 7, 2024

This issue mixes HTTP: and HTTPS:// URLs a little intermittent. Which is the actual problem case?

I can't reproduce any reset issues with the HTTP:// nor HTTPS:// google URLs on my Linux box.

@cuu508
Copy link

cuu508 commented Mar 8, 2024

Sorry for the HTTP/HTTPS confusion. When fetching Google favicon, I can reproduce the RST packets with both http:// and https:// URLs.

I guess reproduction could be tricky as we are likely hitting different data centers through different network paths, and timing differences might be important.

I tested a different URL on a server that I control [...] The server is running haproxy and returns a short text/plain response. On the client I used curl 8.6.0 again. Interestingly with this URL, I see RST packets only with HTTPS, HTTP is fine

edit: I tested my URL with wget and saw RST packets too, so this is not a good example – the issue might be on the server.

icing added a commit to icing/curl that referenced this issue Mar 8, 2024
- refs curl#10290
- When curl sees a TCP close from the peer, do not start
  a TLS shutdown. TLS shutdown is a handshake and if the
  peer already closed the connection, it is not interested
  in participating.
@icing
Copy link
Contributor

icing commented Mar 8, 2024

@cuu508 thanks for the clarification. I can reproduce the RST with getting google's favicon over HTTPS. The reason is that curl tries to send a TLS shutdown after having seen the TCP close from the server.

Could you try #13087 if this solves the problems for you as well? cc: @dfdity @dorrogeray

@cuu508
Copy link

cuu508 commented Mar 8, 2024

Unfortunately I see RST packets with these changes as well when fetching https://www.google.com/favicon.ico:

image

@icing
Copy link
Contributor

icing commented Mar 8, 2024

@cuu508 this looks like an upload to a HTTP resource, not a GET. Just double checking...

@cuu508
Copy link

cuu508 commented Mar 8, 2024

I repeated the experiment with SSLKEYLOGFILE set so Wireshark decrypt the request and response:

image

image

@icing
Copy link
Contributor

icing commented Mar 8, 2024

Thanks. Looking at it again, curl seems to close the connection after having send the GET request, causing all response data from the server to result in RST. Is it possible to get a trace from such a curl run? Like in curl -v --trace-config all

@cuu508
Copy link

cuu508 commented Mar 8, 2024

Sure thing:

Curl trace
SSLKEYLOGFILE=/tmp/tls/secrets.log curl -v --trace-config all https://www.google.com/favicon.ico
11:35:39.638743 [0-0] * Host www.google.com:443 was resolved.
11:35:39.638783 [0-0] * IPv6: 2a00:1450:400f:802::2004
11:35:39.638800 [0-0] * IPv4: 142.250.74.36
11:35:39.638823 [0-0] * [HTTPS-CONNECT] added
11:35:39.638846 [0-0] * [HTTPS-CONNECT] connect, init
11:35:39.638869 [0-0] * [HTTPS-CONNECT] connect, check h21
11:35:39.638892 [0-0] * [HAPPY-EYEBALLS] created ipv4 (timeout 300000ms)
11:35:39.638915 [0-0] * [HAPPY-EYEBALLS] created ipv6 (timeout 300000ms)
11:35:39.638939 [0-0] * [HAPPY-EYEBALLS] ipv4 starting (timeout=300000ms)
11:35:39.638967 [0-0] *   Trying 142.250.74.36:443...
11:35:39.638994 [0-0] * [TCP] cf_socket_open() -> 0, fd=6
11:35:39.639039 [0-0] * [TCP] local address 192.168.88.10 port 52470...
11:35:39.639064 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
11:35:39.639090 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:35:39.639116 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:35:39.639140 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:35:39.639164 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:35:39.639187 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:35:39.639211 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:35:39.639235 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:35:39.639262 [0-0] * [HTTPS-CONNECT] connect, check h21
11:35:39.639287 [0-0] * [TCP] not connected yet
11:35:39.639312 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
11:35:39.639335 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:35:39.639362 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:35:39.639384 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:35:39.639408 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:35:39.639433 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:35:39.639457 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:35:39.639481 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:35:39.661022 [0-0] * [HTTPS-CONNECT] connect, check h21
11:35:39.661219 [0-0] * [TCP] connected
11:35:39.661404 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=1
11:35:39.661550 [0-0] * Connected to www.google.com (142.250.74.36) port 443
11:35:39.661686 [0-0] * [SSL] cf_connect()
11:35:39.669050 [0-0] * ALPN: curl offers http/1.1
11:35:39.669805 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
11:35:39.669999 [0-0] * [TCP] send(len=517) -> 517, err=0
11:35:39.670115 [0-0] * [SSL] ossl_bio_cf_out_write(len=517) -> 517, err=0
11:35:39.670255 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
11:35:39.670382 [0-0] * [TCP] recv(len=5) -> -1, err=81
11:35:39.670511 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
11:35:39.670647 [0-0] * [SSL] populate_x509_store, path=/etc/ssl/certs/ca-certificates.crt, blob=0
11:35:39.735205 [0-0] *  CAfile: /etc/ssl/certs/ca-certificates.crt
11:35:39.735246 [0-0] *  CApath: /etc/ssl/certs
11:35:39.735277 [0-0] * [SSL] cf_connect() -> 0, done=0
11:35:39.735298 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:35:39.735334 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
11:35:39.735352 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:35:39.735369 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
11:35:39.735391 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:35:39.735419 [0-0] * [HTTPS-CONNECT] connect, check h21
11:35:39.735441 [0-0] * [SSL] cf_connect()
11:35:39.735489 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:35:39.735512 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:35:39.735534 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:35:39.735557 [0-0] * [TCP] nw_in_read(len=122, fd=6) -> 122, err=0
11:35:39.735579 [0-0] * [TCP] recv(len=122) -> 122, err=0
11:35:39.735601 [0-0] * [SSL] ossl_bio_cf_in_read(len=122) -> 122, err=0
11:35:39.735630 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
11:35:39.735942 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:35:39.735966 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:35:39.735989 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:35:39.736018 [0-0] * [TCP] nw_in_read(len=1, fd=6) -> 1, err=0
11:35:39.736040 [0-0] * [TCP] recv(len=1) -> 1, err=0
11:35:39.736062 [0-0] * [SSL] ossl_bio_cf_in_read(len=1) -> 1, err=0
11:35:39.736084 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:35:39.736107 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:35:39.736129 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:35:39.736167 [0-0] * [TCP] nw_in_read(len=4172, fd=6) -> 4172, err=0
11:35:39.736190 [0-0] * [TCP] recv(len=4172) -> 4172, err=0
11:35:39.736211 [0-0] * [SSL] ossl_bio_cf_in_read(len=4172) -> 4172, err=0
11:35:39.736244 [0-0] * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
11:35:39.736277 [0-0] * TLSv1.3 (IN), TLS handshake, Certificate (11):
11:35:39.737392 [0-0] * TLSv1.3 (IN), TLS handshake, CERT verify (15):
11:35:39.737522 [0-0] * TLSv1.3 (IN), TLS handshake, Finished (20):
11:35:39.737589 [0-0] * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
11:35:39.737636 [0-0] * TLSv1.3 (OUT), TLS handshake, Finished (20):
11:35:39.737683 [0-0] * [TCP] send(len=80) -> 80, err=0
11:35:39.737700 [0-0] * [SSL] ossl_bio_cf_out_write(len=80) -> 80, err=0
11:35:39.737751 [0-0] * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / X25519 / id-ecPublicKey
11:35:39.737769 [0-0] * ALPN: server accepted http/1.1
11:35:39.737789 [0-0] * Server certificate:
11:35:39.737817 [0-0] *  subject: CN=www.google.com
11:35:39.737842 [0-0] *  start date: Feb  5 08:19:50 2024 GMT
11:35:39.737865 [0-0] *  expire date: Apr 29 08:19:49 2024 GMT
11:35:39.737901 [0-0] *  subjectAltName: host "www.google.com" matched cert's "www.google.com"
11:35:39.737927 [0-0] *  issuer: C=US; O=Google Trust Services LLC; CN=GTS CA 1C3
11:35:39.737949 [0-0] *  SSL certificate verify ok.
11:35:39.737979 [0-0] *   Certificate level 0: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using sha256WithRSAEncryption
11:35:39.738002 [0-0] *   Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
11:35:39.738024 [0-0] *   Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha384WithRSAEncryption
11:35:39.738046 [0-0] * [SSL] cf_connect() -> 0, done=1
11:35:39.738070 [0-0] * [HTTPS-CONNECT] connect+handshake h21: 99ms, 1st data: 96ms
11:35:39.738091 [0-0] * using HTTP/1.x
11:35:39.738117 [0-0] * [HTTPS-CONNECT] connect -> 0, done=1
11:35:39.738183 [0-0] * [TCP] send(len=114) -> 114, err=0
11:35:39.738205 [0-0] * [SSL] ossl_bio_cf_out_write(len=114) -> 114, err=0
11:35:39.738227 [0-0] > GET /favicon.ico HTTP/1.1
11:35:39.738227 [0-0] > Host: www.google.com
11:35:39.738227 [0-0] > User-Agent: curl/8.7.0-DEV
11:35:39.738227 [0-0] > Accept: */*
11:35:39.738227 [0-0] > 
11:35:39.738335 [0-0] * We are completely uploaded and fine
11:35:39.758821 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:35:39.758857 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:35:39.758874 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:35:39.758903 [0-0] * [TCP] nw_in_read(len=593, fd=6) -> 593, err=0
11:35:39.758925 [0-0] * [TCP] recv(len=593) -> 593, err=0
11:35:39.758948 [0-0] * [SSL] ossl_bio_cf_in_read(len=593) -> 593, err=0
11:35:39.759014 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
11:35:39.759092 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
11:35:39.759120 [0-0] * old SSL session ID is stale, removing
11:35:39.759146 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:35:39.759170 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:35:39.759192 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:35:39.759215 [0-0] * [TCP] nw_in_read(len=1395, fd=6) -> 1395, err=0
11:35:39.759236 [0-0] * [TCP] recv(len=1395) -> 1395, err=0
11:35:39.759260 [0-0] * [SSL] ossl_bio_cf_in_read(len=1395) -> 1395, err=0
11:35:39.759289 [0-0] * [SSL] cf_recv(len=102400) -> 1378, 0
11:35:39.759319 [0-0] < HTTP/1.1 200 OK
11:35:39.759346 [0-0] < Accept-Ranges: bytes
11:35:39.759369 [0-0] < Cross-Origin-Resource-Policy: cross-origin
11:35:39.759392 [0-0] < Cross-Origin-Opener-Policy-Report-Only: same-origin; report-to="static-on-bigtable"
11:35:39.759414 [0-0] < Report-To: {"group":"static-on-bigtable","max_age":2592000,"endpoints":[{"url":"https://csp.withgoogle.com/csp/report-to/static-on-bigtable"}]}
11:35:39.759442 [0-0] < Content-Length: 5430
11:35:39.759464 [0-0] < X-Content-Type-Options: nosniff
11:35:39.759487 [0-0] < Server: sffe
11:35:39.759510 [0-0] < X-XSS-Protection: 0
11:35:39.759533 [0-0] < Date: Fri, 08 Mar 2024 05:09:22 GMT
11:35:39.759555 [0-0] < Expires: Sat, 16 Mar 2024 05:09:22 GMT
11:35:39.759571 [0-0] < Cache-Control: public, max-age=691200
11:35:39.759589 [0-0] < Last-Modified: Tue, 22 Oct 2019 18:30:00 GMT
11:35:39.759616 [0-0] < Content-Type: image/x-icon
11:35:39.759641 [0-0] < Vary: Accept-Encoding
11:35:39.759666 [0-0] < Age: 15977
11:35:39.759691 [0-0] < Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000
11:35:39.759714 [0-0] < 
Warning: Binary output can mess up your terminal. Use "--output -" to tell 
Warning: curl to output it to your terminal anyway, or consider "--output 
Warning: <FILE>" to save to a file.
11:35:39.759759 [0-0] * Failure writing output to destination, passed 691 returned 4294967295
11:35:39.759796 [0-0] * Closing connection
11:35:39.759823 [0-0] * [HTTPS-CONNECT] close
11:35:39.759847 [0-0] * [SETUP] close
11:35:39.759895 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:35:39.759921 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:35:39.759945 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:35:39.759972 [0-0] * [TCP] nw_in_read(len=1395, fd=6) -> 1395, err=0
11:35:39.759997 [0-0] * [TCP] recv(len=1395) -> 1395, err=0
11:35:39.760035 [0-0] * [SSL] ossl_bio_cf_in_read(len=1395) -> 1395, err=0
11:35:39.760104 [0-0] * [TCP] send(len=24) -> 24, err=0
11:35:39.760128 [0-0] * [SSL] ossl_bio_cf_out_write(len=24) -> 24, err=0
11:35:39.760155 [0-0] * TLSv1.3 (OUT), TLS alert, close notify (256):
11:35:39.760179 [0-0] * [SSL] SSL shutdown, EOF from server
11:35:39.761087 [0-0] * [HAPPY-EYEBALLS] close
11:35:39.761118 [0-0] * [TCP] cf_socket_close(6)
11:35:39.761185 [0-0] * [TCP] destroy
11:35:39.761205 [0-0] * [HAPPY-EYEBALLS] destroy
11:35:39.761223 [0-0] * [SETUP] destroy
11:35:39.761248 [0-0] * [HTTPS-CONNECT] destroy

image

@icing
Copy link
Contributor

icing commented Mar 8, 2024

The key lines here are:

11:35:39.759759 [0-0] * Failure writing output to destination, passed 691 returned 4294967295
11:35:39.759796 [0-0] * Closing connection

meaning that curl encountered an error in storing the response and aborted the connection. What is the exact command line you are using. Do we have another error here?

Update: it is the writing of binary data to the terminal that fails the transfer. If you use -o /dev/null that will avoid this.

@cuu508
Copy link

cuu508 commented Mar 8, 2024

The command I used was:

SSLKEYLOGFILE=/tmp/tls/secrets.log curl -v --trace-config all https://www.google.com/favicon.ico

In case there's some Google-specific weirdness with the favicon URL, I tested a few other URLs.

Here's an URL of a random Debian mirror (with the idea that it is probably running a simple file server, nothing fancy, and is far away from my location):

SSLKEYLOGFILE=/tmp/tls/secrets.log curl -v --trace-config all https://mirror.linux.org.au/debian/project/trace/
Curl trace
SSLKEYLOGFILE=/tmp/tls/secrets.log curl -v --trace-config all https://mirror.linux.org.au/debian/project/trace/
11:53:19.132318 [0-0] * Host mirror.linux.org.au:443 was resolved.
11:53:19.132416 [0-0] * IPv6: 2400:a4c0::25
11:53:19.132464 [0-0] * IPv4: 103.84.224.37
11:53:19.132521 [0-0] * [HTTPS-CONNECT] added
11:53:19.132575 [0-0] * [HTTPS-CONNECT] connect, init
11:53:19.132634 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:19.132689 [0-0] * [HAPPY-EYEBALLS] created ipv4 (timeout 299999ms)
11:53:19.132748 [0-0] * [HAPPY-EYEBALLS] created ipv6 (timeout 299999ms)
11:53:19.132806 [0-0] * [HAPPY-EYEBALLS] ipv4 starting (timeout=299999ms)
11:53:19.132874 [0-0] *   Trying 103.84.224.37:443...
11:53:19.132941 [0-0] * [TCP] cf_socket_open() -> 0, fd=6
11:53:19.133036 [0-0] * [TCP] local address 192.168.88.10 port 34844...
11:53:19.133104 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
11:53:19.133163 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:53:19.133223 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:19.133280 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:19.133335 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:19.133394 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:19.133449 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:19.133508 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:19.133565 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:19.133623 [0-0] * [TCP] not connected yet
11:53:19.133683 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
11:53:19.133739 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:53:19.133796 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:19.133853 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:19.133911 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:19.133967 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:19.134024 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:19.134078 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:19.334432 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:19.334571 [0-0] * [TCP] not connected yet
11:53:19.334712 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
11:53:19.334847 [0-0] * [HAPPY-EYEBALLS] ipv6 starting (timeout=299796ms)
11:53:19.334990 [0-0] * [TCP] not connected yet
11:53:19.335130 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
11:53:19.335307 [0-0] *   Trying [2400:a4c0::25]:443...
11:53:19.335449 [0-0] * [TCP] cf_socket_open() -> 0, fd=7
11:53:19.335614 [0-0] * [TCP] local address :: port 0...
11:53:19.336063 [0-0] * Immediate connect fail for 2400:a4c0::25: Network is unreachable
11:53:19.336209 [0-0] * [HAPPY-EYEBALLS] ipv6 connect -> 7, connected=0
11:53:19.336330 [0-0] * [HAPPY-EYEBALLS] ipv6 done
11:53:19.336472 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:53:19.336622 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:19.336766 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:19.336899 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:19.337037 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:19.337181 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:19.337323 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:19.440181 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:19.440219 [0-0] * [TCP] connected
11:53:19.440240 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=1
11:53:19.440290 [0-0] * [TCP] destroy
11:53:19.440312 [0-0] * Connected to mirror.linux.org.au (103.84.224.37) port 443
11:53:19.440350 [0-0] * [SSL] cf_connect()
11:53:19.441685 [0-0] * ALPN: curl offers http/1.1
11:53:19.441820 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
11:53:19.441853 [0-0] * [TCP] send(len=517) -> 517, err=0
11:53:19.441876 [0-0] * [SSL] ossl_bio_cf_out_write(len=517) -> 517, err=0
11:53:19.441927 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
11:53:19.441964 [0-0] * [TCP] recv(len=5) -> -1, err=81
11:53:19.441989 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
11:53:19.442012 [0-0] * [SSL] populate_x509_store, path=/etc/ssl/certs/ca-certificates.crt, blob=0
11:53:19.471073 [0-0] *  CAfile: /etc/ssl/certs/ca-certificates.crt
11:53:19.471097 [0-0] *  CApath: /etc/ssl/certs
11:53:19.471122 [0-0] * [SSL] cf_connect() -> 0, done=0
11:53:19.471168 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:53:19.471210 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
11:53:19.471226 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:19.471279 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
11:53:19.471300 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:19.752450 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:19.752590 [0-0] * [SSL] cf_connect()
11:53:19.752777 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:19.752895 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:19.753027 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:19.753178 [0-0] * [TCP] nw_in_read(len=122, fd=6) -> 122, err=0
11:53:19.753323 [0-0] * [TCP] recv(len=122) -> 122, err=0
11:53:19.753461 [0-0] * [SSL] ossl_bio_cf_in_read(len=122) -> 122, err=0
11:53:19.753611 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
11:53:19.754651 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:19.754789 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:19.754935 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:19.755073 [0-0] * [TCP] nw_in_read(len=1, fd=6) -> 1, err=0
11:53:19.755202 [0-0] * [TCP] recv(len=1) -> 1, err=0
11:53:19.755337 [0-0] * [SSL] ossl_bio_cf_in_read(len=1) -> 1, err=0
11:53:19.755475 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:19.755609 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:19.755751 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:19.755892 [0-0] * [TCP] nw_in_read(len=42, fd=6) -> 42, err=0
11:53:19.756045 [0-0] * [TCP] recv(len=42) -> 42, err=0
11:53:19.756186 [0-0] * [SSL] ossl_bio_cf_in_read(len=42) -> 42, err=0
11:53:19.756342 [0-0] * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
11:53:19.756493 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:19.756620 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:19.756752 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:19.756903 [0-0] * [TCP] nw_in_read(len=4604, fd=6) -> 4604, err=0
11:53:19.757036 [0-0] * [TCP] recv(len=4604) -> 4604, err=0
11:53:19.757192 [0-0] * [SSL] ossl_bio_cf_in_read(len=4604) -> 4604, err=0
11:53:19.757379 [0-0] * TLSv1.3 (IN), TLS handshake, Certificate (11):
11:53:19.762319 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:19.762449 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:19.762581 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:19.762723 [0-0] * [TCP] nw_in_read(len=281, fd=6) -> 281, err=0
11:53:19.762857 [0-0] * [TCP] recv(len=281) -> 281, err=0
11:53:19.762991 [0-0] * [SSL] ossl_bio_cf_in_read(len=281) -> 281, err=0
11:53:19.763151 [0-0] * TLSv1.3 (IN), TLS handshake, CERT verify (15):
11:53:19.763491 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:19.763619 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:19.763740 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:19.763870 [0-0] * [TCP] nw_in_read(len=69, fd=6) -> 69, err=0
11:53:19.763994 [0-0] * [TCP] recv(len=69) -> 69, err=0
11:53:19.764134 [0-0] * [SSL] ossl_bio_cf_in_read(len=69) -> 69, err=0
11:53:19.764300 [0-0] * TLSv1.3 (IN), TLS handshake, Finished (20):
11:53:19.764623 [0-0] * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
11:53:19.764901 [0-0] * TLSv1.3 (OUT), TLS handshake, Finished (20):
11:53:19.765089 [0-0] * [TCP] send(len=80) -> 80, err=0
11:53:19.765219 [0-0] * [SSL] ossl_bio_cf_out_write(len=80) -> 80, err=0
11:53:19.765496 [0-0] * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / X25519 / RSASSA-PSS
11:53:19.765613 [0-0] * ALPN: server accepted http/1.1
11:53:19.765747 [0-0] * Server certificate:
11:53:19.765892 [0-0] *  subject: CN=*.linux.org.au
11:53:19.766026 [0-0] *  start date: Jun 14 00:00:00 2023 GMT
11:53:19.766154 [0-0] *  expire date: Jun 14 23:59:59 2024 GMT
11:53:19.766299 [0-0] *  subjectAltName: host "mirror.linux.org.au" matched cert's "*.linux.org.au"
11:53:19.766459 [0-0] *  issuer: C=GB; ST=Greater Manchester; L=Salford; O=Sectigo Limited; CN=Sectigo RSA Domain Validation Secure Server CA
11:53:19.766588 [0-0] *  SSL certificate verify ok.
11:53:19.766735 [0-0] *   Certificate level 0: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
11:53:19.766863 [0-0] *   Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha384WithRSAEncryption
11:53:19.766989 [0-0] *   Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha384WithRSAEncryption
11:53:19.767115 [0-0] * [SSL] cf_connect() -> 0, done=1
11:53:19.767241 [0-0] * [HTTPS-CONNECT] connect+handshake h21: 635ms, 1st data: 621ms
11:53:19.767363 [0-0] * using HTTP/1.x
11:53:19.767497 [0-0] * [HTTPS-CONNECT] connect -> 0, done=1
11:53:19.767822 [0-0] * [TCP] send(len=129) -> 129, err=0
11:53:19.767950 [0-0] * [SSL] ossl_bio_cf_out_write(len=129) -> 129, err=0
11:53:19.768089 [0-0] > GET /debian/project/trace/ HTTP/1.1
11:53:19.768089 [0-0] > Host: mirror.linux.org.au
11:53:19.768089 [0-0] > User-Agent: curl/8.7.0-DEV
11:53:19.768089 [0-0] > Accept: */*
11:53:19.768089 [0-0] > 
11:53:19.768709 [0-0] * We are completely uploaded and fine
11:53:20.072407 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:20.072463 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:20.072501 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:20.072525 [0-0] * [TCP] nw_in_read(len=314, fd=6) -> 314, err=0
11:53:20.072562 [0-0] * [TCP] recv(len=314) -> 314, err=0
11:53:20.072583 [0-0] * [SSL] ossl_bio_cf_in_read(len=314) -> 314, err=0
11:53:20.072639 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
11:53:20.072781 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
11:53:20.072818 [0-0] * [TCP] recv(len=5) -> -1, err=81
11:53:20.072874 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
11:53:20.072896 [0-0] * [SSL] cf_recv(len=102400) -> -1, 81
11:53:20.073424 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:20.073444 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:20.073460 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:20.073535 [0-0] * [TCP] nw_in_read(len=314, fd=6) -> 314, err=0
11:53:20.073552 [0-0] * [TCP] recv(len=314) -> 314, err=0
11:53:20.073568 [0-0] * [SSL] ossl_bio_cf_in_read(len=314) -> 314, err=0
11:53:20.073610 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
11:53:20.073644 [0-0] * old SSL session ID is stale, removing
11:53:20.073673 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
11:53:20.073694 [0-0] * [TCP] recv(len=5) -> -1, err=81
11:53:20.073715 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
11:53:20.073736 [0-0] * [SSL] cf_recv(len=102400) -> -1, 81
11:53:20.076183 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:20.076230 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:20.076250 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:20.076282 [0-0] * [TCP] nw_in_read(len=189, fd=6) -> 189, err=0
11:53:20.076312 [0-0] * [TCP] recv(len=189) -> 189, err=0
11:53:20.076333 [0-0] * [SSL] ossl_bio_cf_in_read(len=189) -> 189, err=0
11:53:20.076366 [0-0] * [SSL] cf_recv(len=102400) -> 172, 0
11:53:20.076395 [0-0] < HTTP/1.1 200 OK
11:53:20.076420 [0-0] < Date: Fri, 08 Mar 2024 09:53:20 GMT
11:53:20.076442 [0-0] < Server: Apache/2.4.38 (Debian)
11:53:20.076464 [0-0] < Vary: Accept-Encoding
11:53:20.076488 [0-0] < Content-Length: 2494
11:53:20.076528 [0-0] < Content-Type: text/html;charset=UTF-8
11:53:20.076550 [0-0] < 
11:53:20.076592 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:20.076614 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:20.076635 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:20.076657 [0-0] * [TCP] nw_in_read(len=2511, fd=6) -> 2511, err=0
11:53:20.076678 [0-0] * [TCP] recv(len=2511) -> 2511, err=0
11:53:20.076700 [0-0] * [SSL] ossl_bio_cf_in_read(len=2511) -> 2511, err=0
11:53:20.076725 [0-0] * [SSL] cf_recv(len=2494) -> 2494, 0
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2 Final//EN">
<html>
 <head>
  <title>Index of /debian/project/trace</title>
 </head>
 <body>
<h1>Index of /debian/project/trace</h1>
  <table>
   <tr><th valign="top"><img src="/icons/blank.gif" alt="[ICO]"></th><th><a href="?C=N;O=D">Name</a></th><th><a href="?C=M;O=A">Last modified</a></th><th><a href="?C=S;O=A">Size</a></th><th><a href="?C=D;O=A">Description</a></th></tr>
   <tr><th colspan="5"><hr></th></tr>
<tr><td valign="top"><img src="/icons/back.gif" alt="[PARENTDIR]"></td><td><a href="/debian/project/">Parent Directory</a></td><td>&nbsp;</td><td align="right">  - </td><td>&nbsp;</td></tr>
<tr><td valign="top"><img src="/icons/unknown.gif" alt="[   ]"></td><td><a href="_hierarchy">_hierarchy</a></td><td align="right">2024-03-08 19:36  </td><td align="right">275 </td><td>&nbsp;</td></tr>
<tr><td valign="top"><img src="/icons/unknown.gif" alt="[   ]"></td><td><a href="_hierarchy.mirror">_hierarchy.mirror</a></td><td align="right">2024-03-08 19:36  </td><td align="right">275 </td><td>&nbsp;</td></tr>
<tr><td valign="top"><img src="/icons/unknown.gif" alt="[   ]"></td><td><a href="_traces">_traces</a></td><td align="right">2024-03-08 19:36  </td><td align="right"> 72 </td><td>&nbsp;</td></tr>
<tr><td valign="top"><img src="/icons/unknown.gif" alt="[   ]"></td><td><a href="ftp-master.debian.org">ftp-master.debian.org</a></td><td align="right">2024-03-08 19:28  </td><td align="right">313 </td><td>&nbsp;</td></tr>
<tr><td valign="top"><img src="/icons/unknown.gif" alt="[   ]"></td><td><a href="master">master</a></td><td align="right">2024-03-08 19:28  </td><td align="right">313 </td><td>&nbsp;</td></tr>
<tr><td valign="top"><img src="/icons/sound2.gif" alt="[SND]"></td><td><a href="mirror.linux.org.au">mirror.linux.org.au</a></td><td align="right">2024-03-08 19:38  </td><td align="right">275 </td><td>&nbsp;</td></tr>
<tr><td valign="top"><img src="/icons/sound2.gif" alt="[SND]"></td><td><a href="syncproxy.au.debian.org">syncproxy.au.debian.org</a></td><td align="right">2024-03-08 19:36  </td><td align="right">699 </td><td>&nbsp;</td></tr>
<tr><td valign="top"><img src="/icons/unknown.gif" alt="[   ]"></td><td><a href="syncproxy2.wna.debian.org">syncproxy2.wna.debian.org</a></td><td align="right">2024-03-08 19:31  </td><td align="right">692 </td><td>&nbsp;</td></tr>
   <tr><th colspan="5"><hr></th></tr>
</table>
<address>Apache/2.4.38 (Debian) Server at mirror.linux.org.au Port 443</address>
</body></html>
11:53:20.076778 [0-0] * Connection #0 to host mirror.linux.org.au left intact

image

@icing
Copy link
Contributor

icing commented Mar 8, 2024

Please let's not switch the things we investigate before we are done knowing what is going on. Could you verify how the following command works in your setup?

SSLKEYLOGFILE=/tmp/tls/secrets.log curl -v --trace-config all https://www.google.com/favicon.ico -o /dev/null

@cuu508
Copy link

cuu508 commented Mar 8, 2024

It works!

Curl Trace
SSLKEYLOGFILE=/tmp/tls/secrets.log curl -v --trace-config all https://www.google.com/favicon.ico -o /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     012:05:30.209902 [0-0] * Host www.google.com:443 was resolved.
12:05:30.210139 [0-0] * IPv6: 2a00:1450:400f:801::2004
12:05:30.210265 [0-0] * IPv4: 142.250.74.164
12:05:30.210395 [0-0] * [HTTPS-CONNECT] added
12:05:30.210522 [0-0] * [HTTPS-CONNECT] connect, init
12:05:30.210648 [0-0] * [HTTPS-CONNECT] connect, check h21
12:05:30.210775 [0-0] * [HAPPY-EYEBALLS] created ipv4 (timeout 299997ms)
12:05:30.210898 [0-0] * [HAPPY-EYEBALLS] created ipv6 (timeout 299997ms)
12:05:30.211025 [0-0] * [HAPPY-EYEBALLS] ipv4 starting (timeout=299997ms)
12:05:30.211169 [0-0] *   Trying 142.250.74.164:443...
12:05:30.211319 [0-0] * [TCP] cf_socket_open() -> 0, fd=6
12:05:30.211531 [0-0] * [TCP] local address 192.168.88.10 port 59060...
12:05:30.211660 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
12:05:30.211785 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
12:05:30.211914 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
12:05:30.212066 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
12:05:30.212189 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
12:05:30.212313 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
12:05:30.212435 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
12:05:30.212556 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
12:05:30.212688 [0-0] * [HTTPS-CONNECT] connect, check h21
12:05:30.212814 [0-0] * [TCP] not connected yet
12:05:30.212937 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
12:05:30.213059 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
12:05:30.213184 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
12:05:30.213306 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
12:05:30.213430 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
12:05:30.213551 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
12:05:30.213672 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
12:05:30.213808 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
12:05:30.234677 [0-0] * [HTTPS-CONNECT] connect, check h21
12:05:30.234862 [0-0] * [TCP] connected
12:05:30.234980 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=1
12:05:30.235113 [0-0] * Connected to www.google.com (142.250.74.164) port 443
12:05:30.235241 [0-0] * [SSL] cf_connect()
12:05:30.242354 [0-0] * ALPN: curl offers http/1.1
12:05:30.243037 [0-0] } [5 bytes data]
12:05:30.243246 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
12:05:30.243381 [0-0] } [512 bytes data]
12:05:30.243651 [0-0] * [TCP] send(len=517) -> 517, err=0
12:05:30.243778 [0-0] * [SSL] ossl_bio_cf_out_write(len=517) -> 517, err=0
12:05:30.243914 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
12:05:30.244055 [0-0] * [TCP] recv(len=5) -> -1, err=81
12:05:30.244177 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
12:05:30.244303 [0-0] * [SSL] populate_x509_store, path=/etc/ssl/certs/ca-certificates.crt, blob=0
12:05:30.297814 [0-0] *  CAfile: /etc/ssl/certs/ca-certificates.crt
12:05:30.297837 [0-0] *  CApath: /etc/ssl/certs
12:05:30.297859 [0-0] * [SSL] cf_connect() -> 0, done=0
12:05:30.297876 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
12:05:30.297899 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
12:05:30.297918 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
12:05:30.297939 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
12:05:30.297963 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
12:05:30.297990 [0-0] * [HTTPS-CONNECT] connect, check h21
12:05:30.298011 [0-0] * [SSL] cf_connect()
12:05:30.298041 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.298066 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.298091 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.298116 [0-0] { [5 bytes data]
12:05:30.298156 [0-0] * [TCP] nw_in_read(len=122, fd=6) -> 122, err=0
12:05:30.298178 [0-0] * [TCP] recv(len=122) -> 122, err=0
12:05:30.298199 [0-0] * [SSL] ossl_bio_cf_in_read(len=122) -> 122, err=0
12:05:30.298223 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
12:05:30.298246 [0-0] { [122 bytes data]
12:05:30.298492 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.298516 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.298539 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.298564 [0-0] { [5 bytes data]
12:05:30.298602 [0-0] * [TCP] nw_in_read(len=1, fd=6) -> 1, err=0
12:05:30.298626 [0-0] * [TCP] recv(len=1) -> 1, err=0
12:05:30.298650 [0-0] * [SSL] ossl_bio_cf_in_read(len=1) -> 1, err=0
12:05:30.298674 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.298697 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.298722 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.298746 [0-0] { [5 bytes data]
12:05:30.298789 [0-0] * [TCP] nw_in_read(len=4171, fd=6) -> 4171, err=0
12:05:30.298813 [0-0] * [TCP] recv(len=4171) -> 4171, err=0
12:05:30.298836 [0-0] * [SSL] ossl_bio_cf_in_read(len=4171) -> 4171, err=0
12:05:30.298865 [0-0] { [1 bytes data]
12:05:30.298901 [0-0] * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
12:05:30.298923 [0-0] { [21 bytes data]
12:05:30.298969 [0-0] * TLSv1.3 (IN), TLS handshake, Certificate (11):
12:05:30.298992 [0-0] { [4002 bytes data]
12:05:30.299826 [0-0] * TLSv1.3 (IN), TLS handshake, CERT verify (15):
12:05:30.299845 [0-0] { [79 bytes data]
12:05:30.299959 [0-0] * TLSv1.3 (IN), TLS handshake, Finished (20):
12:05:30.299976 [0-0] { [52 bytes data]
12:05:30.300085 [0-0] * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
12:05:30.300102 [0-0] } [1 bytes data]
12:05:30.300157 [0-0] * TLSv1.3 (OUT), TLS handshake, Finished (20):
12:05:30.300174 [0-0] } [52 bytes data]
12:05:30.300212 [0-0] * [TCP] send(len=80) -> 80, err=0
12:05:30.300231 [0-0] * [SSL] ossl_bio_cf_out_write(len=80) -> 80, err=0
12:05:30.300280 [0-0] * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / X25519 / id-ecPublicKey
12:05:30.300297 [0-0] * ALPN: server accepted http/1.1
12:05:30.300321 [0-0] * Server certificate:
12:05:30.300347 [0-0] *  subject: CN=www.google.com
12:05:30.300371 [0-0] *  start date: Feb  5 08:19:50 2024 GMT
12:05:30.300395 [0-0] *  expire date: Apr 29 08:19:49 2024 GMT
12:05:30.300421 [0-0] *  subjectAltName: host "www.google.com" matched cert's "www.google.com"
12:05:30.300449 [0-0] *  issuer: C=US; O=Google Trust Services LLC; CN=GTS CA 1C3
12:05:30.300474 [0-0] *  SSL certificate verify ok.
12:05:30.300503 [0-0] *   Certificate level 0: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using sha256WithRSAEncryption
12:05:30.300520 [0-0] *   Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
12:05:30.300537 [0-0] *   Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha384WithRSAEncryption
12:05:30.300558 [0-0] * [SSL] cf_connect() -> 0, done=1
12:05:30.300582 [0-0] * [HTTPS-CONNECT] connect+handshake h21: 89ms, 1st data: 86ms
12:05:30.300607 [0-0] * using HTTP/1.x
12:05:30.300632 [0-0] * [HTTPS-CONNECT] connect -> 0, done=1
12:05:30.300684 [0-0] } [5 bytes data]
12:05:30.300728 [0-0] * [TCP] send(len=114) -> 114, err=0
12:05:30.300767 [0-0] * [SSL] ossl_bio_cf_out_write(len=114) -> 114, err=0
12:05:30.300804 [0-0] > GET /favicon.ico HTTP/1.1
12:05:30.300804 [0-0] > Host: www.google.com
12:05:30.300804 [0-0] > User-Agent: curl/8.7.0-DEV
12:05:30.300804 [0-0] > Accept: */*
12:05:30.300804 [0-0] > 
12:05:30.300921 [0-0] * We are completely uploaded and fine
12:05:30.319854 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.319918 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.319988 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.320062 [0-0] { [5 bytes data]
12:05:30.320175 [0-0] * [TCP] nw_in_read(len=593, fd=6) -> 593, err=0
12:05:30.320245 [0-0] * [TCP] recv(len=593) -> 593, err=0
12:05:30.320311 [0-0] * [SSL] ossl_bio_cf_in_read(len=593) -> 593, err=0
12:05:30.320388 [0-0] { [1 bytes data]
12:05:30.320532 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
12:05:30.320602 [0-0] { [288 bytes data]
12:05:30.320761 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
12:05:30.320831 [0-0] { [288 bytes data]
12:05:30.320967 [0-0] * old SSL session ID is stale, removing
12:05:30.321062 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.321137 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.321207 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.321284 [0-0] { [5 bytes data]
12:05:30.321393 [0-0] * [TCP] nw_in_read(len=1395, fd=6) -> 1395, err=0
12:05:30.321461 [0-0] * [TCP] recv(len=1395) -> 1395, err=0
12:05:30.321534 [0-0] * [SSL] ossl_bio_cf_in_read(len=1395) -> 1395, err=0
12:05:30.321607 [0-0] { [1 bytes data]
12:05:30.321725 [0-0] * [SSL] cf_recv(len=102400) -> 1378, 0
12:05:30.321796 [0-0] < HTTP/1.1 200 OK
12:05:30.321871 [0-0] < Accept-Ranges: bytes
12:05:30.321948 [0-0] < Cross-Origin-Resource-Policy: cross-origin
12:05:30.322016 [0-0] < Cross-Origin-Opener-Policy-Report-Only: same-origin; report-to="static-on-bigtable"
12:05:30.322088 [0-0] < Report-To: {"group":"static-on-bigtable","max_age":2592000,"endpoints":[{"url":"https://csp.withgoogle.com/csp/report-to/static-on-bigtable"}]}
12:05:30.322163 [0-0] < Content-Length: 5430
12:05:30.322233 [0-0] < X-Content-Type-Options: nosniff
12:05:30.322302 [0-0] < Server: sffe
12:05:30.322375 [0-0] < X-XSS-Protection: 0
12:05:30.322448 [0-0] < Date: Fri, 08 Mar 2024 08:48:55 GMT
12:05:30.322521 [0-0] < Expires: Sat, 16 Mar 2024 08:48:55 GMT
12:05:30.322594 [0-0] < Cache-Control: public, max-age=691200
12:05:30.322664 [0-0] < Last-Modified: Tue, 22 Oct 2019 18:30:00 GMT
12:05:30.322733 [0-0] < Content-Type: image/x-icon
12:05:30.322801 [0-0] < Vary: Accept-Encoding
12:05:30.322875 [0-0] < Age: 4595
12:05:30.322947 [0-0] < Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000
12:05:30.323017 [0-0] < 
12:05:30.323095 [0-0] { [692 bytes data]
12:05:30.323249 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.323319 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.323395 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.323463 [0-0] { [5 bytes data]
12:05:30.323577 [0-0] * [TCP] nw_in_read(len=1395, fd=6) -> 1395, err=0
12:05:30.323645 [0-0] * [TCP] recv(len=1395) -> 1395, err=0
12:05:30.323722 [0-0] * [SSL] ossl_bio_cf_in_read(len=1395) -> 1395, err=0
12:05:30.323795 [0-0] { [1 bytes data]
12:05:30.323902 [0-0] * [SSL] cf_recv(len=4738) -> 1378, 0
12:05:30.323975 [0-0] { [1378 bytes data]
12:05:30.324113 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.324179 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.324243 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.324306 [0-0] { [5 bytes data]
12:05:30.324406 [0-0] * [TCP] nw_in_read(len=1395, fd=6) -> 1395, err=0
12:05:30.324470 [0-0] * [TCP] recv(len=1395) -> 1395, err=0
12:05:30.324534 [0-0] * [SSL] ossl_bio_cf_in_read(len=1395) -> 1395, err=0
12:05:30.324600 [0-0] { [1 bytes data]
12:05:30.324698 [0-0] * [SSL] cf_recv(len=3360) -> 1378, 0
12:05:30.324761 [0-0] { [1378 bytes data]
12:05:30.324873 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.324936 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.324999 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.325061 [0-0] { [5 bytes data]
12:05:30.325161 [0-0] * [TCP] nw_in_read(len=1395, fd=6) -> 1395, err=0
12:05:30.325223 [0-0] * [TCP] recv(len=1395) -> 1395, err=0
12:05:30.325286 [0-0] * [SSL] ossl_bio_cf_in_read(len=1395) -> 1395, err=0
12:05:30.325350 [0-0] { [1 bytes data]
12:05:30.325447 [0-0] * [SSL] cf_recv(len=1982) -> 1378, 0
12:05:30.325509 [0-0] { [1378 bytes data]
12:05:30.325618 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
12:05:30.325681 [0-0] * [TCP] recv(len=5) -> 5, err=0
12:05:30.325744 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
12:05:30.325806 [0-0] { [5 bytes data]
12:05:30.325905 [0-0] * [TCP] nw_in_read(len=621, fd=6) -> 621, err=0
12:05:30.325968 [0-0] * [TCP] recv(len=621) -> 621, err=0
12:05:30.326031 [0-0] * [SSL] ossl_bio_cf_in_read(len=621) -> 621, err=0
12:05:30.326095 [0-0] { [1 bytes data]
12:05:30.326191 [0-0] * [SSL] cf_recv(len=604) -> 604, 0
12:05:30.326253 [0-0] { [604 bytes data]
100  5430  100  5430    0     0  45703      0 --:--:-- --:--:-- --:--:-- 46016
12:05:30.326562 [0-0] * Connection #0 to host www.google.com left intact

image

@icing
Copy link
Contributor

icing commented Mar 8, 2024

Thanks. Just to explain: if curl encounters an error on its side, like writing binary to the terminal, it aborts the transfer. If the server is still sending at that time, it needs to see TCP RST from curl as its data was rejected.

@cuu508
Copy link

cuu508 commented Mar 8, 2024

@icing thanks for the explanation, appreciate it! So, when fetching the Google favicon, curl was working as designed. Another case of PEBKAC ;-)

The original issue was about RST packets when directing output to /dev/null. When I came across this issue originally, I was also investigating RST packets, but for requests that return plain text. So me picking Google favicon for the repro case was unfortunate, as it was behaving similarly, but for a separate reason.

Can we look at another favicon, https://en.wikipedia.org/favicon.ico?

Curl Trace
SSLKEYLOGFILE=/tmp/tls/secrets.log ./src/curl -v --trace-config all https://en.wikipedia.org/favicon.ico  -o /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     015:45:48.284311 [0-0] * Host en.wikipedia.org:443 was resolved.
15:45:48.284489 [0-0] * IPv6: 2a02:ec80:300:ed1a::1
15:45:48.284575 [0-0] * IPv4: 185.15.59.224
15:45:48.284664 [0-0] * [HTTPS-CONNECT] added
15:45:48.284750 [0-0] * [HTTPS-CONNECT] connect, init
15:45:48.284835 [0-0] * [HTTPS-CONNECT] connect, check h21
15:45:48.284921 [0-0] * [HAPPY-EYEBALLS] created ipv4 (timeout 299998ms)
15:45:48.285006 [0-0] * [HAPPY-EYEBALLS] created ipv6 (timeout 299998ms)
15:45:48.285093 [0-0] * [HAPPY-EYEBALLS] ipv4 starting (timeout=299998ms)
15:45:48.285195 [0-0] *   Trying 185.15.59.224:443...
15:45:48.285300 [0-0] * [TCP] cf_socket_open() -> 0, fd=6
15:45:48.285467 [0-0] * [TCP] local address 192.168.88.10 port 40850...
15:45:48.285564 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
15:45:48.285659 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
15:45:48.285754 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
15:45:48.285854 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
15:45:48.285955 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
15:45:48.286056 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
15:45:48.286152 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
15:45:48.286247 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
15:45:48.286358 [0-0] * [HTTPS-CONNECT] connect, check h21
15:45:48.286429 [0-0] * [TCP] not connected yet
15:45:48.286502 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
15:45:48.286573 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
15:45:48.286647 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
15:45:48.286721 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
15:45:48.286791 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
15:45:48.286862 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
15:45:48.286931 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
15:45:48.287003 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
15:45:48.328922 [0-0] * [HTTPS-CONNECT] connect, check h21
15:45:48.328988 [0-0] * [TCP] connected
15:45:48.329022 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=1
15:45:48.329061 [0-0] * Connected to en.wikipedia.org (185.15.59.224) port 443
15:45:48.329083 [0-0] * [SSL] cf_connect()
15:45:48.330448 [0-0] * ALPN: curl offers http/1.1
15:45:48.330621 [0-0] } [5 bytes data]
15:45:48.330676 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
15:45:48.330698 [0-0] } [512 bytes data]
15:45:48.330766 [0-0] * [TCP] send(len=517) -> 517, err=0
15:45:48.330787 [0-0] * [SSL] ossl_bio_cf_out_write(len=517) -> 517, err=0
15:45:48.330816 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
15:45:48.330840 [0-0] * [TCP] recv(len=5) -> -1, err=81
15:45:48.330863 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
15:45:48.330889 [0-0] * [SSL] populate_x509_store, path=/etc/ssl/certs/ca-certificates.crt, blob=0
15:45:48.360413 [0-0] *  CAfile: /etc/ssl/certs/ca-certificates.crt
15:45:48.360441 [0-0] *  CApath: /etc/ssl/certs
15:45:48.360466 [0-0] * [SSL] cf_connect() -> 0, done=0
15:45:48.360488 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
15:45:48.360513 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
15:45:48.360533 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
15:45:48.360555 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
15:45:48.360578 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
15:45:48.375465 [0-0] * [HTTPS-CONNECT] connect, check h21
15:45:48.375490 [0-0] * [SSL] cf_connect()
15:45:48.375534 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.375551 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.375567 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.375587 [0-0] { [5 bytes data]
15:45:48.375623 [0-0] * [TCP] nw_in_read(len=122, fd=6) -> 122, err=0
15:45:48.375645 [0-0] * [TCP] recv(len=122) -> 122, err=0
15:45:48.375668 [0-0] * [SSL] ossl_bio_cf_in_read(len=122) -> 122, err=0
15:45:48.375697 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
15:45:48.375719 [0-0] { [122 bytes data]
15:45:48.375956 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.375980 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.376022 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.376048 [0-0] { [5 bytes data]
15:45:48.376086 [0-0] * [TCP] nw_in_read(len=1, fd=6) -> 1, err=0
15:45:48.376109 [0-0] * [TCP] recv(len=1) -> 1, err=0
15:45:48.376141 [0-0] * [SSL] ossl_bio_cf_in_read(len=1) -> 1, err=0
15:45:48.376171 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.376196 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.376229 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.376259 [0-0] { [5 bytes data]
15:45:48.376296 [0-0] * [TCP] nw_in_read(len=42, fd=6) -> 42, err=0
15:45:48.376320 [0-0] * [TCP] recv(len=42) -> 42, err=0
15:45:48.376343 [0-0] * [SSL] ossl_bio_cf_in_read(len=42) -> 42, err=0
15:45:48.376372 [0-0] { [1 bytes data]
15:45:48.376410 [0-0] * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
15:45:48.376432 [0-0] { [25 bytes data]
15:45:48.376473 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.376496 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.376520 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.376543 [0-0] { [5 bytes data]
15:45:48.376581 [0-0] * [TCP] nw_in_read(len=3213, fd=6) -> 3213, err=0
15:45:48.376605 [0-0] * [TCP] recv(len=3213) -> 3213, err=0
15:45:48.376627 [0-0] * [SSL] ossl_bio_cf_in_read(len=3213) -> 3213, err=0
15:45:48.376653 [0-0] { [1 bytes data]
15:45:48.376692 [0-0] * TLSv1.3 (IN), TLS handshake, Certificate (11):
15:45:48.376716 [0-0] { [3196 bytes data]
15:45:48.377936 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.377959 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.377980 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.378001 [0-0] { [5 bytes data]
15:45:48.378036 [0-0] * [TCP] nw_in_read(len=97, fd=6) -> 97, err=0
15:45:48.378060 [0-0] * [TCP] recv(len=97) -> 97, err=0
15:45:48.378082 [0-0] * [SSL] ossl_bio_cf_in_read(len=97) -> 97, err=0
15:45:48.378107 [0-0] { [1 bytes data]
15:45:48.378143 [0-0] * TLSv1.3 (IN), TLS handshake, CERT verify (15):
15:45:48.378165 [0-0] { [80 bytes data]
15:45:48.378286 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.378309 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.378334 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.378357 [0-0] { [5 bytes data]
15:45:48.378394 [0-0] * [TCP] nw_in_read(len=69, fd=6) -> 69, err=0
15:45:48.378417 [0-0] * [TCP] recv(len=69) -> 69, err=0
15:45:48.378442 [0-0] * [SSL] ossl_bio_cf_in_read(len=69) -> 69, err=0
15:45:48.378467 [0-0] { [1 bytes data]
15:45:48.378505 [0-0] * TLSv1.3 (IN), TLS handshake, Finished (20):
15:45:48.378525 [0-0] { [52 bytes data]
15:45:48.378595 [0-0] * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
15:45:48.378617 [0-0] } [1 bytes data]
15:45:48.378672 [0-0] * TLSv1.3 (OUT), TLS handshake, Finished (20):
15:45:48.378693 [0-0] } [52 bytes data]
15:45:48.378736 [0-0] * [TCP] send(len=80) -> 80, err=0
15:45:48.378757 [0-0] * [SSL] ossl_bio_cf_out_write(len=80) -> 80, err=0
15:45:48.378805 [0-0] * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / X25519 / id-ecPublicKey
15:45:48.378827 [0-0] * ALPN: server accepted http/1.1
15:45:48.378850 [0-0] * Server certificate:
15:45:48.378879 [0-0] *  subject: C=US; ST=California; L=San Francisco; O=Wikimedia Foundation, Inc.; CN=*.wikipedia.org
15:45:48.378902 [0-0] *  start date: Oct 18 00:00:00 2023 GMT
15:45:48.378925 [0-0] *  expire date: Oct 16 23:59:59 2024 GMT
15:45:48.378959 [0-0] *  subjectAltName: host "en.wikipedia.org" matched cert's "*.wikipedia.org"
15:45:48.378986 [0-0] *  issuer: C=US; O=DigiCert Inc; CN=DigiCert TLS Hybrid ECC SHA384 2020 CA1
15:45:48.379008 [0-0] *  SSL certificate verify ok.
15:45:48.379035 [0-0] *   Certificate level 0: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using ecdsa-with-SHA384
15:45:48.379057 [0-0] *   Certificate level 1: Public key type EC/secp384r1 (384/192 Bits/secBits), signed using sha384WithRSAEncryption
15:45:48.379079 [0-0] *   Certificate level 2: Public key type RSA (2048/112 Bits/secBits), signed using sha1WithRSAEncryption
15:45:48.379100 [0-0] * [SSL] cf_connect() -> 0, done=1
15:45:48.379121 [0-0] * [HTTPS-CONNECT] connect+handshake h21: 94ms, 1st data: 90ms
15:45:48.379141 [0-0] * using HTTP/1.x
15:45:48.379165 [0-0] * [HTTPS-CONNECT] connect -> 0, done=1
15:45:48.379217 [0-0] } [5 bytes data]
15:45:48.379256 [0-0] * [TCP] send(len=116) -> 116, err=0
15:45:48.379277 [0-0] * [SSL] ossl_bio_cf_out_write(len=116) -> 116, err=0
15:45:48.379298 [0-0] > GET /favicon.ico HTTP/1.1
15:45:48.379298 [0-0] > Host: en.wikipedia.org
15:45:48.379298 [0-0] > User-Agent: curl/8.7.0-DEV
15:45:48.379298 [0-0] > Accept: */*
15:45:48.379298 [0-0] > 
15:45:48.379401 [0-0] * We are completely uploaded and fine
15:45:48.421279 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.421304 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.421325 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.421349 [0-0] { [5 bytes data]
15:45:48.421385 [0-0] * [TCP] nw_in_read(len=282, fd=6) -> 282, err=0
15:45:48.421408 [0-0] * [TCP] recv(len=282) -> 282, err=0
15:45:48.421430 [0-0] * [SSL] ossl_bio_cf_in_read(len=282) -> 282, err=0
15:45:48.421462 [0-0] { [1 bytes data]
15:45:48.421512 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
15:45:48.421536 [0-0] { [265 bytes data]
15:45:48.421609 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.421632 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.421655 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.421677 [0-0] { [5 bytes data]
15:45:48.421720 [0-0] * [TCP] nw_in_read(len=282, fd=6) -> 282, err=0
15:45:48.421742 [0-0] * [TCP] recv(len=282) -> 282, err=0
15:45:48.421765 [0-0] * [SSL] ossl_bio_cf_in_read(len=282) -> 282, err=0
15:45:48.421788 [0-0] { [1 bytes data]
15:45:48.421825 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
15:45:48.421847 [0-0] { [265 bytes data]
15:45:48.421893 [0-0] * old SSL session ID is stale, removing
15:45:48.421922 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
15:45:48.421946 [0-0] * [TCP] recv(len=5) -> -1, err=81
15:45:48.421971 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
15:45:48.421996 [0-0] * [SSL] cf_recv(len=102400) -> -1, 81
15:45:48.422530 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
15:45:48.422559 [0-0] * [TCP] recv(len=5) -> 5, err=0
15:45:48.422583 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
15:45:48.422606 [0-0] { [5 bytes data]
15:45:48.422646 [0-0] * [TCP] nw_in_read(len=3981, fd=6) -> 1443, err=0
15:45:48.422670 [0-0] * [TCP] recv(len=3981) -> 1443, err=0
15:45:48.422694 [0-0] * [SSL] ossl_bio_cf_in_read(len=3981) -> 1443, err=0
15:45:48.422719 [0-0] * [TCP] nw_in_read(len=2538, fd=6) -> -1, err=81
15:45:48.422742 [0-0] * [TCP] recv(len=2538) -> -1, err=81
15:45:48.422766 [0-0] * [SSL] ossl_bio_cf_in_read(len=2538) -> -1, err=81
15:45:48.422790 [0-0] * [SSL] cf_recv(len=102400) -> -1, 81
15:45:48.423861 [0-0] * [TCP] nw_in_read(len=2538, fd=6) -> 1448, err=0
15:45:48.423891 [0-0] * [TCP] recv(len=2538) -> 1448, err=0
15:45:48.423916 [0-0] * [SSL] ossl_bio_cf_in_read(len=2538) -> 1448, err=0
15:45:48.423940 [0-0] * [TCP] nw_in_read(len=1090, fd=6) -> 1090, err=0
15:45:48.423966 [0-0] * [TCP] recv(len=1090) -> 1090, err=0
15:45:48.423993 [0-0] * [SSL] ossl_bio_cf_in_read(len=1090) -> 1090, err=0
15:45:48.424038 [0-0] { [1 bytes data]
15:45:48.424085 [0-0] * [SSL] cf_recv(len=102400) -> 3964, 0
15:45:48.424114 [0-0] < HTTP/1.1 200 OK
15:45:48.424145 [0-0] < date: Fri, 08 Mar 2024 13:23:03 GMT
15:45:48.424169 [0-0] < server: mw1418.eqiad.wmnet
15:45:48.424194 [0-0] < x-content-type-options: nosniff
15:45:48.424219 [0-0] < cache-control: public
15:45:48.424246 [0-0] < expires: Sat, 09 Mar 2024 13:23:03 +0000
15:45:48.424271 [0-0] < content-type: image/vnd.microsoft.icon
15:45:48.424297 [0-0] < vary: Accept-Encoding
15:45:48.424322 [0-0] < age: 1365
15:45:48.424347 [0-0] < x-cache: cp3066 miss, cp3066 hit/50484
15:45:48.424374 [0-0] < x-cache-status: hit-front
15:45:48.424401 [0-0] < server-timing: cache;desc="hit-front", host;desc="cp3066"
15:45:48.424434 [0-0] < strict-transport-security: max-age=106384710; includeSubDomains; preload
15:45:48.424460 [0-0] < report-to: { "group": "wm_nel", "max_age": 604800, "endpoints": [{ "url": "https://intake-logging.wikimedia.org/v1/events?stream=w3c.reportingapi.network_error&schema_uri=/w3c/reportingapi/network_error/1.0.0" }] }
15:45:48.424485 [0-0] < nel: { "report_to": "wm_nel", "max_age": 604800, "failure_fraction": 0.05, "success_fraction": 0.0}
15:45:48.424511 [0-0] < set-cookie: WMF-Last-Access=08-Mar-2024;Path=/;HttpOnly;secure;Expires=Tue, 09 Apr 2024 12:00:00 GMT
15:45:48.424536 [0-0] < set-cookie: WMF-Last-Access-Global=08-Mar-2024;Path=/;Domain=.wikipedia.org;HttpOnly;secure;Expires=Tue, 09 Apr 2024 12:00:00 GMT
15:45:48.424562 [0-0] < x-client-ip: ********redacted*********
15:45:48.424589 [0-0] < set-cookie: GeoIP=******redacted******:v4; Path=/; secure; Domain=.wikipedia.org
15:45:48.424615 [0-0] < set-cookie: NetworkProbeLimit=0.001;Path=/;Secure;Max-Age=3600
15:45:48.424641 [0-0] < accept-ranges: bytes
15:45:48.424665 [0-0] < content-length: 2734
15:45:48.424690 [0-0] < 
15:45:48.424714 [0-0] { [2734 bytes data]
100  2734  100  2734    0     0  19193      0 --:--:-- --:--:-- --:--:-- 19253
15:45:48.424865 [0-0] * Connection #0 to host en.wikipedia.org left intact

Packet capture on client:

image

A couple observations:

  • I also see RST packets when fetching Wikipedia's favicon with wget. It may be a server issue, not a client issue, I'm not sure.
  • When fetching the Google favicon, only the client sent the TLS Close Notify message, the server didn't send it. For the Wikipedia favicon, client sends TLS Close Notify, then the client sends FIN ACK, then the server sends TLS Close notify.

@icing
Copy link
Contributor

icing commented Mar 8, 2024

Thanks @cuu508 ! I tested that and pushed an improvement to #13087. Would be nice if you could verify this.

@cuu508
Copy link

cuu508 commented Mar 10, 2024

I tested again:

Curl trace
SSLKEYLOGFILE=/tmp/tls/secrets.log curl -v --trace-config all https://en.wikipedia.org/favicon.ico  -o /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     011:53:12.115070 [0-0] * Host en.wikipedia.org:443 was resolved.
11:53:12.115308 [0-0] * IPv6: 2a02:ec80:300:ed1a::1
11:53:12.115428 [0-0] * IPv4: 185.15.59.224
11:53:12.115559 [0-0] * [HTTPS-CONNECT] added
11:53:12.115685 [0-0] * [HTTPS-CONNECT] connect, init
11:53:12.115809 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:12.115934 [0-0] * [HAPPY-EYEBALLS] created ipv4 (timeout 299997ms)
11:53:12.116081 [0-0] * [HAPPY-EYEBALLS] created ipv6 (timeout 299997ms)
11:53:12.116207 [0-0] * [HAPPY-EYEBALLS] ipv4 starting (timeout=299997ms)
11:53:12.116351 [0-0] *   Trying 185.15.59.224:443...
11:53:12.116499 [0-0] * [TCP] cf_socket_open() -> 0, fd=6
11:53:12.116726 [0-0] * [TCP] local address 192.168.88.10 port 57518...
11:53:12.116853 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
11:53:12.116976 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:53:12.117107 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:12.117230 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:12.117352 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:12.117476 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:12.117598 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:12.117721 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:12.117855 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:12.117982 [0-0] * [TCP] not connected yet
11:53:12.118108 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
11:53:12.118231 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:53:12.118359 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:12.118477 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:12.118603 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:12.118727 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
11:53:12.118748 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
11:53:12.118770 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:12.159800 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:12.159851 [0-0] * [TCP] connected
11:53:12.159879 [0-0] * [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=1
11:53:12.159906 [0-0] * Connected to en.wikipedia.org (185.15.59.224) port 443
11:53:12.159932 [0-0] * [SSL] cf_connect()
11:53:12.161497 [0-0] * ALPN: curl offers http/1.1
11:53:12.161743 [0-0] } [5 bytes data]
11:53:12.161781 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
11:53:12.161804 [0-0] } [512 bytes data]
11:53:12.161900 [0-0] * [TCP] send(len=517) -> 517, err=0
11:53:12.161938 [0-0] * [SSL] ossl_bio_cf_out_write(len=517) -> 517, err=0
11:53:12.161969 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
11:53:12.161993 [0-0] * [TCP] recv(len=5) -> -1, err=81
11:53:12.162017 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
11:53:12.162045 [0-0] * [SSL] populate_x509_store, path=/etc/ssl/certs/ca-certificates.crt, blob=0
11:53:12.194148 [0-0] *  CAfile: /etc/ssl/certs/ca-certificates.crt
11:53:12.194177 [0-0] *  CApath: /etc/ssl/certs
11:53:12.194202 [0-0] * [SSL] cf_connect() -> 0, done=0
11:53:12.194220 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
11:53:12.194243 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
11:53:12.194266 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:12.194304 [0-0] * [SSL] adjust_pollset, POLLIN fd=6
11:53:12.194326 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
11:53:12.205967 [0-0] * [HTTPS-CONNECT] connect, check h21
11:53:12.206008 [0-0] * [SSL] cf_connect()
11:53:12.206070 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.206087 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.206105 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.206127 [0-0] { [5 bytes data]
11:53:12.206162 [0-0] * [TCP] nw_in_read(len=122, fd=6) -> 122, err=0
11:53:12.206184 [0-0] * [TCP] recv(len=122) -> 122, err=0
11:53:12.206207 [0-0] * [SSL] ossl_bio_cf_in_read(len=122) -> 122, err=0
11:53:12.206232 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
11:53:12.206255 [0-0] { [122 bytes data]
11:53:12.206500 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.206523 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.206545 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.206567 [0-0] { [5 bytes data]
11:53:12.206604 [0-0] * [TCP] nw_in_read(len=1, fd=6) -> 1, err=0
11:53:12.206627 [0-0] * [TCP] recv(len=1) -> 1, err=0
11:53:12.206652 [0-0] * [SSL] ossl_bio_cf_in_read(len=1) -> 1, err=0
11:53:12.206677 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.206700 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.206725 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.206747 [0-0] { [5 bytes data]
11:53:12.206785 [0-0] * [TCP] nw_in_read(len=42, fd=6) -> 42, err=0
11:53:12.206808 [0-0] * [TCP] recv(len=42) -> 42, err=0
11:53:12.206832 [0-0] * [SSL] ossl_bio_cf_in_read(len=42) -> 42, err=0
11:53:12.206860 [0-0] { [1 bytes data]
11:53:12.206898 [0-0] * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
11:53:12.206920 [0-0] { [25 bytes data]
11:53:12.206961 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.206984 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.207006 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.207031 [0-0] { [5 bytes data]
11:53:12.207068 [0-0] * [TCP] nw_in_read(len=3213, fd=6) -> 3213, err=0
11:53:12.207093 [0-0] * [TCP] recv(len=3213) -> 3213, err=0
11:53:12.207117 [0-0] * [SSL] ossl_bio_cf_in_read(len=3213) -> 3213, err=0
11:53:12.207142 [0-0] { [1 bytes data]
11:53:12.207182 [0-0] * TLSv1.3 (IN), TLS handshake, Certificate (11):
11:53:12.207206 [0-0] { [3196 bytes data]
11:53:12.208484 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.208508 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.208530 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.208553 [0-0] { [5 bytes data]
11:53:12.208589 [0-0] * [TCP] nw_in_read(len=97, fd=6) -> 97, err=0
11:53:12.208610 [0-0] * [TCP] recv(len=97) -> 97, err=0
11:53:12.208633 [0-0] * [SSL] ossl_bio_cf_in_read(len=97) -> 97, err=0
11:53:12.208657 [0-0] { [1 bytes data]
11:53:12.208696 [0-0] * TLSv1.3 (IN), TLS handshake, CERT verify (15):
11:53:12.208720 [0-0] { [80 bytes data]
11:53:12.208843 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.208867 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.208892 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.208914 [0-0] { [5 bytes data]
11:53:12.208952 [0-0] * [TCP] nw_in_read(len=69, fd=6) -> 69, err=0
11:53:12.208975 [0-0] * [TCP] recv(len=69) -> 69, err=0
11:53:12.208999 [0-0] * [SSL] ossl_bio_cf_in_read(len=69) -> 69, err=0
11:53:12.209026 [0-0] { [1 bytes data]
11:53:12.209066 [0-0] * TLSv1.3 (IN), TLS handshake, Finished (20):
11:53:12.209083 [0-0] { [52 bytes data]
11:53:12.209147 [0-0] * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
11:53:12.209163 [0-0] } [1 bytes data]
11:53:12.209217 [0-0] * TLSv1.3 (OUT), TLS handshake, Finished (20):
11:53:12.209240 [0-0] } [52 bytes data]
11:53:12.209287 [0-0] * [TCP] send(len=80) -> 80, err=0
11:53:12.209314 [0-0] * [SSL] ossl_bio_cf_out_write(len=80) -> 80, err=0
11:53:12.209364 [0-0] * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / X25519 / id-ecPublicKey
11:53:12.209387 [0-0] * ALPN: server accepted http/1.1
11:53:12.209414 [0-0] * Server certificate:
11:53:12.209445 [0-0] *  subject: C=US; ST=California; L=San Francisco; O=Wikimedia Foundation, Inc.; CN=*.wikipedia.org
11:53:12.209473 [0-0] *  start date: Oct 18 00:00:00 2023 GMT
11:53:12.209499 [0-0] *  expire date: Oct 16 23:59:59 2024 GMT
11:53:12.209537 [0-0] *  subjectAltName: host "en.wikipedia.org" matched cert's "*.wikipedia.org"
11:53:12.209567 [0-0] *  issuer: C=US; O=DigiCert Inc; CN=DigiCert TLS Hybrid ECC SHA384 2020 CA1
11:53:12.209593 [0-0] *  SSL certificate verify ok.
11:53:12.209622 [0-0] *   Certificate level 0: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using ecdsa-with-SHA384
11:53:12.209646 [0-0] *   Certificate level 1: Public key type EC/secp384r1 (384/192 Bits/secBits), signed using sha384WithRSAEncryption
11:53:12.209670 [0-0] *   Certificate level 2: Public key type RSA (2048/112 Bits/secBits), signed using sha1WithRSAEncryption
11:53:12.209693 [0-0] * [SSL] cf_connect() -> 0, done=1
11:53:12.209717 [0-0] * [HTTPS-CONNECT] connect+handshake h21: 93ms, 1st data: 89ms
11:53:12.209743 [0-0] * using HTTP/1.x
11:53:12.209769 [0-0] * [HTTPS-CONNECT] connect -> 0, done=1
11:53:12.209825 [0-0] } [5 bytes data]
11:53:12.209872 [0-0] * [TCP] send(len=116) -> 116, err=0
11:53:12.209899 [0-0] * [SSL] ossl_bio_cf_out_write(len=116) -> 116, err=0
11:53:12.209924 [0-0] > GET /favicon.ico HTTP/1.1
11:53:12.209924 [0-0] > Host: en.wikipedia.org
11:53:12.209924 [0-0] > User-Agent: curl/8.7.0-DEV
11:53:12.209924 [0-0] > Accept: */*
11:53:12.209924 [0-0] > 
11:53:12.210041 [0-0] * We are completely uploaded and fine
11:53:12.252066 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.252091 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.252108 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.252129 [0-0] { [5 bytes data]
11:53:12.252164 [0-0] * [TCP] nw_in_read(len=282, fd=6) -> 282, err=0
11:53:12.252185 [0-0] * [TCP] recv(len=282) -> 282, err=0
11:53:12.252208 [0-0] * [SSL] ossl_bio_cf_in_read(len=282) -> 282, err=0
11:53:12.252236 [0-0] { [1 bytes data]
11:53:12.252284 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
11:53:12.252301 [0-0] { [265 bytes data]
11:53:12.252361 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.252385 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.252410 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.252435 [0-0] { [5 bytes data]
11:53:12.252480 [0-0] * [TCP] nw_in_read(len=282, fd=6) -> 282, err=0
11:53:12.252508 [0-0] * [TCP] recv(len=282) -> 282, err=0
11:53:12.252532 [0-0] * [SSL] ossl_bio_cf_in_read(len=282) -> 282, err=0
11:53:12.252557 [0-0] { [1 bytes data]
11:53:12.252596 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
11:53:12.252620 [0-0] { [265 bytes data]
11:53:12.252664 [0-0] * old SSL session ID is stale, removing
11:53:12.252695 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
11:53:12.252719 [0-0] * [TCP] recv(len=5) -> -1, err=81
11:53:12.252743 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
11:53:12.252767 [0-0] * [SSL] cf_recv(len=102400) -> -1, 81
11:53:12.253286 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
11:53:12.253305 [0-0] * [TCP] recv(len=5) -> 5, err=0
11:53:12.253322 [0-0] * [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
11:53:12.253343 [0-0] { [5 bytes data]
11:53:12.253402 [0-0] * [TCP] nw_in_read(len=3984, fd=6) -> 2891, err=0
11:53:12.253439 [0-0] * [TCP] recv(len=3984) -> 2891, err=0
11:53:12.253502 [0-0] * [SSL] ossl_bio_cf_in_read(len=3984) -> 2891, err=0
11:53:12.253526 [0-0] * [TCP] nw_in_read(len=1093, fd=6) -> -1, err=81
11:53:12.253577 [0-0] * [TCP] recv(len=1093) -> -1, err=81
11:53:12.253632 [0-0] * [SSL] ossl_bio_cf_in_read(len=1093) -> -1, err=81
11:53:12.253671 [0-0] * [SSL] cf_recv(len=102400) -> -1, 81
11:53:12.254477 [0-0] * [TCP] nw_in_read(len=1093, fd=6) -> 1093, err=0
11:53:12.254494 [0-0] * [TCP] recv(len=1093) -> 1093, err=0
11:53:12.254510 [0-0] * [SSL] ossl_bio_cf_in_read(len=1093) -> 1093, err=0
11:53:12.254535 [0-0] { [1 bytes data]
11:53:12.254571 [0-0] * [SSL] cf_recv(len=102400) -> 3967, 0
11:53:12.254593 [0-0] < HTTP/1.1 200 OK
11:53:12.254616 [0-0] < date: Sat, 09 Mar 2024 13:23:04 GMT
11:53:12.254637 [0-0] < server: mw1456.eqiad.wmnet
11:53:12.254658 [0-0] < x-content-type-options: nosniff
11:53:12.254679 [0-0] < cache-control: public
11:53:12.254699 [0-0] < expires: Sun, 10 Mar 2024 13:23:04 +0000
11:53:12.254720 [0-0] < content-type: image/vnd.microsoft.icon
11:53:12.254741 [0-0] < vary: Accept-Encoding
11:53:12.254761 [0-0] < age: 73808
11:53:12.254781 [0-0] < x-cache: cp3066 miss, cp3066 hit/2409075
11:53:12.254802 [0-0] < x-cache-status: hit-front
11:53:12.254823 [0-0] < server-timing: cache;desc="hit-front", host;desc="cp3066"
11:53:12.254846 [0-0] < strict-transport-security: max-age=106384710; includeSubDomains; preload
11:53:12.254869 [0-0] < report-to: { "group": "wm_nel", "max_age": 604800, "endpoints": [{ "url": "https://intake-logging.wikimedia.org/v1/events?stream=w3c.reportingapi.network_error&schema_uri=/w3c/reportingapi/network_error/1.0.0" }] }
11:53:12.254889 [0-0] < nel: { "report_to": "wm_nel", "max_age": 604800, "failure_fraction": 0.05, "success_fraction": 0.0}
11:53:12.254910 [0-0] < set-cookie: WMF-Last-Access=10-Mar-2024;Path=/;HttpOnly;secure;Expires=Thu, 11 Apr 2024 00:00:00 GMT
11:53:12.254931 [0-0] < set-cookie: WMF-Last-Access-Global=10-Mar-2024;Path=/;Domain=.wikipedia.org;HttpOnly;secure;Expires=Thu, 11 Apr 2024 00:00:00 GMT
11:53:12.254951 [0-0] < x-client-ip: **************
11:53:12.254972 [0-0] < set-cookie: GeoIP=******************:v4; Path=/; secure; Domain=.wikipedia.org
11:53:12.254993 [0-0] < set-cookie: NetworkProbeLimit=0.001;Path=/;Secure;Max-Age=3600
11:53:12.255013 [0-0] < accept-ranges: bytes
11:53:12.255034 [0-0] < content-length: 2734
11:53:12.255054 [0-0] < 
11:53:12.255075 [0-0] { [2734 bytes data]
100  2734  100  2734    0     0  19159      0 --:--:-- --:--:-- --:--:-- 19253
11:53:12.255194 [0-0] * Connection #0 to host en.wikipedia.org left intact

image

@icing
Copy link
Contributor

icing commented Mar 11, 2024

Thanks @cuu508 . This trace is from the following situation:

  1. request/response has been handled, curl choses to close the connection on terminating
  2. curl checks, server has not closed connection from its side
  3. curl sends TLS shutdown
  4. curl checks, one time effort, if anything from the server arrived
  5. curl closes the socket
  6. server sends its TLS shutdown
  7. TCP RSTs are sent back to server

This seems unavoidable, since curl is unwilling to hang around at (4) for the server's TLS shutdown to eventually arrive.

Imagine running a command line curl that, having done what you want it to do, waits a second or longer for a server reply that it has no need for. You'd wait for you shell to become available to you again and be quite irritated.

@cuu508
Copy link

cuu508 commented Mar 12, 2024

Thanks for explaining this scenario too, @icing! I now understand what is happening and why.

In the plain HTTP case, the client closes the connection gracefully with FIN ACK, but I'm assuming by that point curl has already closed the socket, and the remaining close sequence is handled by the OS. Whereas TLS Close Notify needs to be handled in the application layer.

From my POW, this issue is resolved. @dfdity, @dorrogeray ?

@dorrogeray
Copy link

@cuu508 I think what I am looking for will be partially solved by #13087, I am fine with marking this one as resolved 👍

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

No branches or pull requests

7 participants