Context Navigation

← Previous Ticket
Next Ticket →

#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.26
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 11 months ago.

Download all attachments as: .zip

Change History (11)

comment:1 by Roman Arutyunyan, 11 months ago

Could you enable debug logging and post the log?

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

comment:2 by cristianorevil@…, 11 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, 11 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, 11 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, 11 months ago

Attachment:	quic-compat-level added

comment:5 by Roman Arutyunyan <arut@…>, 11 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.

follow-up: 7 comment:6 by i81b4u@…, 11 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@…, 11 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@…, 11 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 11 months ago by zhanhb@… (previous) (diff)

comment:9 by Roman Arutyunyan, 9 months ago

Resolution:	→ fixed
Status:	new → closed

comment:10 by m.herasimovich, 40 hours ago

Milestone:	nginx-1.25 → nginx-1.26

Milestone renamed

Note: See TracTickets for help on using tickets.

Download in other formats: