Skip to content

SSL session closes with RST #10290

Description

@dfdity

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

Activity

  1. changed the title [-]Race condition upon ssl session closure that causes RST[/-] [+]SSL session closes with RST[/+] on Jan 13, 2023
  2. bagder commented on Jan 13, 2023

    @bagder
    Member

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

  3. dfdity commented on Jan 13, 2023

    @dfdity
    Author

    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.

  4. bagder commented on Jan 13, 2023

    @bagder
    Member

    I was trying to assess the impact of the problem.

  5. dfdity commented on Jan 14, 2023

    @dfdity
    Author

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

  6. bagder commented on Jan 14, 2023

    @bagder
    Member

    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?

  7. dfdity commented on Jan 19, 2023

    @dfdity
    Author

    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

  8. bagder commented on Jan 28, 2023

    @bagder
    Member

    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?

  9. frehberg commented on Mar 23, 2023

    @frehberg

    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

  10. cuu508 commented on Apr 10, 2023

    @cuu508

    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

  11. cuu508 commented on Apr 10, 2023

    @cuu508

    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.

  12. dfdity commented on Apr 11, 2023

    @dfdity
    Author

    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!

  13. 12 remaining items

  14. icing commented on Mar 8, 2024

    @icing
    Contributor

    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

  15. cuu508 commented on Mar 8, 2024

    @cuu508

    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

  16. icing commented on Mar 8, 2024

    @icing
    Contributor

    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.

  17. cuu508 commented on Mar 8, 2024

    @cuu508

    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

  18. icing commented on Mar 8, 2024

    @icing
    Contributor

    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
    
  19. cuu508 commented on Mar 8, 2024

    @cuu508

    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

  20. icing commented on Mar 8, 2024

    @icing
    Contributor

    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.

  21. cuu508 commented on Mar 8, 2024

    @cuu508

    @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.
  22. icing commented on Mar 8, 2024

    @icing
    Contributor

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

  23. cuu508 commented on Mar 10, 2024

    @cuu508

    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

  24. icing commented on Mar 11, 2024

    @icing
    Contributor

    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.

  25. cuu508 commented on Mar 12, 2024

    @cuu508

    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 ?

  26. dorrogeray commented on Mar 13, 2024

    @dorrogeray

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

  27. added a commit that references this issue on Mar 15, 2024
    c765b04
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions