Re: "Странные" таймауты при получении ответа от бекенда

[Maxim Dounin]

Hello!

On Thu, Jul 24, 2014 at 05:51:14AM -0400, yanda.a wrote:

> Доброго времени суток!
> 
> С недавних пор стали появляться ошибки upstream timed out (60: Operation
> timed out) while reading response header from upstream.
> Что интересно, они появляются только для определенных клиентов, точнее, для
> определенного клиента - какой-то китайской поисковой системы. Начали
> разбираться с проблемой и наткнулись на еще одну странность.
> 
> Логи nginx для неудачного запроса:

[...]

> 2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy:
> "Content-Length: "
> 2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var: "927"

Запрос - с телом в 927 байт, что в целом для GET-запросов не 
характерно, и может быть причиной того, что проблема наблюдается 
только с конкретным клиентом.

[...]

> 2014/07/22 12:35:11 [debug] 63699#0: *200015 socket 134
> 2014/07/22 12:35:11 [debug] 63699#0: *200015 connect to 127.0.0.1:80, fd:134 #200016

Пошли на первый бекенд.

[...]

> 2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream send request
> 2014/07/22 12:35:11 [debug] 63699#0: *200015 chain writer buf fl:0 s:554
> 2014/07/22 12:35:11 [debug] 63699#0: *200015 chain writer buf fl:0 s:536
> 2014/07/22 12:35:11 [debug] 63699#0: *200015 chain writer buf fl:1 s:391

Запрос полностью отправлен nginx'ом, в том числе 536 + 391 == 927 
байт тела запроса.

[...]

> 2014/07/22 12:36:41 [debug] 63699#0: *200015 event timer del: 134:
> 1406032601648

От бекенда так ничего и не пришло, сработал таймаут.

[...]

> 2014/07/22 12:36:41 [debug] 63699#0: *200015 get keepalive peer
> 2014/07/22 12:36:41 [debug] 63699#0: *200015 get rr peer, try: 1
> 2014/07/22 12:36:41 [debug] 63699#0: *200015 get rr peer, current: 1 0
> 2014/07/22 12:36:41 [debug] 63699#0: *200015 socket 3
> 2014/07/22 12:36:41 [debug] 63699#0: *200015 connect to 94.75.244.108:80,
> fd:3 #204118

Попытались пойти на другой бекенд.

[...]

> 2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream dummy handler
> 2014/07/22 12:38:11 [debug] 63699#0: *200015 event timer del: 3:
> 1406032691650
> 2014/07/22 12:38:11 [debug] 63699#0: *200015 http upstream request:
> "/download/driver/AZTECH+MDP_3858SP-WE.html?"

Снова не дождались ответа, опять сработал таймаут.

[...]

> В 12:35:11 отправили запрос бекенду, а через полторы минуты вывалились по
> таймауту. Все бы ничего, если бы не логи самого бекенда:
> 183.60.213.30 - - [22/Jul/2014:12:36:41 +0000] "GET
> /download/driver/AZTECH+MDP_3858SP-WE.html HTTP/1.1" 200 4953 0/45331 "-"
> "Mozilla/5.0 (compatible; EasouSpider;
> +http://www.easou.com/search/spider.html)"

Вероятно, это лог с первого из бекендов, и время 12:36:41 
намекает, что обработка запроса начилась только в тот момент, 
когда nginx разорвал соединение по таймауту.

> Бекенд получил и обработал этот запрос как раз в тот момент, когда nginx
> разрывает соединение. Обработка запроса заняла 45331 us. То есть, как
> такового таймаута быть не должно, бекенд моментально обработал этот запрос.
> Так вот, непонятно, куда все таки попал этот http-запрос и почему он попал к
> бекенду при срабатывании таймаута nginx'а.
> 
> Кто-нибудь сталкивался с подобным? Есть ли мысли о причинах подобного
> поведения?

Запрос с телом и обработка, начинающаяся только при разрыве 
соединения - поведение, характерное для ошибок, связанных с 
чтением тела запроса.  Бекенд по каким-то причинам считает, что 
должно быть больше данных, и ждёт их - пока соединение не закроют. 

При этом каких-либо проблем с отправляемым nginx'ом телом, судя по 
debug log'у, нет, так что имеет смысл смотреть в первую очередь на 
бекенд.

-- 
Maxim Dounin
http://nginx.org/