Não foi possível descobrir o tempo limite NGINX / Puma 110: a conexão expirou

Question

De vez em quando, meu servidor rails para de responder. Eu crio os logs e não há nada - apenas um monte de pedidos que começaram a começar depois que o último foi concluído ...

Usando

• Ubuntu
• Puma 2.15.3
• Ruby 2.2.1p85
• NGINX 1.4.6
• Supervisor (para servidor running & respawning rails & sidekiq)

Registros de trilhos ...

Completed 200 OK in 179ms (Views: 6.2ms | ActiveRecord: 165.7ms)
Started OPTIONS "/api/v2/users/me" for 209.217.218.34 at 2015-12-16 21:43:47 +0000
Started OPTIONS "/api/v2/users/me" for 209.217.218.34 at 2015-12-16 21:44:21 +0000
Started GET "/" for 209.217.218.34 at 2015-12-16 21:45:11 +0000
Started GET "/" for 209.217.218.34 at 2015-12-16 21:45:27 +0000
Started GET "/" for 209.217.218.34 at 2015-12-16 21:48:13 +0000
Started OPTIONS "/api/v2/users/me" for 209.217.218.34 at 2015-12-16 21:49:19 +0000
Started GET "/" for 209.217.218.34 at 2015-12-16 22:11:58 +0000

Os registros do NGINX mostram o tempo de espera aparente ao ler o cabeçalho da resposta

2015/12/16 21:48:43 [error] 1129#0: *1777 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 209.217.218.34, server: example.com, request: "GET / HTTP/1.1", upstream: "http://unix:/example_site/shared/tmp/sockets/puma.staging.sock/", host: "example.com"
2015/12/16 21:49:49 [error] 1129#0: *1783 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 209.217.218.34, server: example.com, request: "OPTIONS /api/v2/users/me HTTP/1.1", upstream: "http://unix:/example_site/shared/tmp/sockets/puma.staging.sock/api/v2/users/me", host: "example.com", referrer: "http://example.com/"
2015/12/16 22:12:28 [error] 1129#0: *1785 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 209.217.218.34, server: example.com, request: "GET / HTTP/1.1", upstream: "http://unix:/example_site/shared/tmp/sockets/puma.staging.sock/", host: "example.com"

O proxy do servidor NGINX passa para um servidor puma, que tem 2 trabalhadores e 8 threads.

Eu executei um comando strace em um dos threads. E vi isso ...

[pid 32463] futex(0x7f0314c27a78, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000042>
[pid 32463] clock_gettime(CLOCK_MONOTONIC, {454145, 535389460}) = 0 <0.000034>
[pid 32463] write(16, "p32428\n", 7)    = 7 <0.000036>
[pid 32463] clock_gettime(CLOCK_MONOTONIC, {454145, 535541983}) = 0 <0.000013>
[pid 32463] clock_gettime(CLOCK_MONOTONIC, {454145, 535578664}) = 0 <0.000012>
[pid 32463] futex(0x7f0314c27a04, FUTEX_WAIT_BITSET_PRIVATE, 5195, {454150, 535578664}, ffffffff <unfinished ...>
[pid 32471] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) <1.000163>
[pid 32471] futex(0x7f03148dc858, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000010>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454146, 119592840}) = 0 <0.000005>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454146, 119637474}) = 0 <0.000006>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454146, 119655894}) = 0 <0.000005>
[pid 32471] futex(0x7f03148dc7e4, FUTEX_WAIT_BITSET_PRIVATE, 25969, {454147, 119655894}, ffffffff <unfinished ...>
[pid 32470] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) <1.000142>
[pid 32470] futex(0x7f0314dc94d8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454146, 531287803}) = 0 <0.000006>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454146, 531415055}) = 0 <0.000049>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454146, 531502589}) = 0 <0.000037>
[pid 32470] futex(0x7f0314dc9464, FUTEX_WAIT_BITSET_PRIVATE, 25969, {454147, 531502589}, ffffffff <unfinished ...>
[pid 32471] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) <1.000166>
[pid 32471] futex(0x7f03148dc858, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000009>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454147, 119925263}) = 0 <0.000005>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454147, 119965172}) = 0 <0.000014>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454147, 119996627}) = 0 <0.000005>
[pid 32471] futex(0x7f03148dc7e4, FUTEX_WAIT_BITSET_PRIVATE, 25971, {454148, 119996627}, ffffffff <unfinished ...>
[pid 32470] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) <1.000142>
[pid 32470] futex(0x7f0314dc94d8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000046>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454147, 531936925}) = 0 <0.000033>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454147, 532077784}) = 0 <0.000042>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454147, 532160473}) = 0 <0.000036>
[pid 32470] futex(0x7f0314dc9464, FUTEX_WAIT_BITSET_PRIVATE, 25971, {454148, 532160473}, ffffffff <unfinished ...>
[pid 32471] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) <1.000143>
[pid 32471] futex(0x7f03148dc858, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000010>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454148, 120250641}) = 0 <0.000004>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454148, 120296848}) = 0 <0.000014>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454148, 120329244}) = 0 <0.000005>
[pid 32471] futex(0x7f03148dc7e4, FUTEX_WAIT_BITSET_PRIVATE, 25973, {454149, 120329244}, ffffffff <unfinished ...>
[pid 32470] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) <1.000130>
[pid 32470] futex(0x7f0314dc94d8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000010>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454148, 532433899}) = 0 <0.000005>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454148, 532527808}) = 0 <0.000015>
[pid 32470] clock_gettime(CLOCK_MONOTONIC, {454148, 532562815}) = 0 <0.000006>
[pid 32470] futex(0x7f0314dc9464, FUTEX_WAIT_BITSET_PRIVATE, 25973, {454149, 532562815}, ffffffff <unfinished ...>
[pid 32471] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) <1.000163>
[pid 32471] futex(0x7f03148dc858, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454149, 120641924}) = 0 <0.000006>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454149, 120692457}) = 0 <0.000010>
[pid 32471] clock_gettime(CLOCK_MONOTONIC, {454149, 120715154}) = 0 <0.000005>
[pid 32471] futex(0x7f03148dc7e4, FUTEX_WAIT_BITSET_PRIVATE, 25975, {454150, 120715154}, ffffffff <unfinished ...>
[pid 32470] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) <1.000141>
[pid 32470] futex(0x7f0314dc94d8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000009>

nginx.conf

user ubuntu;
worker_processes auto;
pid /run/nginx.pid;

env PATH;

events {
  worker_connections 768;
}

http {
  sendfile on;
  tcp_nopush on;
  tcp_nodelay on;
  keepalive_timeout 70;
  types_hash_max_size 2048;    

  ssl_session_cache   shared:SSL:10m;
  ssl_session_timeout 10m;

  include /etc/nginx/mime.types;
  default_type application/octet-stream;

  access_log /var/log/nginx/access.log;
  error_log /var/log/nginx/error.log;

  gzip on;
  gzip_disable "msie6";

  include /etc/nginx/conf.d/*.conf;
  include /etc/nginx/sites-enabled/*;
}

site.conf

upstream app {
  server unix:/example_site/shared/tmp/sockets/puma.production.sock fail_timeout=0;
}

server {
  listen 80;
  listen 443 ssl;

  sendfile off;

  server_name example.com;

  ssl_certificate /etc/nginx/ssl/example.com.crt;
  ssl_certificate_key /etc/nginx/ssl/example.com.key;
  ssl_protocols  TLSv1 TLSv1.1 TLSv1.2;  # don’t use SSLv3 ref: POODLE

  root /example_site/current/public;

  try_files $uri/index.html $uri @app;

  location @app {
    proxy_set_header X-Forwarded-Proto $scheme;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header Host $http_host;
    proxy_read_timeout 30;
    proxy_connect_timeout 60;
    proxy_redirect off;
    proxy_pass http://app;
  }

  error_page 500 502 503 504 /500.html;
  client_max_body_size 4G;
  keepalive_timeout 10;
}

Eu sou incrivelmente novo em usar strace e não tenho certeza do que estou vendo aqui e se isso é valioso para resolver o problema.

Alguém tem alguma idéia sobre o que está acontecendo e o que mais posso fazer para descobrir o que os tempos limite estão acontecendo?

    

Answer 1

O erro nginx que você está vendo é do nginx fechando a conexão porque demorou muito ou o servidor upstream não está aceitando conexões como deveria ou seu proxy não está encaminhando determinados cabeçalhos que seu servidor upstream precisa para o conexão.

Sem ver seu bloco de proxy e configurações relacionadas para o nginx, veja algumas coisas rápidas a serem verificadas.

Coisas rápidas que você pode fazer:

• Confirme seu keepalive_timeout em /etc/nginx/nginx.conf.
• Adicione uma entrada de arquivo de hosts para o seu servidor upstream em sua caixa local e certifique-se de que cada conexão seja concluída e não tenha tempo limite.
• Verifique se você está encaminhando os cabeçalhos corretos no proxy nginx para o seu servidor upstream.

Aqui está o link para as diretivas de aprovação de proxy para nginx: Nginx http_proxy_module

Atualização:

Tente executar nginx -t e veja se ele informa se há algo errado com a sua configuração, porque uma coisa que se destaca agora que eu dei uma segunda olhada é a keepalive_timeout tentar alterar sua keepalive_timeout 70; para keepalive_timeout 70s;

    

Answer 2

Se o seu proxy nginx e seu servidor puma estiverem em dispositivos diferentes, você realmente vai querer tirar algumas capturas de pacotes usando o tcpdump e examiná-los no wireshark para descobrir o que está acontecendo. Se o nginx não fizer algo como One Connect a fazer pool de conexão, então você pode começar a ter problemas com pouco como 2 usuários simultâneos - mas você só pode realmente suportar um máximo de 4 com isso configuração . Um tcpdump confirmará que esse é o problema, permitindo que você conte o número de apertos de mão de 3 vias e veja a 9ª reinicialização.

Longa história curta - tente aumentar o número de trabalhadores e tópicos.