Skip to content

RestServer: investigate and fix http3 problems #382

Description

@wirew0rm

We've identified some problems with HTTP/3, where requests would sometimes stall instead of returning the expected result. As a quick workaround #381 removes the upgrade Headers, so clients will stick with HTTP2 while still being able to investigate HTTP3 by forcing the upgrade, but we need http3 to be re-enabled. The failing requests could be reproduced in curl and firefox (probably also chrome, but there it's more complicated - albeit documented in the README - to force http3 with certificate). In the following I've added some output from opendigitizer-service using http3 and -DOPENCMW_DEBUG_HTTP=ON cmake option and curl as a client:

I00000000 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con next skip pkn=49
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con recv packet len=1200
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt rx pkn=0 dcid=0x095316168109d650cca31392cbb7658abadcfff2 scid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e version=0x00000001 type=Initial len=1148
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm rx 0 Initial CRYPTO(0x06) offset=0 len=512
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con the negotiated version is 0x00000001
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters initial_source_connection_id=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters initial_max_stream_data_bidi_local=131072
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters initial_max_stream_data_bidi_remote=131072
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters initial_max_stream_data_uni=131072
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters initial_max_data=1310720
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters initial_max_streams_bidi=262144
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters initial_max_streams_uni=262144
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters max_idle_timeout=120000
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters max_udp_payload_size=65527
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters ack_delay_exponent=3
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters max_ack_delay=25
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters active_connection_id_limit=2
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters disable_active_migration=0
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters max_datagram_frame_size=0
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters grease_quic_bit=0
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters version_information.chosen_version=0x00000001
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 cry remote transport_parameters version_information.available_versions[0]=0x00000001
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm rx 0 Initial PADDING(0x00) len=615
I2178528939 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt read packet 1200 left 0
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt tx pkn=0 dcid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e scid=0x5a0c9a9977a363a42186e7d8a1e13141ec13 version=0x00000001 type=Initial len=0
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 0 Initial ACK(0x02) largest_ack=0 ack_delay=0(0) ack_range_count=0
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 0 Initial ACK(0x02) range=[0..0] len=0
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 0 Initial CRYPTO(0x06) offset=0 len=90
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 ldc loss_detection_timer=2178529939919116 timeout=999
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt tx pkn=0 dcid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e scid=0x5a0c9a9977a363a42186e7d8a1e13141ec13 version=0x00000001 type=Handshake len=0
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 0 Handshake CRYPTO(0x06) offset=0 len=964
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 ldc loss_detection_timer=2178529939919116 timeout=999
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt tx pkn=1 dcid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e scid=0x5a0c9a9977a363a42186e7d8a1e13141ec13 version=0x00000001 type=Handshake len=0
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 1 Handshake CRYPTO(0x06) offset=964 len=331
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 ldc loss_detection_timer=2178529939919116 timeout=999
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt tx pkn=0 dcid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e type=1RTT k=0
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 0 1RTT NEW_CONNECTION_ID(0x18) seq=1 cid=0xc3df727f7383ec8bf48269ebdf5906885c7a retire_prior_to=0 stateless_reset_token=0x95cf30392ead1521c6c00c114bbbf171
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 0 1RTT STREAM(0x0a) id=0x3 fin=0 offset=0 len=18 uni=1
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 0 1RTT STREAM(0x0a) id=0xb fin=0 offset=0 len=1 uni=1
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 0 1RTT STREAM(0x0a) id=0x7 fin=0 offset=0 len=1 uni=1
I2178528940 0x5a0c9a9977a363a42186e7d8a1e13141ec13 ldc loss_detection_timer=2178529939919116 timeout=999
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con recv packet len=1200
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt rx pkn=1 dcid=0x095316168109d650cca31392cbb7658abadcfff2 scid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e version=0x00000001 type=Initial len=1148
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm rx 1 Initial CRYPTO(0x06) offset=0 len=512
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm rx 1 Initial PADDING(0x00) len=615
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt read packet 1200 left 0
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con processing buffered handshake packet
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt tx pkn=1 dcid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e scid=0x5a0c9a9977a363a42186e7d8a1e13141ec13 version=0x00000001 type=Initial len=0
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 1 Initial ACK(0x02) largest_ack=1 ack_delay=0(0) ack_range_count=0
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 1 Initial ACK(0x02) range=[1..0] len=1
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 1 Initial CRYPTO(0x06) offset=0 len=90
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 ldc loss_detection_timer=2178529939919116 timeout=0
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt tx pkn=2 dcid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e scid=0x5a0c9a9977a363a42186e7d8a1e13141ec13 version=0x00000001 type=Handshake len=0
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 2 Handshake CRYPTO(0x06) offset=0 len=964
I2178529943 0x5a0c9a9977a363a42186e7d8a1e13141ec13 ldc loss_detection_timer=2178529964919116 timeout=21
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con recv packet len=1200
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt rx pkn=2 dcid=0x095316168109d650cca31392cbb7658abadcfff2 scid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e version=0x00000001 type=Initial len=1148
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm rx 2 Initial CRYPTO(0x06) offset=0 len=512
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm rx 2 Initial PADDING(0x00) len=615
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt read packet 1200 left 0
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con processing buffered handshake packet
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt tx pkn=2 dcid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e scid=0x5a0c9a9977a363a42186e7d8a1e13141ec13 version=0x00000001 type=Initial len=0
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 2 Initial ACK(0x02) largest_ack=2 ack_delay=0(0) ack_range_count=0
I2178531945 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 2 Initial ACK(0x02) range=[2..0] len=2
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con recv packet len=1200
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt rx pkn=3 dcid=0x095316168109d650cca31392cbb7658abadcfff2 scid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e version=0x00000001 type=Initial len=1148
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm rx 3 Initial CRYPTO(0x06) offset=0 len=512
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm rx 3 Initial PADDING(0x00) len=615
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt read packet 1200 left 0
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 con processing buffered handshake packet
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 pkt tx pkn=3 dcid=0xe94fa4557c9b11ca853e7d999274844bc2dc8a4e scid=0x5a0c9a9977a363a42186e7d8a1e13141ec13 version=0x00000001 type=Initial len=0
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 3 Initial ACK(0x02) largest_ack=3 ack_delay=0(0) ack_range_count=0
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 3 Initial ACK(0x02) range=[3..0] len=3
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 3 Initial PING(0x01)
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 ldc loss_detection_timer=2178529964919116 timeout=0
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 frm tx 1 1RTT PADDING(0x00) len=1089
I2178535946 0x5a0c9a9977a363a42186e7d8a1e13141ec13 ldc loss_detection_timer=2178529964919116 timeout=0
$ curl -k -vvvv "https://syspc008.gsi.de:8443/dashboards" --http3-only
16:57:22.411021 [0-x] == Info: [MULTI] [INIT] added, transfers=1
16:57:22.411163 [0-x] == Info: [MULTI] [INIT] multi_perform(running=1)
16:57:22.411275 [0-x] == Info: [MULTI] [INIT] -> [SETUP]
16:57:22.411370 [0-x] == Info: [MULTI] [SETUP] -> [CONNECT]
16:57:22.411463 [0-x] == Info: [READ] client_reset, clear readers
16:57:22.411592 [0-0] == Info: [MULTI] [CONNECT] [CPOOL] added connection 0. The cache now contains 1 members
16:57:22.411834 [0-0] == Info: [MULTI] [CONNECT] -> [RESOLVING]
16:57:22.411942 [0-0] == Info: [MULTI] [RESOLVING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:22.412562 [0-0] == Info: [MULTI] [RESOLVING] multi_perform(running=1)
16:57:22.412690 [0-0] == Info: [MULTI] [RESOLVING] Curl_multi_will_close fd=4
16:57:22.412817 [0-0] == Info: Host syspc008.gsi.de:8443 was resolved.
16:57:22.412929 [0-0] == Info: IPv6: (none)
16:57:22.412999 [0-0] == Info: IPv4: 140.181.95.179
16:57:22.413085 [0-0] == Info: [HTTPS-CONNECT] adding wanted h3
16:57:22.413194 [0-0] == Info: [HTTPS-CONNECT] added
16:57:22.413284 [0-0] == Info: [MULTI] [RESOLVING] -> [CONNECTING]
16:57:22.413405 [0-0] == Info: [HTTPS-CONNECT] connect, init
16:57:22.413495 [0-0] == Info: [HAPPY-EYEBALLS] created ipv4 (timeout 299998ms)
16:57:22.413620 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 starting (timeout=299998ms)
16:57:22.413752 [0-0] == Info:   Trying 140.181.95.179:8443...
16:57:22.413849 [0-0] == Info: [UDP] cf_socket_open() -> 0, fd=4
16:57:22.413966 [0-0] == Info: [UDP] QUIC socket 4 connected: [140.181.95.179:34406] -> [140.181.95.179:8443]
16:57:22.414203 [0-0] == Info: [UDP] cf_udp_connect(), opened socket=4 (140.181.95.179:34406)
16:57:22.415662 [0-0] == Info: [SSLS] find peer slot for syspc008.gsi.de:8443:QUIC:NO-VRFY-PEER:NO-VRFY-HOST:IMPL-quictls/3.3.0:G among 25 slots
16:57:22.415911 [0-0] == Info: [SSLS] peer not found for syspc008.gsi.de:8443:QUIC:NO-VRFY-PEER:NO-VRFY-HOST:IMPL-quictls/3.3.0:G
16:57:22.416123 [0-0] == Info: [SSLS] no cached session for syspc008.gsi.de:8443:QUIC:NO-VRFY-PEER:NO-VRFY-HOST:IMPL-quictls/3.3.0:G
16:57:22.416617 [0-0] == Info: [HTTP/3] vquic_send(len=1200, gso=1200) -> 0, sent=1200
16:57:22.416755 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:22.416874 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:22.416979 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:22.417131 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:22.417248 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:22.417361 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:22.417474 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=2
16:57:22.417603 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:22.417710 [0-0] == Info: [HTTP/3] ossl_populate_x509_store, path=none, blob=0
16:57:22.417842 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:22.417931 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:22.418062 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:22.418171 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:22.418302 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:22.418424 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:22.418531 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:22.418649 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:23.418350 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:23.418502 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:23.418596 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:23.418727 [0-0] == Info: [HTTP/3] vquic_send(len=1200, gso=1200) -> 0, sent=1200
16:57:23.418906 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:23.419102 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:23.419297 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:23.419533 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:23.419723 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:23.419934 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:23.420143 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:24.421344 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:24.421507 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:24.421615 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:24.421721 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:24.421907 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:24.422120 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:24.422220 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:24.422434 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:24.422614 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:25.419335 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:25.419519 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:25.419636 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:25.419801 [0-0] == Info: [HTTP/3] vquic_send(len=1200, gso=1200) -> 0, sent=1200
16:57:25.419988 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:25.420147 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:25.420269 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:25.420471 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:25.420605 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:25.420754 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:25.420903 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:26.422122 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:26.422266 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:26.422384 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:26.422499 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:26.422602 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:26.422794 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:26.422971 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:26.423113 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:26.423293 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:27.424523 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:27.424659 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:27.424759 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:27.424865 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:27.424958 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:27.425077 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:27.425177 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:27.425278 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:27.425402 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:28.426559 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:28.426735 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:28.426837 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:28.426944 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:28.427094 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:28.427279 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:28.427453 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:28.427593 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:28.427748 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:29.418958 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:29.419127 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:29.419247 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:29.419428 [0-0] == Info: [HTTP/3] vquic_send(len=1200, gso=1200) -> 0, sent=1200
16:57:29.419629 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:29.419832 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:29.419984 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:29.420171 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:29.420377 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:29.420568 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:29.420695 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:30.421882 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:30.422012 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:30.422118 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:30.422226 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:30.422355 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:30.422435 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:30.422502 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:30.422569 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:30.422636 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:31.423342 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:31.423468 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:31.423567 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
16:57:31.423674 [0-0] == Info: [HTTPS-CONNECT] connect -> 0, done=0
16:57:31.423765 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 0, done=0
16:57:31.423887 [0-0] == Info: [UDP] adjust_pollset, !active, POLLIN fd=4
16:57:31.423986 [0-0] == Info: [HAPPY-EYEBALLS] adjust_pollset -> 1 socks
16:57:31.424086 [0-0] == Info: [HTTPS-CONNECT] adjust_pollset -> 1 socks
16:57:31.424184 [0-0] == Info: [MULTI] [CONNECTING] multi_wait pollset[fd=4 IN], timeouts=1
16:57:32.417337 [0-0] == Info: [MULTI] [CONNECTING] multi_perform(running=1)
16:57:32.417475 [0-0] == Info: [HTTP/3] ingress, recvmmsg -> EAGAIN
16:57:32.417590 [0-0] == Info: ngtcp2_conn_handle_expiry returned error: ERR_HANDSHAKE_TIMEOUT
16:57:32.417719 [0-0] == Info: [HTTP/3] connect -> 55, done=0
16:57:32.417857 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 connect -> 55, connected=0
16:57:32.417966 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 done
16:57:32.418097 [0-0] == Info: [HAPPY-EYEBALLS] all eyeballers failed
16:57:32.418194 [0-0] == Info: [HAPPY-EYEBALLS] ipv4 assess started=1, result=55
16:57:32.418378 [0-0] == Info: Failed to connect to syspc008.gsi.de port 8443 after 10005 ms: Failed sending data to the peer
16:57:32.418552 [0-0] == Info: [HTTPS-CONNECT] connect, all attempts failed
16:57:32.418658 [0-0] == Info: [HTTPS-CONNECT] connect -> 55, done=0
16:57:32.418753 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(block=0) -> 55, done=0
16:57:32.418873 [0-0] == Info: [HTTPS-CONNECT] Curl_conn_connect(), filter returned 55
16:57:32.418992 [0-0] == Info: [MULTI] [CONNECTING] multi_done: status: 55 prem: 1 done: 0
16:57:32.419114 [0-0] == Info: [WRITE] [OUT] done
16:57:32.419201 [0-0] == Info: [MULTI] [CONNECTING] multi_done, not reusing connection=0, forbid=0, close=0, premature=1, conn_multiplex=0
16:57:32.419418 [0-0] == Info: closing connection #0
16:57:32.419625 [0-0] == Info: [MULTI] [CONNECTING] -> [COMPLETED]
16:57:32.419744 [0-0] == Info: [MULTI] [COMPLETED] Expire cleared
16:57:32.419845 [0-0] == Info: [MULTI] [COMPLETED] -> [MSGSENT]
16:57:32.419944 [0-0] == Info: [MULTI] [COMPLETED] removed, transfers=0
curl: (55) ngtcp2_conn_handle_expiry returned error: ERR_HANDSHAKE_TIMEOUT

To test in firefox, set in about::config:

network.http.http3.disable_when_third_party_roots_found = false
network.http.http3.alt-svc-mapping-for-testing=opencmw-service.example.com;h3=":443";h3-29=":443"

Activity

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions