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

[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 00007FF7599D8E48
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 gzip in: 0000000000000000
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http copy filter: -2 "/api/epg?from=1578862800&to=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: 7043333034, new: 7043333039
> 2020/01/13 02:28:13 [debug] 17855#17855: *29319057 http upstream exit: 0000000000000000
> 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&to=1578949199 HTTP/2.0", upstream: "http://192.168.50.48:8081/api/epg?from=1578862800&to=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&to=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&to=1578949199 HTTP/2.0", upstream: " http://192.168.50.48:8081/api/epg?from=1578862800&to=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&to=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/