Назад | Перейти на главную страницу

Невозможно определить время ожидания NGINX / Puma 110: Истекло время ожидания подключения

Время от времени мой сервер rails перестает отвечать. Я просматриваю журналы и ничего не вижу - просто куча запросов, которые начали запускаться после завершения последнего ...

С помощью

Ubuntu
Пума 2.15.3
Рубин 2.2.1p85
NGINX 1.4.6
Супервизор (для запуска / возрождения сервера rails и sidekiq)

Журналы Rails ...

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

Журналы NGINX показывают очевидное время ожидания при чтении заголовка ответа.

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"

Прокси-сервер NGINX переходит к серверу puma, который имеет 2 рабочих и 8 потоков.

Я выполнил команду strace в одном из потоков. И увидел это ...

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

Я невероятно новичок в использовании strace и не совсем уверен, что я здесь просматриваю, и действительно ли это полезно для решения проблемы.

У кого-нибудь есть идеи о том, что происходит, и что еще я могу сделать, чтобы выяснить, какие тайм-ауты происходят?

Ошибка nginx, которую вы видите, связана либо с тем, что nginx закрывает соединение, потому что это заняло слишком много времени, либо вышестоящий сервер не принимает соединения, как должен, либо ваш прокси-сервер не пересылает определенные заголовки, которые нужны вашему вышестоящему серверу для соединения.

Не видя вашего блока прокси и связанных настроек для nginx, вот несколько быстрых вещей, которые нужно проверить.

Что вы можете сделать быстро:

Дважды проверьте свой keepalive_timeout в /etc/nginx/nginx.conf.
Добавьте запись в файл hosts для вашего вышестоящего сервера в локальном ящике и убедитесь, что каждое соединение завершается и не истекает тайм-аут.
Убедитесь, что вы пересылаете правильные заголовки на прокси-сервере nginx обратно на вышестоящий сервер.

Вот ссылка на директивы прохождения прокси для nginx: Nginx http_proxy_module

Обновить:

Попробуйте бежать nginx -t и посмотрите, сообщит ли он вам, что с вашей конфигурацией что-то не так, потому что одна вещь, которая выделяется сейчас, когда я снова смотрю, - это keepalive_timeout попробуйте изменить свой keepalive_timeout 70; к keepalive_timeout 70s;

Если ваш прокси-сервер nginx и ваш сервер puma находятся на разных устройствах, вам действительно захочется захватить несколько пакетов с помощью tcpdump и изучить их в wirehark, чтобы выяснить, что происходит. Если nginx не делает что-то вроде One Connect чтобы сделать пул соединений, тогда у вас могут возникнуть проблемы с всего 2 одновременных пользователя - но вы действительно можете поддерживать максимум 4 с этой конфигурацией. Tcpdump подтвердит, что это проблема, позволяя вам подсчитать количество трехсторонних рукопожатий и увидеть сброс девятого.

Короче говоря - попробуйте увеличить количество рабочих и потоков.