nginx proxy_pass eventually returns GATEWAY_TIMEOUT even though server is still active
I have set up a nginx proxy passthrough which works fine when nginx initially loads up, but eventually (maybe after a day or so?, not too sure at this point) the location that is a proxy passthrough only returns a 504 GATEWAY_TIMEOUT response. The odd thing is that I have set up multiple proxy_pass locations and it is random what goes down and what stays up.
Here is the nginx config file:
server {
listen 80;
server_name example.com;
access_log /var/log/nginx/access.log;
error_log /var/log/nginx/error.log;
root /srv/www/frontend/current/;
location / {
try_files $uri $uri/ /index.html;
}
# Block all svn access
if ($request_uri ~* ^.*\.svn.*$) {
return 404;
}
# Block all git access
if ($request_uri ~* ^.*\.git.*$) {
return 404;
}
location /nginx_status {
stub_status on;
access_log off;
allow 127.0.0.1;
deny all;
}
location /api/karma/ {
proxy_pass <server A>;
}
location /api/auth/ {
proxy_pass <server B>;
}
location /api/search/ {
proxy_pass <server C>;
}
location /api/history/ {
proxy_pass <server D>;
}
}
(I've anonymized the server locations obviously)
So for example, when nginx initially starts up, I can do
curl -i example.com/api/history/health_check
(where health_check is a known end-point) and get a 200 response, but after a while, the same exact command returns 504 GATEWAY_TIMEOUT.
The underlying server and http server are still fully operational though and I can do curl commands directly against the server's address and get responses both from my local machine and when sshed into the nginx server.
The location prefix that starts returning a GATEWAY_TIMEOUT is random, and ever since it has been setup each of the four locations that have proxy_pass have failed in this fashion at one point or another.
Everything is hosted on AWS t2_micro Ubuntu 14.04 Linux instances and nginx itself is v1.4.6. The underlying servers/applications are not being restarted, and the AWS instances themselves have been up the whole time as well. The underlying http servers are Go applications, but again, when I start getting these GATEWAY_TIMEOUTs, the applications themselves are fully operational.
There was nothing interesting in the error logs when this happens, but I've just turned on debug logging on the error log, and here is what comes up for a broken request:
2015/07/13 19:56:31 [debug] 3523#0: *12096 post event 00000000022542A0
2015/07/13 19:56:31 [debug] 3523#0: *12096 delete posted event 00000000022542A0
2015/07/13 19:56:31 [debug] 3523#0: *12096 http wait request handler
2015/07/13 19:56:31 [debug] 3523#0: *12096 posix_memalign: 000000000222F6A0:256 @16
2015/07/13 19:56:31 [debug] 3523#0: *12096 malloc: 0000000002225CA0:1024
2015/07/13 19:56:31 [debug] 3523#0: *12096 recv: fd:23 1018 of 1024
2015/07/13 19:56:31 [debug] 3523#0: *12096 reusable connection: 0
2015/07/13 19:56:31 [debug] 3523#0: *12096 posix_memalign: 00000000022260B0:4096 @16
2015/07/13 19:56:31 [debug] 3523#0: *12096 http process request line
2015/07/13 19:56:31 [debug] 3523#0: *12096 http request line: "POST <url> HTTP/1.1"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http uri: "<url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http args: ""
2015/07/13 19:56:31 [debug] 3523#0: *12096 http exten: ""
2015/07/13 19:56:31 [debug] 3523#0: *12096 http process request header line
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "host: <url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Accept: application/json, text/plain, */*"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Accept-Encoding: gzip, deflate"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Accept-Language: en-US,en;q=0.8"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Authorization: <auth token>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Content-Type: application/json;charset=UTF-8"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Origin: <url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Referer: <url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.132 Safari/537.36"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "X-Forwarded-For: <ip address>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "X-Forwarded-Port: 443"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "X-Forwarded-Proto: https"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Content-Length: 209"
2015/07/13 19:56:31 [debug] 3523#0: *12096 posix_memalign: 00000000022270C0:4096 @16
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header: "Connection: keep-alive"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http header done
2015/07/13 19:56:31 [debug] 3523#0: *12096 event timer del: 23: 1436817428740
2015/07/13 19:56:31 [debug] 3523#0: *12096 generic phase: 0
2015/07/13 19:56:31 [debug] 3523#0: *12096 rewrite phase: 1
** snip ( bunch of logs about trying to match the url to a route )
2015/07/13 19:56:31 [debug] 3523#0: *12096 http cl:209 max:4194304
2015/07/13 19:56:31 [debug] 3523#0: *12096 rewrite phase: 3
2015/07/13 19:56:31 [debug] 3523#0: *12096 post rewrite phase: 4
2015/07/13 19:56:31 [debug] 3523#0: *12096 generic phase: 5
2015/07/13 19:56:31 [debug] 3523#0: *12096 generic phase: 6
2015/07/13 19:56:31 [debug] 3523#0: *12096 generic phase: 7
2015/07/13 19:56:31 [debug] 3523#0: *12096 access phase: 8
2015/07/13 19:56:31 [debug] 3523#0: *12096 access phase: 9
2015/07/13 19:56:31 [debug] 3523#0: *12096 post access phase: 10
2015/07/13 19:56:31 [debug] 3523#0: *12096 try files phase: 11
2015/07/13 19:56:31 [debug] 3523#0: *12096 http client request body preread 209
2015/07/13 19:56:31 [debug] 3523#0: *12096 http request body content length filter
2015/07/13 19:56:31 [debug] 3523#0: *12096 http body new buf t:1 f:0 0000000002225FC9, pos 0000000002225FC9, size: 209 file: 0, size: 0
2015/07/13 19:56:31 [debug] 3523#0: *12096 http init upstream, client timer: 0
2015/07/13 19:56:31 [debug] 3523#0: *12096 epoll add event: fd:23 op:3 ev:80000005
2015/07/13 19:56:31 [debug] 3523#0: *12096 http script copy: "Host: "
2015/07/13 19:56:31 [debug] 3523#0: *12096 http script var: "<aws url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http script copy: "
"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http script copy: "Connection: close
"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http script copy: "Content-Length: "
2015/07/13 19:56:31 [debug] 3523#0: *12096 http script var: "209"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http script copy: "
"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Accept: application/json, text/plain, */*"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Accept-Encoding: gzip, deflate"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Accept-Language: en-US,en;q=0.8"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Authorization: <auth>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Content-Type: application/json;charset=UTF-8"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Origin: <url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Referer: <url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.132 Safari/537.36"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "X-Forwarded-For: 96.45.202.230"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "X-Forwarded-Port: 443"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "X-Forwarded-Proto: https"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header:
"POST /v1/trip HTTP/1.0
Host: <url>
Connection: close
Content-Length: 209
Accept: application/json, text/plain, */*
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.8
Authorization: <auth>
Content-Type: application/json;charset=UTF-8
Origin: <url>
Referer: <url>
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.132 Safari/537.36
X-Forwarded-For: 96.45.202.230
X-Forwarded-Port: 443
X-Forwarded-Proto: https
"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http cleanup add: 0000000002227C40
2015/07/13 19:56:31 [debug] 3523#0: *12096 get rr peer, try: 2
2015/07/13 19:56:31 [debug] 3523#0: *12096 get rr peer, current: 1 0
2015/07/13 19:56:31 [debug] 3523#0: *12096 socket 24
2015/07/13 19:56:31 [debug] 3523#0: *12096 epoll add connection: fd:24 ev:80000005
2015/07/13 19:56:31 [debug] 3523#0: *12096 connect to 54.174.36.245:80, fd:24 #12097
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream connect: -2
2015/07/13 19:56:31 [debug] 3523#0: *12096 posix_memalign: 000000000222F7B0:128 @16
2015/07/13 19:56:31 [debug] 3523#0: *12096 event timer add: 24: 60000:1436817451902
2015/07/13 19:56:31 [debug] 3523#0: *12096 http finalize request: -4, "<url>" a:1, c:2
2015/07/13 19:56:31 [debug] 3523#0: *12096 http request count:2 blk:0
2015/07/13 19:56:31 [debug] 3523#0: *12096 post event 000000000226E2B0
2015/07/13 19:56:31 [debug] 3523#0: *12096 delete posted event 000000000226E2B0
2015/07/13 19:56:31 [debug] 3523#0: *12096 http run request: "<url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream check client, write event:1, "<url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream recv(): -1 (11: Resource temporarily unavailable)
2015/07/13 19:56:31 [debug] 3523#0: post event 0000000002253E90
2015/07/13 19:56:31 [debug] 3523#0: delete posted event 0000000002253E90
2015/07/13 19:56:31 [debug] 3523#0: accept on 0.0.0.0:80, ready: 0
2015/07/13 19:56:31 [debug] 3523#0: posix_memalign: 000000000222F840:256 @16
2015/07/13 19:56:31 [debug] 3523#0: *12098 accept: 172.31.15.160 fd:25
2015/07/13 19:56:31 [debug] 3523#0: *12098 event timer add: 25: 60000:1436817451902
2015/07/13 19:56:31 [debug] 3523#0: *12098 reusable connection: 1
2015/07/13 19:56:31 [debug] 3523#0: *12098 epoll add event: fd:25 op:1 ev:80000001
2015/07/13 19:56:31 [debug] 3523#0: post event 0000000002253E90
2015/07/13 19:56:31 [debug] 3523#0: delete posted event 0000000002253E90
2015/07/13 19:56:31 [debug] 3523#0: accept on 0.0.0.0:80, ready: 0
2015/07/13 19:56:31 [debug] 3523#0: posix_memalign: 000000000222F950:256 @16
2015/07/13 19:56:31 [debug] 3523#0: *12099 accept: 172.31.15.160 fd:26
2015/07/13 19:56:31 [debug] 3523#0: *12099 event timer add: 26: 60000:1436817451902
2015/07/13 19:56:31 [debug] 3523#0: *12099 reusable connection: 1
2015/07/13 19:56:31 [debug] 3523#0: *12099 epoll add event: fd:26 op:1 ev:80000001
2015/07/13 19:56:31 [debug] 3523#0: *12096 post event 000000000226E040
2015/07/13 19:56:31 [debug] 3523#0: *12096 delete posted event 000000000226E040
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream request: "<url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream send request handler
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream send request
2015/07/13 19:56:31 [debug] 3523#0: *12096 chain writer buf fl:0 s:830
2015/07/13 19:56:31 [debug] 3523#0: *12096 chain writer buf fl:1 s:209
2015/07/13 19:56:31 [debug] 3523#0: *12096 chain writer in: 0000000002227C98
2015/07/13 19:56:31 [debug] 3523#0: *12096 writev: 1039
2015/07/13 19:56:31 [debug] 3523#0: *12096 chain writer out: 0000000000000000
2015/07/13 19:56:31 [debug] 3523#0: *12096 event timer del: 24: 1436817451902
2015/07/13 19:56:31 [debug] 3523#0: *12096 event timer add: 24: 60000:1436817451904
2015/07/13 19:56:31 [debug] 3523#0: *12096 post event 0000000002254030
2015/07/13 19:56:31 [debug] 3523#0: *12096 post event 000000000226E040
2015/07/13 19:56:31 [debug] 3523#0: *12096 delete posted event 000000000226E040
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream request: "<url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream dummy handler
2015/07/13 19:56:31 [debug] 3523#0: *12096 delete posted event 0000000002254030
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream request: "<url>"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream process header
2015/07/13 19:56:31 [debug] 3523#0: *12096 malloc: 00000000022280D0:4096
2015/07/13 19:56:31 [debug] 3523#0: *12096 recv: fd:24 141 of 4096
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy status 200 "200 OK"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Content-Type: text/plain"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Date: Mon, 13 Jul 2015 19:56:31 GMT"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Server: nginx/1.6.2"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Content-Length: 0"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header: "Connection: Close"
2015/07/13 19:56:31 [debug] 3523#0: *12096 http proxy header done
2015/07/13 19:56:31 [debug] 3523#0: *12096 xslt filter header
2015/07/13 19:56:31 [debug] 3523#0: *12096 HTTP/1.1 200 OK
Server: nginx/1.4.6 (Ubuntu)
Date: Mon, 13 Jul 2015 19:56:31 GMT
Content-Type: text/plain
Content-Length: 0
Connection: keep-alive
The interesting line (to me) is:
2015/07/13 19:56:31 [debug] 3523#0: *12096 http upstream recv(): -1 (11: Resource temporarily unavailable)
I tried looking up that string in Google but to be honest I don't really understand the answers and they don't seem related to the issue I am having either way.
Solution 1:
The bottle neck is probably in your t2_micro number of file descriptors, but there is also a high likelihood of it being a network bandwidth issue.
There are two generic ways to fix this problem without increasing bandwidth: 1) Increase the limit (number) of open files system wide and/or ulimit for nginx 2) Upgrade to nginx 1.7.5 or higher
If increasing file descriptors doesn't resolve the issue, keep in mind the t2_micro is generically a low network bandwidth product. Though you might not be able to get 'better' network performance, you can try for a 'more accurate' proxy response health_check that minimizes the t2_micro weaknesses, utilizing a couple of tweaks:
- Buffering is on by default, so confirm the default path specified in
proxy_temp_pathexists and has sufficient disk space, because if it doesn't, buffered messages might sporadically be empty or missed and create a timeout condition awaiting the response. - You'll need version 1.7.5 or higher to adjust
proxy_next_upstream_timeoutandproxy_next_upstream_triesto have nginx handle proxy requests 'more intelligently' on a low bandwidth server. For instance, you can define a number of retries before passing an error.
UPDATE: To configure the number of proxy tries before an error in version 1.7.5 and higher, add this entry to nginx.conf:
proxy_next_upstream_tries 3;
This will give you two retries (one try, plus two retries).
Solution 2:
Add this to nginx.conf :
proxy_connect_timeout 600;
proxy_send_timeout 600;
proxy_read_timeout 600;
send_timeout 600;
Then do 'service nginx reload' ( 'systemctl nginx reload' if you're using systemd )