Re: Sporadic timeouts on https://google.com with HTTP/3 on Arch Linux

From: Jicea via curl-library <curl-library_at_lists.haxx.se>
Date: Sun, 28 Jul 2024 14:16:14 +0000

> That's exactly the advice for the next step that I would offer. Getting HTTP/3
> details into a failing log should help us better understand what's going on.

I've enabled traces with curl_global_trace("http/3,ssl");

Here are logs of a timeout session:

* Host google.com:443 was resolved.
* IPv6: 2607:f8b0:4005:814::200e
* IPv4: 142.250.191.46
* Trying 142.250.191.46:443...
* [HTTP/3] populate_x509_store, path=/etc/ssl/certs/ca-certificates.crt, blob=0
* CAfile: /etc/ssl/certs/ca-certificates.crt
* CApath: none
* [HTTP/3] QUIC tls init -> 0
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 998ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 998ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 6ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] [2] send 16 bytes to QUIC blocked
* [HTTP/3] [10] send 1 bytes to QUIC blocked
* [HTTP/3] [6] send 1 bytes to QUIC blocked
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 0ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 0ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 12ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 6ms
* [HTTP/3] handshake complete after 18ms
* Server certificate:
* subject: CN=*.google.com
* start date: Jul 1 06:35:43 2024 GMT
* expire date: Sep 23 06:35:42 2024 GMT
* subjectAltName: host "google.com" matched cert's "google.com"
* issuer: C=US; O=Google Trust Services; CN=WR2
* SSL certificate verify ok.
* Certificate level 0: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using sha256WithRSAEncryption
* Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
* Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha384WithRSAEncryption
* [HTTP/3] peer verified
* [HTTP/3] QUIC expiry in 6ms
* [HTTP/3] connect -> 0, done=1
* Connected to google.com (142.250.191.46) port 443
* using HTTP/3
* [HTTP/3] [3] accepted remote uni stream
* [HTTP/3] [3] forward 48 bytes to nghttp3 -> 48
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] [0] OPENED stream for https://google.com/
* [HTTP/3] [0] [:method: HEAD]
* [HTTP/3] [0] [:scheme: https]
* [HTTP/3] [0] [:authority: google.com]
* [HTTP/3] [0] [:path: /]
* [HTTP/3] [0] [accept: */*]
* [HTTP/3] [0] send 9 bytes to QUIC ok
* [HTTP/3] [0] forwarded 9/9 h3 bytes to QUIC, eos=1
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 5ms
* [HTTP/3] [0] cf_send(len=48) -> 48, 0
> HEAD / HTTP/3
Host: google.com
Accept: */*
* Request completely sent off
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 29ms
* [HTTP/3] [0] cf_recv(len=16384) -> -1, 81
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 29ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 25ms
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 24999ms
* [HTTP/3] [0] cf_recv(len=16384) -> -1, 81
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 24999ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 24995ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 24945ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 24845ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 23844ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 22843ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 21842ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 20841ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 19840ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 18839ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 17838ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 16837ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 15836ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 14835ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 13834ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 12833ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 11832ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 10830ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 9829ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 8828ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 7827ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 6826ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 5825ms
* Operation timed out after 20002 milliseconds with 0 bytes received
* [HTTP/3] [0] easy handle is done
* [HTTP/3] [0] RESET: error 268
* Connection #0 to host google.com left intact

For comparison, here is a log of a normal session:

* Host google.com:443 was resolved.
* IPv6: 2607:f8b0:4004:c07::8b, 2607:f8b0:4004:c07::65, 2607:f8b0:4004:c07::66, 2607:f8b0:4004:c07::64
* IPv4: 142.251.163.100, 142.251.163.138, 142.251.163.139, 142.251.163.101, 142.251.163.113, 142.251.163.102
* Trying 142.251.163.100:443...
* [HTTP/3] populate_x509_store, path=/etc/ssl/certs/ca-certificates.crt, blob=0
* CAfile: /etc/ssl/certs/ca-certificates.crt
* CApath: none
* [HTTP/3] QUIC tls init -> 0
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 998ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 998ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 25ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 25ms
* [HTTP/3] QUIC SSL_connect() -> WANT_RECV
* [HTTP/3] QUIC expiry in 17ms
* [HTTP/3] handshake complete after 25ms
* Server certificate:
* subject: CN=*.google.com
* start date: Jul 1 06:35:43 2024 GMT
* expire date: Sep 23 06:35:42 2024 GMT
* subjectAltName: host "google.com" matched cert's "google.com"
* issuer: C=US; O=Google Trust Services; CN=WR2
* SSL certificate verify ok.
* Certificate level 0: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using sha256WithRSAEncryption
* Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
* Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha384WithRSAEncryption
* [HTTP/3] peer verified
* [HTTP/3] QUIC expiry in 25ms
* [HTTP/3] connect -> 0, done=1
* Connected to google.com (142.251.163.100) port 443
* using HTTP/3
* [HTTP/3] [3] accepted remote uni stream
* [HTTP/3] [3] forward 41 bytes to nghttp3 -> 41
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] [2] send 16 bytes to QUIC ok
* [HTTP/3] [2] forwarded 16/16 h3 bytes to QUIC, eos=0
* [HTTP/3] [10] send 1 bytes to QUIC ok
* [HTTP/3] [10] forwarded 1/1 h3 bytes to QUIC, eos=0
* [HTTP/3] [6] send 1 bytes to QUIC ok
* [HTTP/3] [6] forwarded 1/1 h3 bytes to QUIC, eos=0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] [0] OPENED stream for https://google.com/
* [HTTP/3] [0] [:method: HEAD]
* [HTTP/3] [0] [:scheme: https]
* [HTTP/3] [0] [:authority: google.com]
* [HTTP/3] [0] [:path: /]
* [HTTP/3] [0] [accept: */*]
* [HTTP/3] [6] send 12 bytes to QUIC ok
* [HTTP/3] [6] forwarded 12/12 h3 bytes to QUIC, eos=0
* [HTTP/3] [0] send 9 bytes to QUIC ok
* [HTTP/3] [0] forwarded 9/9 h3 bytes to QUIC, eos=1
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 24ms
* [HTTP/3] [0] cf_send(len=48) -> 48, 0
> HEAD / HTTP/3
Host: google.com
Accept: */*
* Request completely sent off
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 38ms
* [HTTP/3] [0] cf_recv(len=16384) -> -1, 81
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 38ms
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 35ms
* [HTTP/3] [0] cf_recv(len=16384) -> -1, 81
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 35ms
* [HTTP/3] [0] h3_quic_recv -> EOS
* [HTTP/3] [0] status: HTTP/3 301
* [HTTP/3] [0] header: location: https://www.google.com/
* [HTTP/3] [0] header: content-type: text/html; charset=UTF-8
* [HTTP/3] [0] header: content-security-policy-report-only: object-src 'none';base-uri 'self';script-src 'nonce-D_LHqMx56Q3nhK0cSlD2bQ' 'strict-dynamic' 'report-sample' 'unsafe-eval' 'unsafe-inline' https: http:;report-uri https://csp.withgoogle.com/csp/gws/other-hp
* [HTTP/3] [0] header: date: Sun, 28 Jul 2024 14:05:31 GMT
* [HTTP/3] [0] header: expires: Tue, 27 Aug 2024 14:05:31 GMT
* [HTTP/3] [0] header: cache-control: public, max-age=2592000
* [HTTP/3] [0] header: server: gws
* [HTTP/3] [0] header: content-length: 220
* [HTTP/3] [0] header: x-xss-protection: 0
* [HTTP/3] [0] header: x-frame-options: SAMEORIGIN
* [HTTP/3] [0] header: alt-svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000
* [HTTP/3] [0] end_headers, status=301
* [HTTP/3] [0] forward 374 bytes to nghttp3 -> 374
* [HTTP/3] [0] CLOSED
* [HTTP/3] [0] close nghttp3 stream -> 0
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 24ms
* [HTTP/3] [0] cf_recv(len=16384) -> 593, 0
< HTTP/3 301
< location: https://www.google.com/
< content-type: text/html; charset=UTF-8
< content-security-policy-report-only: object-src 'none';base-uri 'self';script-src 'nonce-D_LHqMx56Q3nhK0cSlD2bQ' 'strict-dynamic' 'report-sample' 'unsafe-eval' 'unsafe-inline' https: http:;report-uri https://csp.withgoogle.com/csp/gws/other-hp
< date: Sun, 28 Jul 2024 14:05:31 GMT
< expires: Tue, 27 Aug 2024 14:05:31 GMT
< cache-control: public, max-age=2592000
< server: gws
< content-length: 220
< x-xss-protection: 0
< x-frame-options: SAMEORIGIN
< alt-svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000
<
* [HTTP/3] [7] accepted remote uni stream
* [HTTP/3] [11] accepted remote uni stream
* [HTTP/3] [7] forward 2 bytes to nghttp3 -> 2
* [HTTP/3] [11] forward 2 bytes to nghttp3 -> 2
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 24ms
* [HTTP/3] [0] cf_recv(len=16384) -> 0, 0
* [HTTP/3] [0] easy handle is done
* Connection #0 to host google.com left intact

I can't pretend to understand the logs but I've the impression that there is a diff in the timeout session:

* [HTTP/3] QUIC expiry in 29ms
* [HTTP/3] [0] cf_recv(len=16384) -> -1, 81
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 29ms
* [HTTP/3] data idle
* [HTTP/3] QUIC expiry in 25ms
* [HTTP/3] progress_ingress -> 0
* [HTTP/3] h3_send_streams -> 0
* [HTTP/3] progress_egress -> 0
* [HTTP/3] QUIC expiry in 24999ms
* [HTTP/3] [0] cf_recv(len=16384) -> -1, 81

" QUIC expiry" jumps from 25ms to 24999ms, I don't see this kind of jumps in the normal session,

Hope someone will spot something!

Regards,

Jean-Christophe



On 27/07/2024, 14:44, "Daniel Stenberg" <daniel_at_haxx.se <mailto:daniel_at_haxx.se>> wrote:


--------------------------------------------------------------------------------------------------------------
CAUTION : This email originated outside the company. Do not click on any links or open attachments unless you are expecting them from the sender.


ATTENTION : Cet e-mail provient de l'extérieur de l'entreprise. Ne cliquez pas sur les liens ou n'ouvrez pas les pièces jointes à moins de connaitre l'expéditeur.
--------------------------------------------------------------------------------------------------------------


On Fri, 26 Jul 2024, Jicea via curl-library wrote:


> If somebody has any advice about how to approach this debugging, I'll be
> happy to test things. My next plan is to try to add more traces with
> curl_global_trace


That's exactly the advice for the next step that I would offer. Getting HTTP/3
details into a failing log should help us better understand what's going on.


Also of course: note that the OpenSSL-QUIC backend for HTTP/3 is still
considered experimental.


--


/ daniel.haxx.se
| Commercial curl support up to 24x7 is available!
| Private help, bug fixes, support, ports, new features
| https://curl.se/support.html <https://curl.se/support.html>



____________________________________________________________________________________________________________
Ce message et ses pieces jointes peuvent contenir des informations confidentielles ou privilegiees et ne doivent donc
pas etre diffuses, exploites ou copies sans autorisation. Si vous avez recu ce message par erreur, veuillez le signaler
a l'expediteur et le detruire ainsi que les pieces jointes. Les messages electroniques etant susceptibles d'alteration,
Orange decline toute responsabilite si ce message a ete altere, deforme ou falsifie. Merci.

This message and its attachments may contain confidential or privileged information that may be protected by law;
they should not be distributed, used or copied without authorisation.
If you have received this email in error, please notify the sender and delete this message and its attachments.
As emails may be altered, Orange is not liable for messages that have been modified, changed or falsified.
Thank you.

-- 
Unsubscribe: https://lists.haxx.se/mailman/listinfo/curl-library
Etiquette:   https://curl.se/mail/etiquette.html

Received on 2024-07-28