Nginx – Cannot figure out NGINX / Puma timeout 110: Connection timed out

nginxruby-on-railsUbuntu

Every so often, my rails server stops responding. I tail the logs and there is nothing—just a bunch of requests that have begun to start after the last one completed…

Using

  • Ubuntu
  • Puma 2.15.3
  • Ruby 2.2.1p85
  • NGINX 1.4.6
  • Supervisor (for running / respawning rails server & sidekiq)

Rails logs… 

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

The NGINX logs show the apparent timeout happening from reading the response header

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"

The NGINX server proxy passes to a puma server, which has 2 workers and 8 threads.

I ran a strace command on one of the threads. And saw this…

[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;
}

I'm incredibly new to using strace and am not really sure what I'm viewing here and if this is even valuable to solving the problem.

Anyone have any ideas on what's going on and what more I can do to figure out what the timeouts are happening?

Best Answer

The nginx error that you're seeing is from either nginx closing the connection because it took too long or the upstream server is not accepting connections like it should or your proxy isn't forwarding certain headers that your upstream server needs for the connection.

Without seeing your proxy block and related setting for nginx here are some quick things to check.

Quick things you can do:

  • Double check your keepalive_timeout in /etc/nginx/nginx.conf.
  • Add a hosts file entry for your upstream server on your local box and make sure that every connection completes and does not timeout.
  • Make sure that your are forwarding the correct headers on the nginx proxy back to your upstream server.

Here is the link to the proxy pass directives for nginx: Nginx http_proxy_module

Update:

Try running nginx -t and see if it tells you if there is anything wrong with your config because one thing that stands out now that I tooks a second look is the keepalive_timeout try changing your keepalive_timeout 70; to keepalive_timeout 70s;

Related Topic