Opened 9 months ago

Closed 7 months ago

#2500 closed defect (fixed)

After update to nginx 1.25 and configure vhost to enable http/3 quic error generated

Reported by: cristianorevil@… Owned by:
Priority: major Milestone: nginx-1.25
Component: http/3 Version:
Keywords: Cc:
uname -a: Linux xxxxxxxxx 5.15.0-69-generic #76-Ubuntu SMP Fri Mar 17 17:19:29 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.25.0
built by gcc 11.3.0 (Ubuntu 11.3.0-1ubuntu1~22.04.1)
built with OpenSSL 3.0.2 15 Mar 2022
TLS SNI support enabled
configure arguments: --with-cc-opt=-DNGX_HTTP_HEADERS --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib/nginx/modules --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx --with-compat --with-file-aio --with-threads --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_mp4_module --with-http_random_index_module --with-http_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module --with-http_v3_module --with-mail --with-mail_ssl_module --with-stream --with-stream_realip_module --with-stream_ssl_module --with-stream_ssl_preread_module --with-cc-opt='-g -O2 -fPIE -fstack-protector-strong -Wformat -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -fPIC -DTCP_FASTOPEN=23' --with-ld-opt='-Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now -Wl,--as-needed -pie'

Description

I have update nginx to 1.25 in ubuntu 22.04, the update was installe successfully, i have confgured a vhost to add http3 directives:

listen 443 quic reuseport;
listen 443 ssl http2;

location / {

# used to advertise the availability of HTTP/3
add_header Alt-Svc 'h3=":443"; ma=86400';
.....

}

Testing a connection with a browser (last verions of chorme or last version of firefox) i see the connetcion still remain http/2 but the header Alt-Svc 'h3=":443"; ma=86400'; is present, if i test an http3 connection with curl, the connection fail and in nginx error log i see:

ssl_do_handshake() failed (ssl: error:0a000119:ssl routines::decryption failed or bad record mac) while handling frames

Retesting with curl and hhtp2 all works fine

Attachments (1)

quic-compat-level (1.1 KB ) - added by Roman Arutyunyan 9 months ago.

Download all attachments as: .zip

Change History (10)

comment:1 by Roman Arutyunyan, 9 months ago

Could you enable debug logging and post the log?

https://nginx.org/en/docs/debugging_log.html

comment:2 by cristianorevil@…, 9 months ago

here the log:

2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B010:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: malloc: 0000559E68E3B220:1200
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic recvmsg: 192.168.113.2:51638 fd:60 n:1200
2023/05/25 18:03:06 [debug] 12878#12878: *2 http3 init session
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68E3B6E0:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 add cleanup: 0000559E68E3B868
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 60000:5605022
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic run
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx long flags:cd version:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx init len:295
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx dcid len:16 f22a1225dc2a05bc25c609f44ae28ce1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx scid len:20 9cc632e6927ad9eac5f1a74063b5bc0b6866ac33
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic address validation token len:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 malloc: 0000559E68E39C20:2352
2023/05/25 18:03:06 [debug] 12878#12878: *2 malloc: 0000559E68A4C3E0:1928
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_set_initial_secret
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68E3A560:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic socket seq:0 listening at sid:0000000000002003d1df8f4829b6b6bbf9db70a6 nsock:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic cid seq:0 received id:20:9cc632e6927ad9eac5f1a74063b5bc0b6866ac33:00000000000000000000000000000000
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68E3A770:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path seq:0 created addr:192.168.113.2:51638
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path seq:0 set active sent:0 recvd:0 state:LN
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68E3A980:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic socket seq:-1 listening at sid:f22a1225dc2a05bc25c609f44ae28ce1 nsock:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 reusable connection: 1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic connection created
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx clearflags:c0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx number:0 len:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet len:1200 via sock seq:0 path seq:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path seq:0 status sent:0 recvd:1200 state:LN
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat set method
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68A4CD40:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic stateless reset token d27471517c4892e2957d3a7ff4d306c6
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame rx init CRYPTO len:274 off:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic SSL_quic_read_level:0 SSL_quic_write_level:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat rx init len:274
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat parse transport params
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL server name: "avapa.hextra.dev"
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL ALPN supported by client: h3
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL ALPN supported by client: h3-29
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL ALPN supported by client: h3-28
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL ALPN supported by client: h3-27
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL ALPN selected: h3
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat tx init len:90
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_add_handshake_data
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic SSL_get_peer_quic_transport_params(): params_len:76
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic transport parameters parsed ok
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp disable active migration: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp idle_timeout:60000
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp max_udp_payload_size:65527
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp max_data:1048576
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp max_stream_data_bidi_local:1048576
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp max_stream_data_bidi_remote:1048576
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp max_stream_data_uni:1048576
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp initial_max_streams_bidi:262144
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp initial_max_streams_uni:262144
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp ack_delay_exponent:3
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp max_ack_delay:25
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp active_connection_id_limit:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic tp initial source_connection_id len:20 9cc632e6927ad9eac5f1a74063b5bc0b6866ac33
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic client maximum packet size truncated
2023/05/25 18:03:06 [debug] 12878#12878: *2 malloc: 0000559E68E7D490:4096
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68A4D990:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 post event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat secret SERVER_HANDSHAKE_TRAFFIC_SECRET
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_set_write_secret() level:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat secret CLIENT_HANDSHAKE_TRAFFIC_SECRET
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_set_read_secret() level:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat add transport params
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat tx hs len:133
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_add_handshake_data
2023/05/25 18:03:06 [debug] 12878#12878: *2 malloc: 0000559E68E7E930:4096
2023/05/25 18:03:06 [debug] 12878#12878: *2 update posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat tx hs len:4287
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_add_handshake_data
2023/05/25 18:03:06 [debug] 12878#12878: *2 malloc: 0000559E68E7F940:4096
2023/05/25 18:03:06 [debug] 12878#12878: *2 malloc: 0000559E68B9BE70:4096
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68E80950:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 update posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat tx hs len:520
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_add_handshake_data
2023/05/25 18:03:06 [debug] 12878#12878: *2 malloc: 0000559E68C00000:4096
2023/05/25 18:03:06 [debug] 12878#12878: *2 update posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat tx hs len:52
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_add_handshake_data
2023/05/25 18:03:06 [debug] 12878#12878: *2 malloc: 0000559E68C01010:4096
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68B9E3D0:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 update posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat secret EXPORTER_SECRET
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat secret SERVER_TRAFFIC_SECRET_0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_set_write_secret() level:3
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic SSL_quic_read_level:2 SSL_quic_write_level:3
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL_do_handshake: -1
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL_get_error: 2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_ack_packet pn:0 largest -1 fr:0 nranges:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 update posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet done rc:0 level:init decr:1 pn:0 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx short flags:0
2023/05/25 18:03:06 [info] 12878#12878: *2 quic fixed bit is not set while parsing quic packet, client: 192.168.113.2, server: 0.0.0.0:443
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet done rc:-5 parse failed
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 60000:5605022
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: read:60000
2023/05/25 18:03:06 [debug] 12878#12878: *2 delete posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic push handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 post event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output init packet max:1252 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx init CRYPTO len:90 off:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx init ACK n:0 delay:0 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet tx init bytes:99 need_ack:1 number:0 encoded nl:1 trunc:0x0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:1086 min:1034
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CRYPTO len:133 off:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic split frame now:4292 need:883 shrink:3409
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CRYPTO len:878 off:133
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet tx hs bytes:1020 need_ack:1 number:0 encoded nl:1 trunc:0x0
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 1252 of 1252
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:166
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:1252
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:1252
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:1252 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic split frame now:3414 need:1186 shrink:2228
2023/05/25 18:03:06 [debug] 12878#12878: *2 posix_memalign: 0000559E68B9E5E0:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CRYPTO len:1181 off:1011
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet tx hs bytes:1186 need_ack:1 number:1 encoded nl:1 trunc:0x1
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 1252 of 1252
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:1252
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:2504
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:2504
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path limit 1252 - 1096
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:1096 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic split frame now:2233 need:1030 shrink:1203
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CRYPTO len:1025 off:2192
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet tx hs bytes:1030 need_ack:1 number:2 encoded nl:1 trunc:0x2
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 1096 of 1096
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:2504
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:3600
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:3600
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path limit 1252 - 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:0 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer: 60, old: 5605022, new: 5605022
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:997
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 997:5546019
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: send:60000 pto:997
2023/05/25 18:03:06 [debug] 12878#12878: *2 delete posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic push handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path limit 1252 - 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:0 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: send:60000 pto:997
2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic recvmsg: fd:60 n:1200
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic input handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx long flags:c7 version:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx init len:22
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx scid len:20 9cc632e6927ad9eac5f1a74063b5bc0b6866ac33
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic address validation token len:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx clearflags:c0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx number:1 len:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet len:1200 via sock seq:0 path seq:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path seq:0 status sent:3600 recvd:2400 state:LN
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame rx init ACK n:0 delay:15 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_handle_ack_frame level:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion ack recovery win:131054 ss:-1 if:3434
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_drop_ack_ranges pn:0 largest:0 fr:0 nranges:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 post event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic updated largest received ack:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic rtt sample latest:111 min:111 avg:111 var:55
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5546019
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:220
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 220:5545353
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_ack_packet pn:1 largest -1 fr:0 nranges:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet done rc:0 level:init decr:1 pn:1 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx long flags:ea version:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx hs len:22
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx scid len:20 9cc632e6927ad9eac5f1a74063b5bc0b6866ac33
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx clearflags:e0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx number:0 len:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic socket seq:-1 closed nsock:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5545353
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:220
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 220:5545353
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path seq:0 in handshake sent:3600 recvd:2400 state:V
2023/05/25 18:03:06 [debug] 12878#12878: *2 update posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame rx hs ACK n:0 delay:1 1-0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_handle_ack_frame level:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion ack recovery win:131054 ss:-1 if:2348
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion ack recovery win:131054 ss:-1 if:1096
2023/05/25 18:03:06 [debug] 12878#12878: *2 update posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic updated largest received ack:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic rtt sample latest:111 min:111 avg:111 var:42
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5545353
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:168
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 168:5545301
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_ack_packet pn:0 largest -1 fr:0 nranges:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet done rc:0 level:hs decr:1 pn:0 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx short flags:0
2023/05/25 18:03:06 [info] 12878#12878: *2 quic fixed bit is not set while parsing quic packet, client: 192.168.113.2, server: 0.0.0.0:443
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet done rc:-5 parse failed
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer: 60, old: 5605022, new: 5605133
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: read:59889 pto:168
2023/05/25 18:03:06 [debug] 12878#12878: *2 delete posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic push handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:1252 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic split frame now:1208 need:1186 shrink:22
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CRYPTO len:1181 off:3217
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet tx hs bytes:1186 need_ack:1 number:3 encoded nl:1 trunc:0x3
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 1252 of 1252
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:1096
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:2348
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:2348
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:1252 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CRYPTO len:22 off:4398
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CRYPTO len:520 off:4420
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CRYPTO len:52 off:4940
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet tx hs bytes:607 need_ack:1 number:4 encoded nl:1 trunc:0x4
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 673 of 673
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:2348
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:3021
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:3021
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer: 60, old: 5605022, new: 5605133
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5545301
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:279
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 279:5545412
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: send:59889 pto:279
2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic recvmsg: fd:60 n:71
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic input handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx long flags:e3 version:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx hs len:22
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx scid len:20 9cc632e6927ad9eac5f1a74063b5bc0b6866ac33
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx clearflags:e0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx number:1 len:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet len:71 via sock seq:0 path seq:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path seq:0 status sent:5525 recvd:2471 state:V
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame rx hs ACK n:0 delay:3 2-0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_handle_ack_frame level:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion ack recovery win:131054 ss:-1 if:1925
2023/05/25 18:03:06 [debug] 12878#12878: *2 post event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic updated largest received ack:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic rtt sample latest:210 min:111 avg:124 var:53
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5545412
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:237
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 237:5545469
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_ack_packet pn:1 largest 0 fr:0 nranges:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet done rc:0 level:hs decr:1 pn:1 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer: 60, old: 5605022, new: 5605232
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: read:59790 pto:237
2023/05/25 18:03:06 [debug] 12878#12878: *2 delete posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic push handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: read:59790 pto:237
2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic recvmsg: fd:60 n:71
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic input handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx long flags:e7 version:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx hs len:22
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx scid len:20 9cc632e6927ad9eac5f1a74063b5bc0b6866ac33
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx clearflags:e0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx number:2 len:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet len:71 via sock seq:0 path seq:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path seq:0 status sent:5525 recvd:2542 state:V
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame rx hs ACK n:0 delay:1 3-0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_handle_ack_frame level:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion slow start win:132306 ss:-1 if:673
2023/05/25 18:03:06 [debug] 12878#12878: *2 post event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic updated largest received ack:3
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic rtt sample latest:274 min:111 avg:143 var:72
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5545469
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:157
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 157:5545564
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_ack_packet pn:2 largest 1 fr:1 nranges:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet done rc:0 level:hs decr:1 pn:2 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5605022
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 60000:5605407
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: read:60000 pto:157
2023/05/25 18:03:06 [debug] 12878#12878: *2 delete posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic push handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: read:60000 pto:157
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5545564
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic pto timer
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic pto hs pto_count:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 post event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 update posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: read:59843
2023/05/25 18:03:06 [debug] 12878#12878: *2 delete posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic push handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:1252 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs PING
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet tx hs bytes:3 need_ack:1 number:5 encoded nl:1 trunc:0x5
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 68 of 68
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:673
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:741
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:741
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic output hs packet max:1252 min:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs PING
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet tx hs bytes:3 need_ack:1 number:6 encoded nl:1 trunc:0x6
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 68 of 68
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:741
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:809
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion send if:809
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer: 60, old: 5605407, new: 5605564
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:862
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 862:5546426
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic state: send:59843 pto:862
2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic recvmsg: fd:60 n:128
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic input handler
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx long flags:e9 version:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx hs len:79
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx scid len:20 9cc632e6927ad9eac5f1a74063b5bc0b6866ac33
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx clearflags:e0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet rx number:3 len:1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet len:128 via sock seq:0 path seq:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic path seq:0 status sent:5661 recvd:2670 state:V
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame rx hs ACK n:0 delay:122 4-0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_handle_ack_frame level:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic congestion slow start win:132979 ss:-1 if:136
2023/05/25 18:03:06 [debug] 12878#12878: *2 post event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic updated largest received ack:4
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic rtt sample latest:495 min:111 avg:187 var:131
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5546426
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic lost timer pto:647
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer add: 60: 647:5546275
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame rx hs CRYPTO len:52 off:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic SSL_quic_read_level:2 SSL_quic_write_level:3
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat rx hs len:52
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic compat app alert:20 len:2
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic ngx_quic_send_alert() level:app alert:20
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic SSL_quic_read_level:2 SSL_quic_write_level:3
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL_do_handshake: -1
2023/05/25 18:03:06 [debug] 12878#12878: *2 SSL_get_error: 1
2023/05/25 18:03:06 [error] 12878#12878: *2 SSL_do_handshake() failed (SSL: error:0A000119:SSL routines::decryption failed or bad record mac) while handling frames, client: 192.168.113.2, server: 0.0.0.0:443
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic packet done rc:-1 level:hs decr:1 pn:3 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic close initiated rc:-1
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic close immediate term:1 drain:0 error:276 "handshake failed"
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx hs CONNECTION_CLOSE err:276 handshake failed ft:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 86 of 86
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic frame tx init CONNECTION_CLOSE err:276 handshake failed ft:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 sendmsg: 87 of 87
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5546275
2023/05/25 18:03:06 [debug] 12878#12878: *2 delete posted event 0000559E68E3A228
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic socket seq:0 closed nsock:0
2023/05/25 18:03:06 [debug] 12878#12878: *2 quic close completed
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: 60: 5605407
2023/05/25 18:03:06 [debug] 12878#12878: *2 reusable connection: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 run cleanup: 0000559E68E3B868
2023/05/25 18:03:06 [debug] 12878#12878: *2 event timer del: -1: 5605022
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68C01010
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68C00000
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68B9BE70
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E7F940
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E7E930
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E7D490
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68A4C3E0
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E39C20
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E3B220
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E3B010, unused: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E3B6E0, unused: 8
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E3A560, unused: 8
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E3A770, unused: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E3A980, unused: 8
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68A4CD40, unused: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68A4D990, unused: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68E80950, unused: 0
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68B9E3D0, unused: 8
2023/05/25 18:03:06 [debug] 12878#12878: *2 free: 0000559E68B9E5E0, unused: 0
2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B6E0:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *3 quic recvmsg: 192.168.113.2:51638 fd:60 n:62
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B010:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *3 http3 init session
2023/05/25 18:03:06 [debug] 12878#12878: *3 add cleanup: 0000559E68E3B8B8
2023/05/25 18:03:06 [debug] 12878#12878: *3 event timer add: 60: 60000:5605629
2023/05/25 18:03:06 [debug] 12878#12878: *3 quic run
2023/05/25 18:03:06 [debug] 12878#12878: *3 quic packet rx short flags:49
2023/05/25 18:03:06 [debug] 12878#12878: *3 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *3 quic handle stateless reset output
2023/05/25 18:03:06 [debug] 12878#12878: *3 quic stateless reset token d27471517c4892e2957d3a7ff4d306c6
2023/05/25 18:03:06 [debug] 12878#12878: *3 sendmsg: 79 of 79
2023/05/25 18:03:06 [debug] 12878#12878: *3 quic packet done rc:-5 level:app decr:0 pn:0 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *3 quic packet rejected rc:-4, cleanup connection
2023/05/25 18:03:06 [debug] 12878#12878: *3 reusable connection: 0
2023/05/25 18:03:06 [debug] 12878#12878: *3 run cleanup: 0000559E68E3B8B8
2023/05/25 18:03:06 [debug] 12878#12878: *3 event timer del: -1: 5605629
2023/05/25 18:03:06 [debug] 12878#12878: *3 free: 0000559E68E3B6E0, unused: 16
2023/05/25 18:03:06 [debug] 12878#12878: *3 free: 0000559E68E3B010, unused: 48
2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B010:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *4 quic recvmsg: 192.168.113.2:51638 fd:60 n:44
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B6E0:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *4 http3 init session
2023/05/25 18:03:06 [debug] 12878#12878: *4 add cleanup: 0000559E68E3B880
2023/05/25 18:03:06 [debug] 12878#12878: *4 event timer add: 60: 60000:5605629
2023/05/25 18:03:06 [debug] 12878#12878: *4 quic run
2023/05/25 18:03:06 [debug] 12878#12878: *4 quic packet rx short flags:40
2023/05/25 18:03:06 [debug] 12878#12878: *4 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *4 quic handle stateless reset output
2023/05/25 18:03:06 [debug] 12878#12878: *4 quic stateless reset token d27471517c4892e2957d3a7ff4d306c6
2023/05/25 18:03:06 [debug] 12878#12878: *4 sendmsg: 47 of 47
2023/05/25 18:03:06 [debug] 12878#12878: *4 quic packet done rc:-5 level:app decr:0 pn:0 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *4 quic packet rejected rc:-4, cleanup connection
2023/05/25 18:03:06 [debug] 12878#12878: *4 reusable connection: 0
2023/05/25 18:03:06 [debug] 12878#12878: *4 run cleanup: 0000559E68E3B880
2023/05/25 18:03:06 [debug] 12878#12878: *4 event timer del: -1: 5605629
2023/05/25 18:03:06 [debug] 12878#12878: *4 free: 0000559E68E3B010, unused: 8
2023/05/25 18:03:06 [debug] 12878#12878: *4 free: 0000559E68E3B6E0, unused: 72
2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B6E0:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *5 quic recvmsg: 192.168.113.2:51638 fd:60 n:44
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B010:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *5 http3 init session
2023/05/25 18:03:06 [debug] 12878#12878: *5 add cleanup: 0000559E68E3B1B0
2023/05/25 18:03:06 [debug] 12878#12878: *5 event timer add: 60: 60000:5605630
2023/05/25 18:03:06 [debug] 12878#12878: *5 quic run
2023/05/25 18:03:06 [debug] 12878#12878: *5 quic packet rx short flags:5c
2023/05/25 18:03:06 [debug] 12878#12878: *5 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *5 quic handle stateless reset output
2023/05/25 18:03:06 [debug] 12878#12878: *5 quic stateless reset token d27471517c4892e2957d3a7ff4d306c6
2023/05/25 18:03:06 [debug] 12878#12878: *5 sendmsg: 110 of 110
2023/05/25 18:03:06 [debug] 12878#12878: *5 quic packet done rc:-5 level:app decr:0 pn:0 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *5 quic packet rejected rc:-4, cleanup connection
2023/05/25 18:03:06 [debug] 12878#12878: *5 reusable connection: 0
2023/05/25 18:03:06 [debug] 12878#12878: *5 run cleanup: 0000559E68E3B1B0
2023/05/25 18:03:06 [debug] 12878#12878: *5 event timer del: -1: 5605630
2023/05/25 18:03:06 [debug] 12878#12878: *5 free: 0000559E68E3B6E0, unused: 8
2023/05/25 18:03:06 [debug] 12878#12878: *5 free: 0000559E68E3B010, unused: 72
2023/05/25 18:03:06 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B010:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *6 quic recvmsg: 192.168.113.2:51638 fd:60 n:116
2023/05/25 18:03:06 [debug] 12878#12878: posix_memalign: 0000559E68E3B6E0:512 @16
2023/05/25 18:03:06 [debug] 12878#12878: *6 http3 init session
2023/05/25 18:03:06 [debug] 12878#12878: *6 add cleanup: 0000559E68E3B8C8
2023/05/25 18:03:06 [debug] 12878#12878: *6 event timer add: 60: 60000:5605630
2023/05/25 18:03:06 [debug] 12878#12878: *6 quic run
2023/05/25 18:03:06 [debug] 12878#12878: *6 quic packet rx short flags:42
2023/05/25 18:03:06 [debug] 12878#12878: *6 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:06 [debug] 12878#12878: *6 quic handle stateless reset output
2023/05/25 18:03:06 [debug] 12878#12878: *6 quic stateless reset token d27471517c4892e2957d3a7ff4d306c6
2023/05/25 18:03:06 [debug] 12878#12878: *6 sendmsg: 154 of 154
2023/05/25 18:03:06 [debug] 12878#12878: *6 quic packet done rc:-5 level:app decr:0 pn:0 perr:0
2023/05/25 18:03:06 [debug] 12878#12878: *6 quic packet rejected rc:-4, cleanup connection
2023/05/25 18:03:06 [debug] 12878#12878: *6 reusable connection: 0
2023/05/25 18:03:06 [debug] 12878#12878: *6 run cleanup: 0000559E68E3B8C8
2023/05/25 18:03:06 [debug] 12878#12878: *6 event timer del: -1: 5605630
2023/05/25 18:03:06 [debug] 12878#12878: *6 free: 0000559E68E3B010, unused: 13
2023/05/25 18:03:06 [debug] 12878#12878: *6 free: 0000559E68E3B6E0, unused: 0
2023/05/25 18:03:07 [debug] 12878#12878: quic recvmsg on 0.0.0.0:443, ready: 0
2023/05/25 18:03:07 [debug] 12878#12878: posix_memalign: 0000559E68E3B6E0:512 @16
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic recvmsg: 192.168.113.2:51638 fd:60 n:127
2023/05/25 18:03:07 [debug] 12878#12878: posix_memalign: 0000559E68E3B010:512 @16
2023/05/25 18:03:07 [debug] 12878#12878: *7 http3 init session
2023/05/25 18:03:07 [debug] 12878#12878: *7 add cleanup: 0000559E68E3B1F8
2023/05/25 18:03:07 [debug] 12878#12878: *7 event timer add: 60: 60000:5605938
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic run
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic packet rx long flags:e3 version:1
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic packet rx hs len:78
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic packet rx dcid len:20 0000000000002003d1df8f4829b6b6bbf9db70a6
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic packet rx scid len:20 9cc632e6927ad9eac5f1a74063b5bc0b6866ac33
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic expected initial, got handshake
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic packet done rc:-1 level:hs decr:0 pn:0 perr:0
2023/05/25 18:03:07 [debug] 12878#12878: *7 quic packet rejected rc:-1, cleanup connection
2023/05/25 18:03:07 [debug] 12878#12878: *7 reusable connection: 0
2023/05/25 18:03:07 [debug] 12878#12878: *7 run cleanup: 0000559E68E3B1F8
2023/05/25 18:03:07 [debug] 12878#12878: *7 event timer del: -1: 5605938
2023/05/25 18:03:07 [debug] 12878#12878: *7 free: 0000559E68E3B6E0, unused: 2
2023/05/25 18:03:07 [debug] 12878#12878: *7 free: 0000559E68E3B010, unused: 0

The log od CURL IS:

  • Connect socket 5 over QUIC to 46.28.24.113:443
  • Sent QUIC client Initial, ALPN: h3,h3-29,h3-28,h3-27
  • Skipped certificate verification
  • Connected to xxxxxxx port 443 (#0)
  • Connected to xxxxxxx port 443 (#0)
  • h2h3 [:method: HEAD]
  • h2h3 [:path: /]
  • h2h3 [:scheme: https]
  • h2h3 [:authority: avapa.hextra.dev]
  • h2h3 [user-agent: curl/7.87.0-DEV]
  • h2h3 [accept: */*]
  • Using HTTP/3 Stream ID: 0 (easy handle 0xaaaaefd99870)

    HEAD / HTTP/3
    Host: avapa.hextra.dev
    user-agent: curl/7.87.0-DEV
    accept: */*

comment:3 by Roman Arutyunyan, 9 months ago

I see a decryption problem in openssl while using compat layer. Did you build nginx from source? If so, could you please rebuild it with more packet debugging and post the log again. I need the following macros enabled:

--with-cc-opt="-DNGX_QUIC_DEBUG_PACKETS -DNGX_QUIC_DEBUG_FRAMES -DNGX_QUIC_DEBUG_CRYPTO"

TLS packet content will appear in the log. If you don't want to post it here, you can send the log directly to my email arut@….

Also, there's a (probably) unrelated problem with trailing zeroes in packets, which we'd like to debug as well. The macros will help with that too.

comment:4 by Roman Arutyunyan, 9 months ago

We have managed to reproduce the issue. If you build nginx from source, the attached patch should fix the problem.

by Roman Arutyunyan, 9 months ago

Attachment: quic-compat-level added

comment:5 by Roman Arutyunyan <arut@…>, 9 months ago

In 9118:b4a57278bf24/nginx:

QUIC: fixed compat with ciphers other than AES128 (ticket #2500).

Previously, rec.level field was not uninitialized in SSL_provide_quic_data().
As a result, its value was always ssl_encryption_initial. Later in
ngx_quic_ciphers() such level resulted in resetting the cipher to
TLS1_3_CK_AES_128_GCM_SHA256 and using AES128 to encrypt the packet.

Now the level is initialized and the right cipher is used.

comment:6 by i81b4u@…, 9 months ago

I experience the same problems and although the initial error does not show up anymore after applying the quic-compat-level patch, the results are the same. I only get http/2 connections.

One thing I noticed (pre and post patch) is that https://http3check.net/ reports that QUIC and HTTP/3 is supported? And yes, the nginx-logs do show success. I also used other sites to test like https://domsignal.com/http3-test but these tests fail.

Collected debug logs after compiling nginx (which includes the quic-compat-level patch) with:

--with-cc-opt="-DNGX_QUIC_DEBUG_PACKETS -DNGX_QUIC_DEBUG_FRAMES -DNGX_QUIC_DEBUG_CRYPTO"

Happy to share, just tell me where to drop them.

in reply to:  6 comment:7 by f2d@…, 9 months ago

Replying to i81b4u@…:

I experience the same problems and although the initial error does not show up anymore after applying the quic-compat-level patch, the results are the same. I only get http/2 connections.

One thing I noticed (pre and post patch) is that https://http3check.net/ reports that QUIC and HTTP/3 is supported? And yes, the nginx-logs do show success. I also used other sites to test like https://domsignal.com/http3-test but these tests fail.

The patch does help fix the error of this ticket, and HTTP/3.0 (h3) works in newest browsers for me.

What you need is probably fix your configuration, for example try adding "add_header Alt-Svc (...)".

See examples in:
https://nginx.org/en/docs/quic.html
https://nginx.org/en/docs/http/ngx_http_v3_module.html

Those examples put header in "location" blocks, but for me it also works directly alongside "listen" directives.

comment:8 by zhanhb@…, 9 months ago

The access log says that the request made by wget/http3check.net is HTTP/1.1 rather than HTTP/3.

I'm not sure if http3check.net checks http3 request actually.

Nginx version: 1.25.0 from official mainline repository for centos8.

Last edited 9 months ago by zhanhb@… (previous) (diff)

comment:9 by Roman Arutyunyan, 7 months ago

Resolution: fixed
Status: newclosed
Note: See TracTickets for help on using tickets.