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

[Maxim Dounin]

Hello!

On Thu, Jun 22, 2017 at 04:30:39PM +0300, Алексанр Платонов wrote:

> Пожалуйста, новые дампы и логи.
> https://ufile.io/0ony2
> https://ufile.io/bgt1i
> 
> 2017/06/22 15:53:55 [error] 45615#45615: *89748123 upstream timed out (110:
> Connection timed out) while connecting to upstream, client: 176.59.44.27,
> server: server, request: "POST
> /api/events/batch?app_id=311&uid=uid&usr_latitude=55.50582&adv_id=b309f032e4-4516-8950-cc01093bb398&usr_longitude=37.3288475&timestamp=1492954855
> HTTP/1.1", upstream: "fastcgi://217.69.137.58:8086", host: "server"
> 2017/06/22 15:53:55 [error] 45611#45611: *89788909 upstream timed out (110:
> Connection timed out) while connecting to upstream, client: 46.146.189.93,
> server: server, request: "POST
> /api/events/batch?app_id=311&uid=uid&usr_latitude=0.0&adv_id=f341a189-59573f-a520-9c76b003d6c4&usr_longitude=0.0&timestamp=1498136049
> HTTP/1.1", upstream: "fastcgi://217.69.137.35:8086", host: "server"
> 
> Есть идеи почему так может быть?

Судя по тому, что происходит всё в рамках одной миллисекунды:

15:53:51.936803 IP 217.69.137.60.45391 > 217.69.137.58.8086: Flags [S], seq 1264135273, win 14600, options [mss 1460,sackOK,TS val 70412504 ecr 0,nop,wscale 7], length 0
15:53:51.937189 IP 217.69.137.58.8086 > 217.69.137.60.45391: Flags [S.], seq 1137150422, ack 1264135274, win 14480, options [mss 1460,sackOK,TS val 70430564 ecr 70412504,nop,wscale 7], length 0
15:53:51.937194 IP 217.69.137.60.45391 > 217.69.137.58.8086: Flags [R], seq 1264135274, win 0, length 0

15:53:55.846481 IP 217.69.137.60.60107 > 217.69.137.58.8086: Flags [S], seq 694406592, win 14600, options [mss 1460,sackOK,TS val 70416414 ecr 0,nop,wscale 7]
15:53:55.846833 IP 217.69.137.58.8086 > 217.69.137.60.60107: Flags [S.], seq 104810584, ack 694406593, win 14480, options [mss 1460,sackOK,TS val 70434474 ecr
15:53:55.846841 IP 217.69.137.60.60107 > 217.69.137.58.8086: Flags [.], ack 1, win 115, options [nop,nop,TS val 70416414 ecr 70434474], length 0
15:53:55.846938 IP 217.69.137.60.60107 > 217.69.137.58.8086: Flags [F.], seq 1, ack 1, win 115, options [nop,nop,TS val 70416414 ecr 70434474], length 0
15:53:55.847081 IP 217.69.137.58.8086 > 217.69.137.60.60107: Flags [F.], seq 1, ack 2, win 114, options [nop,nop,TS val 70434474 ecr 70416414], length 0
15:53:55.847092 IP 217.69.137.60.60107 > 217.69.137.58.8086: Flags [.], ack 2, win 115, options [nop,nop,TS val 70416414 ecr 70434474], length 0

15:53:55.846491 IP 217.69.137.60.41780 > 217.69.137.35.8086: Flags [S], seq 2302129673, win 14600, options [mss 1460,sackOK,TS val 70416414 ecr 0,nop,wscale 7], length 0
15:53:55.847537 IP 217.69.137.35.8086 > 217.69.137.60.41780: Flags [S.], seq 410704669, ack 2302129674, win 14480, options [mss 1460,sackOK,TS val 4234532892 ecr 70416414,nop,wscale 7], length 0
15:53:55.847543 IP 217.69.137.60.41780 > 217.69.137.35.8086: Flags [R], seq 2302129674, win 0, length 0

и в двух случаях из трёх речь идёт о том, что соединение было 
закрыто раньше, чем установлено (RST в ответ на SYN-ACK).  Это всё 
выглядит как-то совсем подозрительно.  Было бы интересно увидеть 
debug log'и.

Кроме того, я бы рекомендовал посмотреть, что происходит со 
временем на сервере.  Коллеги ранее наблюдали нечто подобное, 
когда время в виртуальной машине с одной стороны выставлялось 
средствами системы виртуализации, а с другой - его пытался править 
timesyncd.  Борьба шла с переменным успехом, и продолжалась долго.  
Стало заметно, когда разница времён превысила минуту, и при каждом 
сдвиге времени вперёд стали срабатывать таймауты в nginx'е.

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