QUIC: err_quic_protocol_error

Lafiel · January 21, 2024, 4:18pm

После переход с Nginx 1.25.3 с поддержкой протокола QUIC на Angie 1.4.0 начал замечать, что в логах периодически возникает ошибка загрузки файлов - ERR_QUIC_PROTOCOL_ERROR. На Nginx ошибок не возникает, перепроверил.
В debug логе режим проблематично отследить момент возникновения ошибки, слишком много событий, а в браузере нет точных меток времени для возможности определить местоположение.
В позапрошлом году сталкивался с аналогичной проблемой на стороне Nginx, помогло увеличение параметра keepalive_requests. Сейчас стоит высокой значение keepalive_requests, но проблему не решает.

Удалось поймать в логах нужные события:

В первом логе запрос с ошибкой, второй лог уже запрос прошёл успешно.
Обратил внимание, что при ошибке Angie выдаёт заголовок content-length со значением 1.

Lafiel · January 25, 2024, 6:38am

Нужно ли ещё предоставить дополнительные логи?

vl · January 25, 2024, 10:58am

Добрый день.

Было бы неплохо увидеть подробности из броузера о том, какая конкретно ошибка в QUIIC протоколе произошла, а не общее ‘ERR_QUIC_PROTOCOL_ERROR’.
На стороне сервера надо включить debug log, в том числе общий, а не только для одного виртуального сервера, где будут сообщения про собственно quic.
(см A debugging log)

Также хотелось бы видеть конфигурацию.

Как часто случается проблема? Есть ли какие-то факторы, которые влияют на её появление?

Lafiel · January 25, 2024, 7:31pm

Постарался собрать более полный лог - 2024/01/25 22:01:36 [debug] 30812#30812: *539 add cleanup: 0000680A50473028202 - Pastebin.com
Конфигурация nginx - pid /run/nginx/nginx.pid;error_log /var/data/web/37106/domains/example.com/lo - Pastebin.com
На этот раз ошибка с загрузкой файла 1acad237aa15b33a.png

Проблема проявляется 1-2 раза за несколько часов. В основном проявляется когда более высокая активность в браузере - чаще обновляется домашняя лента в микро-блоге.

VBart · January 26, 2024, 12:33am

В браузере желательно собрать более подробный лог для QUIC соединения: How to capture a NetLog dump
HTTP Logging — Firefox Source Docs documentation

Lafiel · January 26, 2024, 5:14am

NetLog:

vl · January 29, 2024, 11:41am

Похоже на вот этот случай (в нетлоге хрома ошибки 122):

https://mailman.nginx.org/pipermail/nginx-devel/2021-May/014066.html

Ещё я бы попробовал упростить конфигурацию, выключив (временно) треды/aio, и посмотрев, продолжает ли происходить ошибка.

Также хотелось бы понять - случаются ли ошибки по какому-то счётчику (судя по номер 532 в примере до keepalive_requests ещё далеко)

Lafiel · January 29, 2024, 4:11pm

Добрый вечер.
Отключил треды/aio, проблема не исчезла.

vl · January 30, 2024, 9:44am

Хорошо, это исключаем.

В идеале хотелось бы получить минимальный конфиг, который воспроизводит
проблему, а также способ порождения клиентских запросов, который к ней
приводит.

Скажите, вы можете видеть эту проблему просто запрашивая в цикле этот ресурс
при помощи, например curl (с поддержкой HTTP/3) ? Или в браузере?

Если нет, то надо получить полный лог quic/udp соединения с самого начала.

Упрощённо, HTTP/3 работает так: есть некое основное UDP ‘соединение’, внутри
которого бегают независимые стримы: несколько управляющих и стримы запросов.

Как читать логи quic:

найдите ваш запрос, например:

2024/01/29 13:06:29 [debug] 1765202#1765202: *7 http3 request line: “GET /system/ava.png HTTP/3.0”

в данной строке мы видим GET запрос по HTTP/3 протоколу для файла ava.png.

*7 - это номер соединения, назначенный QUIC-стриму запроса.

Найдите момент порождения этого стрима:

2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic stream id:0x0 create
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 posix_memalign: 00005568371BEDF0:512 @16
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 posix_memalign: 00005568371D7560:16384 @16
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 reusable connection: 0
2024/01/29 13:06:29 [debug] 1765202#1765202: *7 add cleanup: 00005568371D7620

…
2024/01/29 13:06:29 [debug] 1765202#1765202: *7 quic init stream

Найдите первое появление соединения *7 перед выводом ‘quic init stream’;
это будет строка ‘add cleanup’, а перед ней строка ‘quic stream id 0x…
create’; В данном пример это соединение *2.

Вот всё это соединение *2 нам и надо проанализировать.
Можно посмотреть, как завершилось quic соединение *2,
т.к. всё относящееся к QUIC протоколу происходит в рамках этого соединения:

Если поискать ‘quic close handler’, то мы увидим начало закрытия этого
соединения.

2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic frame rx app CONNECTION_CLOSE err:0 ft:0
…
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic close handler
…
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic close initiated rc:0 c:00007FD01900F200
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic close immediate term:0 drain:1 error:1 “”

Например, здесь мы видим, что клиент прислал фрейм CONNECTION_CLOSE,
который породил процесс закрытия соединения на сервере; начинают закрываться
все стримы в этом соединении:

…
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic stream id:0x2 cleanup
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic stream id:0x2 close
…
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic stream id:0xa cleanup
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic stream id:0xa close
…

В итоге, соединение закрывается окончательно:
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic close resumed rc:0 c:00007FD01900F200
2024/01/29 13:06:29 [debug] 1765202#1765202: *2 quic close completed

В случае ошибок уровня протокола на сервере, то в дебаг-логе будет какая-нибудь
ошибка. Если же ошибка произошла на клиенте, то он может прислать её описание
в CONNECTION_CLOSE фрейме, с указанием типа фрейм, который её породил.
К сожалению, не всегда клиент присылает описание ошибки, которая, по его
мнению произошла.

Lafiel · January 30, 2024, 11:39am

До вечера попробую по частям отключать некоторые параметры и пронаблюдать, будет ли проявляться ошибка. Потом попробую ещё раз собрать логи.
Можно было бы ещё и на тестовом сервере попробовать воспроизвести ошибку, но я не могу заставить браузер на базе Chrome подключаться по протоколу HTTP/3. На сервере используется само-подписной сертификат, а в браузере он добавлен как доверенный. При этом через curl соединения по HTTP/3 работают. По отладочным логам видно было, что браузер в запросе не указывает, что он поддерживает этот протокол.

vl · January 30, 2024, 12:19pm

вообще хром можно принудить ходить на http/3 опциями коммандной строки:

–origin-to-force-quic-on=localhost:8443 --enable-logging=stderr

Lafiel · January 30, 2024, 5:38pm

Закомментировал эти параметры:

# ssl_session_cache             shared:SSL:64m;
# ssl_session_timeout           10m;
# ssl_buffer_size               16k;
# ssl_early_data                on;
# ssl_prefer_server_ciphers     on;
# ssl_stapling                  on;
# ssl_stapling_verify           on;
# ssl_session_tickets           off;

Пока ошибок не видел, пробую включать по несколько параметров обратно и наблюдать.

Пробовал разные вариации - не помогает, работает по HTTP/2 протоколу. Вместо localhost прописывал домен в локальной сети. При указании 433 порта, на котором у меня запущен QUIC, сайт вообще перестаёт открываться.

Lafiel · January 31, 2024, 7:04am

Вроде бы отключение ssl_early_data устраняет ошибку.

vl · January 31, 2024, 7:23am

А расскажите пожалуйста, у вас nginx и angie - собраны с одинаковым openssl ?
и покажите вывод c -V.

Lafiel · January 31, 2024, 7:45am

Да, одинаковые версии OpenSSL.
Nginx:

nginx version: nginx/1.25.3
built by gcc 13.2.0 (GCC)
built with OpenSSL 3.1.4+quic 24 Oct 2023
TLS SNI support enabled
configure arguments:
--prefix=/nix/store/lz0i4670y4lqb3sv0hpcmra5sk0lcz7m-nginxQuic-1.25.3
--sbin-path=bin/nginx
--with-http_ssl_module
--with-http_v2_module
--with-http_realip_module
--with-http_addition_module
--with-http_xslt_module
--with-http_sub_module
--with-http_dav_module
--with-http_flv_module
--with-http_mp4_module
--with-http_gunzip_module
--with-http_gzip_static_module
--with-http_auth_request_module
--with-http_random_index_module
--with-http_secure_link_module
--with-http_degradation_module
--with-http_stub_status_module
--with-threads
--with-pcre-jit
--http-log-path=/var/log/nginx/access.log
--error-log-path=/var/log/nginx/error.log
--pid-path=/var/log/nginx/nginx.pid
--http-client-body-temp-path=/tmp/nginx_client_body
--http-proxy-temp-path=/tmp/nginx_proxy
--http-fastcgi-temp-path=/tmp/nginx_fastcgi
--http-uwsgi-temp-path=/tmp/nginx_uwsgi
--http-scgi-temp-path=/tmp/nginx_scgi
--with-openssl-opt=enable-ktls
--with-stream
--with-stream_realip_module
--with-stream_ssl_module
--with-stream_ssl_preread_module
--with-http_image_filter_module
--with-http_geoip_module
--with-stream_geoip_module
--with-file-aio
--with-http_v3_module
--add-module=/nix/store/eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee-rtmp
--add-module=/nix/store/eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee-dav
--add-module=/nix/store/eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee-moreheaders

Angie:

Angie version: Angie/1.4.0
built by gcc 13.2.0 (GCC)
built with OpenSSL 3.1.4+quic 24 Oct 2023
TLS SNI support enabled
configure arguments:
--prefix=/nix/store/9bmjxkyrq0f5gmz4a8y7kphx77bg6syf-angieQuic-1.4.0
--sbin-path=bin/nginx
--with-http_ssl_module
--with-http_v2_module
--with-http_realip_module
--with-http_addition_module
--with-http_xslt_module
--with-http_sub_module
--with-http_dav_module
--with-http_flv_module
--with-http_mp4_module
--with-http_gunzip_module
--with-http_gzip_static_module
--with-http_auth_request_module
--with-http_random_index_module
--with-http_secure_link_module
--with-http_degradation_module
--with-http_stub_status_module
--with-threads
--with-pcre-jit
--http-log-path=/var/log/nginx/access.log
--error-log-path=/var/log/nginx/error.log
--pid-path=/var/log/nginx/nginx.pid
--http-client-body-temp-path=/tmp/nginx_client_body
--http-proxy-temp-path=/tmp/nginx_proxy
--http-fastcgi-temp-path=/tmp/nginx_fastcgi
--http-uwsgi-temp-path=/tmp/nginx_uwsgi
--http-scgi-temp-path=/tmp/nginx_scgi
--with-openssl-opt=enable-ktls
--with-stream
--with-stream_realip_module
--with-stream_ssl_module
--with-stream_ssl_preread_module
--with-http_image_filter_module
--with-http_geoip_module
--with-stream_geoip_module
--with-file-aio
--with-http_v3_module
--add-module=/nix/store/eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee-rtmp
--add-module=/nix/store/eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee-dav
--add-module=/nix/store/eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee-moreheaders

Lafiel · February 2, 2024, 7:23am

Проверил с BoringSSL, проблем не наблюдается, но с ним у меня не работает kTLS.

Lafiel · February 10, 2024, 8:12am

Есть какая-либо вероятность исправления ошибки?
Или лучше подбирать другую SSL библиотеку?

vl · February 12, 2024, 6:37am

Т.е. в итоге ситуация выглядит так:
nginx + openssl + ssl_early_data on - работает нормально
angie + openssl + ssl_early_data on - возникают ошибки
angie +openssl + ssl_early_data off - ошибок нет
angie +boringssl + ssl_early_data on - ошибок нет
правильно?

Lafiel · February 12, 2024, 8:02am

Да, всё верно. Только в boringssl у меня нет поддержки kernel tls, вероятно надо проверять параметры сборки, может не активировано.

vl · February 12, 2024, 9:18am

В случае сборки с openssl, TLS early data не поддерживается, так что опцию можно безболезненно отключить, всё равно от неё нет толку.

см. http://nginx.org/en/docs/quic.html:

An SSL library that provides QUIC support is recommended to build nginx, such as BoringSSL, LibreSSL, or QuicTLS. Otherwise, the OpenSSL compatibility layer will be used that does not support early data.