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/ _______________________________________________ nginx-ru mailing list [email protected] http://mailman.nginx.org/mailman/listinfo/nginx-ru
