Re: Не понимаю в чем причина кода ответа 504 с ошибкой Connection timed out

[Алексанр Платонов]

>
>  Это совсем не похоже на таймаут. Возможно, перепутаны коннекции в дампе,
>  проверьте номера портов и tcp seq
>
>  А это похоже на таймаут коннекта. Вопрос в том, почему SYN+ACK от бэкенда
>  пришёл с такой задержкой. Возможно, бэкенд перегружен.
>  Возможно, свитчи по пути перегружены трафиком.


Дампы:
RST: https://ufile.io/09s7w
FIN: https://ufile.io/0bkq5

это вот эти два запроса
2017/06/15 13:12:43 [error] 8449#8449: *729923 upstream timed out (110:
Connection timed out) while connecting to upstream, client: 128.74.129.198,
server: site, request: "GET /api/v1/product/58a2ed54d53f3d224a6b05c5
HTTP/1.1", upstream: "fastcgi://217.69.137.168:8080", host: "api.site"
2017/06/15 13:12:43 [error] 8471#8471: *734373 upstream timed out (110:
Connection timed out) while connecting to upstream, client: 31.173.243.12,
server: site, request: "GET
/api/v1/counters/5730243396ad843510595f43?adv_id=D5D4F8D7-DEB7-4FE0-807E-143651398124&app_id=iphone%2F3782&timestamp=1497521562&uid=uid&usr_latitude=55.0252283782156&usr_longitude=82.93059721079625
HTTP/1.1", upstream: "fastcgi://217.69.137.73:8080", host: "api.site"

rtt порядка 1-2 миллисекунд, таймаут 300 миллисекунд. Время до посылки FIN
и RST это величина до десятков миллисекунд. Я ожидал увидеть RST через ~
300 миллисекунд.
Возможно  с RST это вторая попытка отправить пакет через RTO + некоторое
время, но из debug log nginx я не понял сколько было попыток, вроде одна.
FIN объяснить не могу. Так как запросов мало, примерно один запрос на один
ip:port в секунду, то проблемые сессии легко видны в tcpdump.

Возможно, бэкенд перегружен.
> Возможно, свитчи по пути перегружены трафиком. Бэкенд создал 50% от max
> кол-ва воркеров, там динамический пул. По остальным ресурсам тоже ок.
>
> Сеть на портах загружена на 5-7%, за всю сеть не скажу, но хосты раскиданы
по трем ДЦ ~ хаотично и закономерности я не вижу.
Если бы воспроизводилась в одном месте, то я бы видел максимумы ошибок,
связанные с одним хостом/дц. Ситуация была бы и на других проектах, но пока
такого не замечали.

> > Не понятно почему при настройке nginx fastcgi_connect_timeout 300ms; в
> логе
> > вижу upstream_response_time: 0.677 секунды. Есть этому объяснение?
>
>  Коннект это одно, а ожидание ответа бэкенда ПОСЛЕ завершения коннекта
>  это другое. Можно сконнектиться, послать запрос и долго ждать ответа.
>
> Можно, но это в моем понимание будет уже таймаут на получение ответа после
установления соединения и он равен ~ 2 мин.
Разве в это поле не должен подставиться +- таймаут, ведь код ответа уже
есть?

Александр

15 июня 2017 г., 18:13 пользователь Evgeniy Berdnikov <bgx на protva.ru>
написал:

> On Thu, Jun 15, 2017 at 05:21:38PM +0300, Алексанр Платонов wrote:
> > У меня есть ~30 хостов в 3-х разных ДЦ. Nginx принимает нагрузку и
> > распределяет её по алгоритму WRR на php-fpm пулы, расположенные на этих
> же
> > хостах.
> >
> > Периодически, примерно 1/5000 (ошибка к общему кол-ву запросов)  на
> > случайном хосте получает ошибку:
> > front14 2017/06/15 15:37:40 [error] 13063#13063: *2446289 upstream timed
> > out (110: Connection timed out) while connecting to upstream, client:
> > 217.69.135.0, server: site, request: "GET
> > /files/images/1284_1284/58/b4/58b455be4b559395714059e5.jpg
> > HTTP/1.0", upstream: "fastcgi://217.69.137.52:8081", host: "site"
> >
> > после получения ошибки nginx проксирует запрос на другой сервер и там все
> > отрабатывает нормально.
> >
> > front14 217.69.135.0 - - [15/Jun/2017:15:37:41 +0300] "GET
> > /files/images/1284_1284/58/b4/58b455be4b559395714059e5.jpg HTTP/1.0" 200
> > 139517 "-" "okhttp/3.4.1" "-" request_time: 1.660 upstream_addr:
> > 217.69.137.52:8081, 217.69.137.51:8081 upstream_response_time: 0.677,
> 0.981
> > upstream_status: 504, 200 upstream_cache_status: - "tid:"
> > 13063-1497530259.494-217.69.135.0-163-2446289
> ...
> > Снимал несколько раз tcpdump и наблюдал следующую картину:
> > 1) хост с nginx послылает FIN на бэкенд сразу после своего же ACK бэкенду
> > через 13ms, не пересылая данные вообще.
>
>  Это совсем не похоже на таймаут. Возможно, перепутаны коннекции в дампе,
>  проверьте номера портов и tcp seq
>
>
> > 2) хост с nginx посылает RST через 10 мкс после получения SYN, ACK от
> > бэкенда и через ~ 780 мкс от своего SYN.
>
>  А это похоже на таймаут коннекта. Вопрос в том, почему SYN+ACK от бэкенда
>  пришёл с такой задержкой. Возможно, бэкенд перегружен.
>  Возможно, свитчи по пути перегружены трафиком.
>
> > Не понятно почему при настройке nginx fastcgi_connect_timeout 300ms; в
> логе
> > вижу upstream_response_time: 0.677 секунды. Есть этому объяснение?
>
>  Коннект это одно, а ожидание ответа бэкенда ПОСЛЕ завершения коннекта
>  это другое. Можно сконнектиться, послать запрос и долго ждать ответа.
> --
>  Eugene Berdnikov
> _______________________________________________
> nginx-ru mailing list
> nginx-ru на nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx-ru
>
----------- следущая часть -----------
Вложение в формате HTML было извлечено…
URL: <http://mailman.nginx.org/pipermail/nginx-ru/attachments/20170615/60254e5b/attachment.html>