Re: Пустая переменная $upstream status при 499

2020-01-14 Пенетрантность Maxim Dounin 
Hello!

On Mon, Jan 13, 2020 at 03:07:20PM -0500, yanda.a wrote:

> Maxim Dounin Wrote:
> ---
> > Hello!
> > 
> > Где-то тут общение с бекендом завершено, однако ответ ещё не 
> > полностью отправлен клиенту.  В процессе отправки клиенте 
> > закрывает HTTP/2 stream:
> Кстати да, я немного не досмотрел. В этом server {} не используется listen
> http2. Но, в логах наблюдается именно http/2.0 и в хроме видно h2 в консоли
> разработчика. Не могли бы вы подсказать, насколько это адекватно? 

Параметры директивы listen - это параметры listen-сокета, и они 
применяются ко всем соединениям, использующим данный listen-сокет.  

Соответственно если у вас написано в одном сервере:

listen 443 ssl http2;

а в другом

listen 443;

то для соединений, принятых на порту 443 будет использоваться SSL 
и HTTP/2.

Нюанс - сейчас одном сервере можно написать

listen 443 ssl http2;

а в другом

listen 443 ssl;

то есть без "http2", и будет работать так же, как если бы 
параметров не было написано вообще - то есть будет использоваться 
и SSL, и HTTP/2.  Это, безусловно, вводит в заблуждение, и такое 
мы, видимо, в ближайшем будущем просто запретим.

[...]

> Постараюсь описать ситуацию. Мы пытаемся выгружать эти логи в clickhouse для
> анализа latency и работы бекендов в целом, и сбора разнообразной статистики.
> Для этого на выходе у нас ожидается, что переменные (после парсинга это
> массивы в нашем случае) $upstream_addr, $upstream_response_time и
> $upstream_status имеют одну длину. Но, как показала практика, это не всегда
> так. В связи с этим ещё один, вероятно последний, вопрос. Есть ли
> возможность сделать это поведение более предсказуемым? Или проще добавлять
> недостающие элементы массива в процессе обработки (по сути угадывая, что там
> должно быть)?

Элемент массива там есть, в соответствующей позиции $upstream_status указан "-".

-- 
Maxim Dounin
http://mdounin.ru/
___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2020-01-13 Пенетрантность yanda.a 
Maxim Dounin Wrote:
---
> Hello!
> 
> Где-то тут общение с бекендом завершено, однако ответ ещё не 
> полностью отправлен клиенту.  В процессе отправки клиенте 
> закрывает HTTP/2 stream:
Кстати да, я немного не досмотрел. В этом server {} не используется listen
http2. Но, в логах наблюдается именно http/2.0 и в хроме видно h2 в консоли
разработчика. Не могли бы вы подсказать, насколько это адекватно? 

> При этом в функции ngx_http_terminate_request(), которая обновляет 
> статус запроса тогда и только тогда, когда статус либо ещё не 
> стоит, либо клиенту вообще ничего не было отправлено.  В данном 
> случае, видимо, за счёт использования HTTP/2 случается ситуация, 
> когда клиенту вообще ничего не отправлено (вероятно, за счёт 
> других данных в соединении), и статус таки обновляется на 499.
> 
> Ситуация с $upstream_status "-", видимо, получается похожим 
> образом: если в процессе работы с бекендом клиент отменяет HTTP/2 
> stream, то у соответствующей этому stream'у структуре соединения 
> будет проставлен флаг c->error.  И если после этого случается 
> timeout бекенда, то в ngx_http_upstream_next() nginx, увидев 
> стоящий флаг c->error, не пойдёт на следующий бекенд, а вместо 
> этого завершит обработку запроса с кодом 499.
> 
> То есть я был неправ, получить в логах 499 при использовании 
> proxy_ignore_client_abort таки можно, хотя и непросто.  В простых 
> случаях это в основном затрагивает HTTP/2, но и в HTTP/1.x можно 
> получить похожее поведение, например, при использовании 
> подзапросов.
> 
> На практике при использовании proxy_ignore_client_abort это 
> означает, что работа с бекендом завершена или не начиналась.
> 
> Возвращаясь к исходному вопросу: да, текущее поведение выглядит 
> нормально.

Постараюсь описать ситуацию. Мы пытаемся выгружать эти логи в clickhouse для
анализа latency и работы бекендов в целом, и сбора разнообразной статистики.
Для этого на выходе у нас ожидается, что переменные (после парсинга это
массивы в нашем случае) $upstream_addr, $upstream_response_time и
$upstream_status имеют одну длину. Но, как показала практика, это не всегда
так. В связи с этим ещё один, вероятно последний, вопрос. Есть ли
возможность сделать это поведение более предсказуемым? Или проще добавлять
недостающие элементы массива в процессе обработки (по сути угадывая, что там
должно быть)?

Posted at Nginx Forum: 
https://forum.nginx.org/read.php?21,286606,286718#msg-286718

___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2020-01-13 Пенетрантность Maxim Dounin 
Hello!

On Mon, Jan 13, 2020 at 09:39:29AM -0500, yanda.a wrote:

> Да, конечно, единственное что - изменю доменное имя, если вы не против.

Ок, так понятно, что происходит:

> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http write filter 
> 7FF7599D8E48
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip in: 
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http copy filter: -2 
> "/api/epg?from=1578862800=1578949199"
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 pipe write downstream done
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 event timer: 92, old: 
> 7043363034, new: 7043363039
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 event timer: 78, old: 
> 704034, new: 704039
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http upstream exit: 
> 
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 finalize http upstream 
> request: 0
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 finalize http proxy request
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 free rr peer 2 0
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 close http upstream 
> connection: 92

Где-то тут общение с бекендом завершено, однако ответ ещё не 
полностью отправлен клиенту.  В процессе отправки клиенте 
закрывает HTTP/2 stream:

> 2020/01/13 02:28:13 [info] 17855#17855: *29319057 client canceled stream 39 
> while sending to client, client: 176.59.97.91, server: mydomain.info, 
> request: "GET /api/epg?from=1578862800=1578949199 HTTP/2.0", upstream: 
> "http://192.168.50.48:8081/api/epg?from=1578862800=1578949199;, 
> host:"www.mydomain.info", referrer: "https://www.mydomain.info/;

И дальше зовётся ngx_http_test_reading(), который и финализирует 
соединение с кодом 499:

> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http run request: 
> "/api/epg?from=1578862800=1578949199"
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http test reading
> 2020/01/13 02:28:13 [info] 17855#17855: *29319057 client prematurely closed 
> connection while sending to client, client: 176.59.97.91, server: 
> mydomain.info, request: "GET /api/epg?from=1578862800=1578949199 
> HTTP/2.0", upstream: " 
> http://192.168.50.48:8081/api/epg?from=1578862800=1578949199;, host: 
> "www.mydomain.info", referrer: "https://www.mydomain.info/;
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http finalize request: 
> 499, "/api/epg?from=1578862800=1578949199" a:1, c:1
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http terminate request 
> count:1
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http terminate cleanup 
> count:1 blk:0

При этом в функции ngx_http_terminate_request(), которая обновляет 
статус запроса тогда и только тогда, когда статус либо ещё не 
стоит, либо клиенту вообще ничего не было отправлено.  В данном 
случае, видимо, за счёт использования HTTP/2 случается ситуация, 
когда клиенту вообще ничего не отправлено (вероятно, за счёт 
других данных в соединении), и статус таки обновляется на 499.

Ситуация с $upstream_status "-", видимо, получается похожим 
образом: если в процессе работы с бекендом клиент отменяет HTTP/2 
stream, то у соответствующей этому stream'у структуре соединения 
будет проставлен флаг c->error.  И если после этого случается 
timeout бекенда, то в ngx_http_upstream_next() nginx, увидев 
стоящий флаг c->error, не пойдёт на следующий бекенд, а вместо 
этого завершит обработку запроса с кодом 499.

То есть я был неправ, получить в логах 499 при использовании 
proxy_ignore_client_abort таки можно, хотя и непросто.  В простых 
случаях это в основном затрагивает HTTP/2, но и в HTTP/1.x можно 
получить похожее поведение, например, при использовании 
подзапросов.

На практике при использовании proxy_ignore_client_abort это 
означает, что работа с бекендом завершена или не начиналась.

Возвращаясь к исходному вопросу: да, текущее поведение выглядит 
нормально.

-- 
Maxim Dounin
http://mdounin.ru/
___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2020-01-13 Пенетрантность yanda.a 
Да, конечно, единственное что - изменю доменное имя, если вы не против.
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http write filter
7FF7599D8E48
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip in:

2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http copy filter: -2
"/api/epg?from=1578862800=1578949199"
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 pipe write downstream
done
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 event timer: 92, old:
7043363034, new: 7043363039
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 event timer: 78, old:
704034, new: 704039
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http upstream exit:

2020/01/13 02:28:13 [debug] 17855#17855: *29319057 finalize http upstream
request: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 finalize http proxy
request
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 free rr peer 2 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 close http upstream
connection: 92
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 free: 7FF752049F80,
unused: 48
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 event timer del: 92:
7043363034
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 reusable connection: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http upstream temp fd:
-1
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http output filter
"/api/epg?from=1578862800=1578949199"
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http copy filter:
"/api/epg?from=1578862800=1578949199"
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http postpone filter
"/api/epg?from=1578862800=1578949199" 7FFD9965DD50
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http gzip filter
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip in:
7FF7599D8738
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip
in_buf:7FF759A96318 ni: ai:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 deflate in:
ni: no:7FF759ADF752 ai:0 ao:14510 fl:4 redo:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 deflate out:
ni: no:7FF759AE3000 ai:0 ao:0 rc:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip
in_buf:7FF759A96318 pos:
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 malloc:
7FF759F2F000:32768
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 deflate in:
ni: no:7FF759F2F000 ai:0 ao:32768 fl:4 redo:1
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 deflate out:
ni: no:7FF759F30319 ai:0 ao:27879 rc:1
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip
in_buf:7FF759A96318 pos:
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 free: 7FF759857000
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF759B58000, pos 7FF759B5FFF6, size: 10 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF75AB19000, pos 7FF75AB19000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF75F8F7000, pos 7FF75F8F7000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF7599F3000, pos 7FF7599F3000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF759A2, pos 7FF759A2, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF759A8E000, pos 7FF759A8E000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write new buf t:1 f:0
7FF759ADB000, pos 7FF759ADB000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write new buf t:1 f:0
7FF759F2F000, pos 7FF759F2F000, size: 4897 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http write filter: l:1
f:1 s:201515
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http write filter limit
262144
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 windows:
conn:11893020 stream:6029312
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A96418: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A96500: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A965E8: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A966D0: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A96808: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A968F0: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A969D8: len:8192 flags:0

Re: Пустая переменная $upstream status при 499

2020-01-13 Пенетрантность yanda.a 
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http write filter
7FF7599D8E48
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip in:

2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http copy filter: -2
"/api/epg?from=1578862800=1578949199"
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 pipe write downstream
done
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 event timer: 92, old:
7043363034, new: 7043363039
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 event timer: 78, old:
704034, new: 704039
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http upstream exit:

2020/01/13 02:28:13 [debug] 17855#17855: *29319057 finalize http upstream
request: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 finalize http proxy
request
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 free rr peer 2 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 close http upstream
connection: 92
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 free: 7FF752049F80,
unused: 48
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 event timer del: 92:
7043363034
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 reusable connection: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http upstream temp fd:
-1
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http output filter
"/api/epg?from=1578862800=1578949199"
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http copy filter:
"/api/epg?from=1578862800=1578949199"
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http postpone filter
"/api/epg?from=1578862800=1578949199" 7FFD9965DD50
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http gzip filter
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip in:
7FF7599D8738
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip
in_buf:7FF759A96318 ni: ai:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 deflate in:
ni: no:7FF759ADF752 ai:0 ao:14510 fl:4 redo:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 deflate out:
ni: no:7FF759AE3000 ai:0 ao:0 rc:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip
in_buf:7FF759A96318 pos:
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 malloc:
7FF759F2F000:32768
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 deflate in:
ni: no:7FF759F2F000 ai:0 ao:32768 fl:4 redo:1
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 deflate out:
ni: no:7FF759F30319 ai:0 ao:27879 rc:1
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip
in_buf:7FF759A96318 pos:
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 free: 7FF759857000
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF759B58000, pos 7FF759B5FFF6, size: 10 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF75AB19000, pos 7FF75AB19000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF75F8F7000, pos 7FF75F8F7000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF7599F3000, pos 7FF7599F3000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF759A2, pos 7FF759A2, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write old buf t:1 f:0
7FF759A8E000, pos 7FF759A8E000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write new buf t:1 f:0
7FF759ADB000, pos 7FF759ADB000, size: 32768 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 write new buf t:1 f:0
7FF759F2F000, pos 7FF759F2F000, size: 4897 file: 0, size: 0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http write filter: l:1
f:1 s:201515
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http write filter limit
262144
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 windows:
conn:11893020 stream:6029312
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A96418: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A96500: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A965E8: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A966D0: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A96808: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A968F0: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame 7FF759A969D8: len:8192 flags:0
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http2:39 create DATA
frame

Re: Пустая переменная $upstream status при 499

2020-01-13 Пенетрантность Maxim Dounin 
Hello!

On Mon, Jan 13, 2020 at 04:46:22AM -0500, yanda.a wrote:

> Maxim Dounin Wrote:
> ---
> > Hello!
> > 
> > On Mon, Dec 30, 2019 at 03:22:01AM -0500, yanda.a wrote:
> > 
> > > Добрался до конфигурации, скину почти полную конфигурацию:
> > 
> > [...]
> > 
> > Смысла в "почти полной" конфигурации не очень много.  Нужна 
> > конфигурация, с которой воспроизводится то, на что вы жалуетесь.
> > 
> > Попробуйте воспроизвести проблемное поведение в песочнице, с 
> > использованием минимальной конфигурации.  Скорее всего в процессе 
> > станет понятно, в чём именно проблема.
> 
> Думаю, что смысла в конфигурации в принципе нет, если я все понял верно.

Нет, вы не всё поняли верно.  Вы приводите код из функции 
ngx_http_upstream_check_broken_connection(), который не может 
быть вызван, если в конфигурации сказано 
proxy_ignore_client_abort.

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

> Дело в том, что на текущей конфигурации мне никак не удалось воспроизвести
> это поведение в тестовом окружении. От безысходности пришлось включить дебаг
> и искать сообщения из логов в исходниках.
> 
> Например, вот что есть в логах:
> 2020/01/13 02:28:13 [info] 17855#17855: *29319057 client prematurely closed
> connection while sending to client, client: 176.59.97.91 
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http finalize request:
> 499, "/api/epg?from=1578862800=1578949199" a:1, c:1

Покажите debug log для соединения *29319057 плюс-минус хотя бы 
пару десятков строк от "client prematurely closed", и по 
возможности без купюр.  Возможно что-то станет понятнее.

-- 
Maxim Dounin
http://mdounin.ru/
___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2020-01-13 Пенетрантность yanda.a 
Maxim Dounin Wrote:
---
> Hello!
> 
> On Mon, Dec 30, 2019 at 03:22:01AM -0500, yanda.a wrote:
> 
> > Добрался до конфигурации, скину почти полную конфигурацию:
> 
> [...]
> 
> Смысла в "почти полной" конфигурации не очень много.  Нужна 
> конфигурация, с которой воспроизводится то, на что вы жалуетесь.
> 
> Попробуйте воспроизвести проблемное поведение в песочнице, с 
> использованием минимальной конфигурации.  Скорее всего в процессе 
> станет понятно, в чём именно проблема.
> 
> -- 
> Maxim Dounin
> http://mdounin.ru/
> ___
> nginx-ru mailing list
> nginx-ru@nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx-ru


Думаю, что смысла в конфигурации в принципе нет, если я все понял верно.
Дело в том, что на текущей конфигурации мне никак не удалось воспроизвести
это поведение в тестовом окружении. От безысходности пришлось включить дебаг
и искать сообщения из логов в исходниках.

Например, вот что есть в логах:
2020/01/13 02:28:13 [info] 17855#17855: *29319057 client prematurely closed
connection while sending to client, client: 176.59.97.91 
2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http finalize request:
499, "/api/epg?from=1578862800=1578949199" a:1, c:1

И вот как это выглядит в логах:
request_time:   1.6401
bytes_sent: 0
status: 499
upstream_addr:  ['backend-01-1']
upstream_status:[200]
upstream_response_time: [1.225]

То есть, мы получили ответ от бекенда, но не смогли по какой-то причине
отдать клиенту (это уже другая история). Но, соединение с бекендом мы уже
закрыли! А теперь смотрим исходники:

if (!u->cacheable && u->peer.connection) {
ngx_log_error(NGX_LOG_INFO, ev->log, err,
  "client prematurely closed connection, "
  "so upstream connection is closed too");
ngx_http_upstream_finalize_request(r, u,
   NGX_HTTP_CLIENT_CLOSED_REQUEST);
return;
}

ngx_log_error(NGX_LOG_INFO, ev->log, err,
  "client prematurely closed connection");

if (u->peer.connection == NULL) {
ngx_http_upstream_finalize_request(r, u,
   NGX_HTTP_CLIENT_CLOSED_REQUEST);
}

У нас peer.connection == NULL, так как мы уже получили ответ и закрыли
соединение с бекендом.

К сожалению, запросы с лагающим бекендом пока не удалось отловить в логах.
Но, надеюсь они появятся в обозримом будущем и удастся что-то найти.

Posted at Nginx Forum: 
https://forum.nginx.org/read.php?21,286606,286711#msg-286711

___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2019-12-31 Пенетрантность Maxim Dounin 
Hello!

On Mon, Dec 30, 2019 at 03:22:01AM -0500, yanda.a wrote:

> Добрался до конфигурации, скину почти полную конфигурацию:

[...]

Смысла в "почти полной" конфигурации не очень много.  Нужна 
конфигурация, с которой воспроизводится то, на что вы жалуетесь.

Попробуйте воспроизвести проблемное поведение в песочнице, с 
использованием минимальной конфигурации.  Скорее всего в процессе 
станет понятно, в чём именно проблема.

-- 
Maxim Dounin
http://mdounin.ru/
___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2019-12-30 Пенетрантность yanda.a 
Добрался до конфигурации, скину почти полную конфигурацию:

load_module
"/usr/lib64/nginx/modules/ngx_http_geoip_module.so";
load_module
"/usr/lib64/nginx/modules/ndk_http_module.so";
load_module
"/usr/lib64/nginx/modules/ngx_http_lua_module.so";
load_module
"/usr/lib64/nginx/modules/ngx_http_brotli_filter_module.so";
load_module
"/usr/lib64/nginx/modules/ngx_http_brotli_static_module.so";

usernginx   nginx;
worker_rlimit_nofile245760;
worker_processes24;
worker_priority -10;
worker_cpu_affinity auto
;

pid /var/run/nginx.pid;

pcre_jiton;

thread_pool local_pool  threads=8;  
   # Pool for local filesystem
thread_pool nfs_poolthreads=8;  
   # Pool for NFS-share

events {
worker_connections  10240;
use epoll;
multi_accepton;
accept_mutexoff;
}

http {
include mime.types;
default_typeapplication/octet-stream;

log_format  jsonescape=json 
   '{'
'"request_id":"$request_id",'
'"remote_addr":"$remote_addr",'
'"http_host":"$http_host",'
'"server_name":"$server_name",'
'"domain_tags":"$domain_tags",'
'"ssl_auth":"$ssl_client_verify",'
'"ssl_cn":"$ssl_client_s_dn",'
'"timestamp":"$time_local",'
'"status":"$status",'
'"request_time":"$request_time",'
'"upstream_name":"$upstream_name",' #
custom variable
'"upstream_status":"$upstream_status",'
'"upstream_queue_time":"$upstream_response_time",'
'"upstream_connect_time":"$upstream_response_time",'
'"upstream_header_time":"$upstream_response_time",'
'"upstream_response_time":"$upstream_response_time",'
'"upstream_cache_status":"$upstream_cache_status",'
'"upstream_addr":"$upstream_addr",'
'"request_method":"$request_method",'
'"request_uri":"$request_uri",'
'"protocol":"$server_protocol",'
'"bytes_received":"$request_length",'
'"bytes_sent":"$body_bytes_sent",'
'"referer":"$http_referer",'
'"user_agent":"$http_user_agent",'
'"x_requested_with":"$http_x_requested_with",'
'"scheme":"$scheme"'
'}';

access_log 
syslog:server=unix:/dev/log,tag=access_log,facility=local6  json;
error_log  
syslog:server=unix:/dev/log,tag=error_log,facility=local7   warn;

# Disk read settings
sendfileon;
sendfile_max_chunk  256k;
aio threads=local_pool;
aio_write   on;
directio4m; # this is disabled
in location where are used files from NFS-share
output_buffers  1   2m;
read_ahead  512k;   # ignored in Linux

# Buffers
large_client_header_buffers 4 32k;
client_body_buffer_size 128k;

# TCP-socket settings
keepalive_timeout   15  15;
keepalive_requests  1000;
tcp_nopush  on;
tcp_nodelay on;
reset_timedout_connection   on;

# Internal memory structures
open_file_cache max=100
inactive=40s;
open_file_cache_valid   60s;
open_file_cache_min_uses2;
open_file_cache_errors  on;
open_log_file_cache max=500 inactive=30m   
valid=10m   min_uses=1;
variables_hash_max_size 2048;
variables_hash_bucket_size  128;
server_names_hash_max_size  1024;
server_names_hash_bucket_size   128;

Re: Пустая переменная $upstream status при 499

2019-12-27 Пенетрантность Maxim Dounin 
Hello!

On Fri, Dec 27, 2019 at 10:03:51AM -0500, yanda.a wrote:

> Maxim Dounin Wrote:
> ---
> > Hello!
> > 
> > При "proxy_ignore_client_abort on;" статуса 499 быть вообще не 
> > должно. 
> > 
> > Что показывает "nginx -V" и что в конфиге?
> > 
> > -- 
> > Maxim Dounin
> > http://mdounin.ru/
> > ___
> > nginx-ru mailing list
> > nginx-ru@nginx.org
> > http://mailman.nginx.org/mailman/listinfo/nginx-ru
> 
> nginx version: nginx/1.16.1
> built by gcc 4.8.5 20150623 (Red Hat 4.8.5-16) (GCC) 
> built with OpenSSL 1.1.1d  10 Sep 2019
> TLS SNI support enabled
> configure arguments: --sbin-path=/usr/sbin/nginx
> --modules-path=/usr/lib64/nginx/modules --prefix=/etc/nginx
> --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log
> --http-log-path=/var/log/nginx/log/nginx/access.log
> --http-client-body-temp-path=/var/tmp/nginx/client_body
> --http-proxy-temp-path=/var/tmp/nginx/proxy
> --http-fastcgi-temp-path=/var/tmp/nginx/fastcgi
> --http-uwsgi-temp-path=/var/tmp/nginx/uwsgi
> --http-scgi-temp-path=/var/tmp/nginx/scgi --pid-path=/run/nginx.pid
> --lock-path=/run/lock/subsys/nginx --user=nginx --group=nginx --with-compat
> --with-file-aio --with-ipv6 --with-http_addition_module
> --with-http_auth_request_module --with-http_dav_module
> --with-http_degradation_module --with-http_flv_module
> --with-http_geoip_module=dynamic --with-http_gunzip_module
> --with-http_gzip_static_module --with-http_image_filter_module=dynamic
> --with-http_mp4_module --with-http_perl_module=dynamic
> --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_xslt_module=dynamic --with-mail=dynamic
> --with-mail_ssl_module --with-pcre --with-pcre-jit --with-stream=dynamic
> --with-stream_realip_module --with-stream_ssl_module
> --with-stream_ssl_preread_module
> --with-openssl=../third_party/openssl-1.1.1d
> --with-openssl-opt=enable-tls1_3 --with-threads
> --add-dynamic-module=modules/ngx_brotli
> --add-dynamic-module=modules/xss-nginx-module-0.06
> --add-dynamic-module=modules/naxsi-0.56
> --add-dynamic-module=modules/incubator-pagespeed-ngx-1.13.35.2-stable
> --add-dynamic-module=modules/lua-nginx-module-0.10.15
> --add-dynamic-module=modules/ngx_devel_kit-0.3.1 --with-cc-opt='-O2 -g -pipe
> -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong
> --param=ssp-buffer-size=4 -grecord-gcc-switches
> -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -m64 -mtune=generic -fPIC'
> --with-ld-opt='-Wl,-z,relro -Wl,-z,now -pie -Wl,-rpath,/usr/lib64
> -ljemalloc'
> 
> Что именно нужно из конфига? Просто он очень большой, не думаю что это
> хорошая идея

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

daemon off;
master_process on;
error_log stderr info;

worker_processes 1;

events {
worker_connections 1024;
}


http {
log_format test  "status: $status\n"
 "upstream_addr: $upstream_addr\n"
 "upstream_status: $upstream_status";

access_log /dev/stderr test;
 
upstream u {
   server 127.0.0.1:8081;
   server 127.0.0.1:8082;
}

server {
listen 8080;

location / {
proxy_pass http://u;
proxy_ignore_client_abort on;
proxy_read_timeout 3s;
}
}

server {
listen 8081;
listen 8082;
delay 5s;
access_log off;
}
}

(Директива delay - от ngx_http_delay_module, 
http://mdounin.ru/hg/ngx_http_delay_module/, вместо неё можно 
использовать любой бекенд, который отвечает долго.)

Делаем запрос и сбрасываем соединение:

$ curl -k "http://127.0.0.1:8080/foo;
^C

На выходе получаем:

status: 504
upstream_addr: 127.0.0.1:8081, 127.0.0.1:8082
upstream_status: 504, 504

-- 
Maxim Dounin
http://mdounin.ru/
___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2019-12-27 Пенетрантность yanda.a 
Предварительно, могу показать как оно проксируется, не знаю хватит ли
этого:
http {
proxy_http_version  1.1;
proxy_redirect  off;
proxy_intercept_errors  on;
proxy_next_upstream error timeout invalid_header
http_500 http_502 http_503 http_504;
proxy_connect_timeout   90;
proxy_send_timeout  90;
proxy_read_timeout  90;
proxy_buffering on;
proxy_buffer_size   64k;
proxy_buffers   128 128k;
proxy_busy_buffers_size 128k;
proxy_temp_file_write_size  128k;
proxy_ignore_headersSet-Cookie;
proxy_hide_header   X-Powered-By;
proxy_ignore_client_abort   on;
proxy_temp_path
/var/tmp/nginx/vhosts_proxy_temp;

server {
...

location / {
try_files   $uri   
@proxy_upstream;
}

location ~ \.php$ {
proxy_pass 
http://$httpd_upstream;

proxy_set_headerConnection  
   "";
proxy_set_headerHost
   $host;
proxy_set_headerX-Real-IP   
   $remote_addr;
proxy_set_headerX-Forwarded-For 
   $remote_addr;
proxy_set_headerX-Forwarded-Port
   $server_port;
proxy_set_headerX-Forwarded-Proto   
   $scheme;
proxy_set_headerX-Forwarded-Server  
   $server_addr;
proxy_set_headerX-Url-Scheme
   $scheme;
}

location @proxy_upstream {
proxy_pass 
http://$httpd_upstream;

proxy_set_headerConnection  
   "";
proxy_set_headerHost
   $host;
proxy_set_headerX-Real-IP   
   $remote_addr;
proxy_set_headerX-Forwarded-For 
   $remote_addr;
proxy_set_headerX-Forwarded-Port
   $server_port;
proxy_set_headerX-Forwarded-Proto   
   $scheme;
proxy_set_headerX-Forwarded-Server  
   $server_addr;
proxy_set_headerX-Url-Scheme
   $scheme;
}
}

map $remote_addr $httpd {
default httpd;
}

upstream httpd {
server  backend-01-1:8081  max_fails=5;
server  backend-01-2:8081  max_fails=5;
}
}

Posted at Nginx Forum: 
https://forum.nginx.org/read.php?21,286606,286610#msg-286610

___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2019-12-27 Пенетрантность yanda.a 
Maxim Dounin Wrote:
---
> Hello!
> 
> При "proxy_ignore_client_abort on;" статуса 499 быть вообще не 
> должно. 
> 
> Что показывает "nginx -V" и что в конфиге?
> 
> -- 
> Maxim Dounin
> http://mdounin.ru/
> ___
> nginx-ru mailing list
> nginx-ru@nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx-ru

nginx version: nginx/1.16.1
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-16) (GCC) 
built with OpenSSL 1.1.1d  10 Sep 2019
TLS SNI support enabled
configure arguments: --sbin-path=/usr/sbin/nginx
--modules-path=/usr/lib64/nginx/modules --prefix=/etc/nginx
--conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log
--http-log-path=/var/log/nginx/log/nginx/access.log
--http-client-body-temp-path=/var/tmp/nginx/client_body
--http-proxy-temp-path=/var/tmp/nginx/proxy
--http-fastcgi-temp-path=/var/tmp/nginx/fastcgi
--http-uwsgi-temp-path=/var/tmp/nginx/uwsgi
--http-scgi-temp-path=/var/tmp/nginx/scgi --pid-path=/run/nginx.pid
--lock-path=/run/lock/subsys/nginx --user=nginx --group=nginx --with-compat
--with-file-aio --with-ipv6 --with-http_addition_module
--with-http_auth_request_module --with-http_dav_module
--with-http_degradation_module --with-http_flv_module
--with-http_geoip_module=dynamic --with-http_gunzip_module
--with-http_gzip_static_module --with-http_image_filter_module=dynamic
--with-http_mp4_module --with-http_perl_module=dynamic
--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_xslt_module=dynamic --with-mail=dynamic
--with-mail_ssl_module --with-pcre --with-pcre-jit --with-stream=dynamic
--with-stream_realip_module --with-stream_ssl_module
--with-stream_ssl_preread_module
--with-openssl=../third_party/openssl-1.1.1d
--with-openssl-opt=enable-tls1_3 --with-threads
--add-dynamic-module=modules/ngx_brotli
--add-dynamic-module=modules/xss-nginx-module-0.06
--add-dynamic-module=modules/naxsi-0.56
--add-dynamic-module=modules/incubator-pagespeed-ngx-1.13.35.2-stable
--add-dynamic-module=modules/lua-nginx-module-0.10.15
--add-dynamic-module=modules/ngx_devel_kit-0.3.1 --with-cc-opt='-O2 -g -pipe
-Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong
--param=ssp-buffer-size=4 -grecord-gcc-switches
-specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -m64 -mtune=generic -fPIC'
--with-ld-opt='-Wl,-z,relro -Wl,-z,now -pie -Wl,-rpath,/usr/lib64
-ljemalloc'

Что именно нужно из конфига? Просто он очень большой, не думаю что это
хорошая идея

Posted at Nginx Forum: 
https://forum.nginx.org/read.php?21,286606,286609#msg-286609

___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Re: Пустая переменная $upstream status при 499

2019-12-27 Пенетрантность Maxim Dounin 
Hello!

On Thu, Dec 26, 2019 at 02:20:37PM -0500, yanda.a wrote:

> Есть upstream с несколькими серверами. На этом upstream'е бывают очень
> долгие запросы (это уже другая история). Если клиент разорвал соединение, в
> логах будет $status = 499, но продолжаем ждать ответа от бекенда (опция
> proxy_ignore_client_abort on), и если бекенд не отвалился по таймауту, то в
> переменную $upstream_status пишется код его ответа. А вот если клиент
> отключился от нас и бекенд отвалился по таймауту, то переменная
> $upstream_status пустая, хотя, должна быть 504 по идее.
> 
> Для сравнения, ситуация с 504 (не кусок из логов, а просто содержимое
> переменных, но это взято из реальных логов, которых нет в сыром виде):
> status: 504
> upstream_addr: backend-01-1,backend-01-2
> upstream_status: 504,504
> upstream_response_time: 90,90
> 
> Ситуация с 499 и таймаутом бекенда:
> status: 499
> upstream_addr: backend-01-1
> upstream_status: -
> upstream_response_time: 90
> 
> Ситуация с 499 и без таймаута бекенда:
> status: 499
> upstream_addr: backend-01-2
> upstream_status: 200
> upstream_response_time: 0.038
> 
> 
> Собственно, вопрос, нормальное ли подобное поведение? Или это больше
> смахивает на баг? Используется версия 1.16.1.

При "proxy_ignore_client_abort on;" статуса 499 быть вообще не 
должно. 

Что показывает "nginx -V" и что в конфиге?

-- 
Maxim Dounin
http://mdounin.ru/
___
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru