404 then upstream timeout

Server NGINX
1

Hi all,

I’m running into a strange issue with nginx upstreaming to a varnish
cache.

When I POST to a specific URL with invalid parameters, I want the call
to return a 404.

However, nginx returns 504 after a 60ish second timeout.

I notice in my logs that $upstream_status is returning 2 values “404 :
504”.
$upstream_response_time is “0.026 : 60.000”

If I hit varnish directly, the call returns immediately with the
proper 404 response.

Tracing varnish logs during this call shows that only a single request
is made against, even though $upstream_status seems to be returning 2
values.

Here’s the basic config (salient bits only)

upstream varnish { http://127.0.0.1:2222; }

server {
proxy_redirect false;
proxy_max_temp_file_size 0;
proxy_next_upstream off;
proxy_read_timeout 60;
proxy_intercept_errors on;

error_page 404 /404.html;
error_page 500 /500.html;

location / {
proxy_pass http://varnish;
}
}

This is nginx/0.5.32. Does anyone know why nginx seems to be making 2
calls, when it should only be returning 404 immediately?

Thanks,
eden

2

Can you sniff the traffic between nginx and varnish with ngrep ? What
does it indicate ?

Cheers

Dave

3

I finally got a chance to repro this in a sandboxed environment and
ngrep the local adapter. It appears there might be 2 issues here – 1
with nginx and 1 with varnish.

The config that I tested is:

http {
upstream varnish { server 127.0.0.1:9999; }
server {
listen 8888;
root /files;
error_page 404 /404.html;
location / {
proxy_intercept_errors on;
proxy_pass http://varnish;
}
}
}

Varnish is setup to proxy to a mongrel instance that’s running a
simple rails app.

When I POST to a URL that 404s from mongrel (e.g. /a), I see ngrep
passing the request to nginx, then varnish, then finally hitting
mongrel. Varnish proxies the request back to nginx. The whole time
it looks fine and 404 status code is set correctly. However, after
nginx receives the response, it immediately makes a GET request
against the same URL which then causes the connection to time out.

This change seems to fix things, but it still seems unnecessary.

  • error_page 404 /404.html;
  • error_page 404 @404;
  • location @404 {
  • rewrite .* /404.html last;
  • }

This causes nginx instead requests /404.html as a second request
(instead of the same URI with the method changed to a get) and passes
back the right response without a timeout. Two questions I can’t seem
to answer:

  1. Why does nginx make a second GET request against the backend for
    the URI that was originally posted to?
  2. (maybe not appropriate for this list) Why would varnish timeout on
    this second request from nginx?

Below is the ngrep dump. Does anyone have insight to the above two
issues?

T 127.0.0.1:61133 → 127.0.0.1:8888 [AP]
POST /i HTTP/1.1…User-Agent: curl/7.16.3 (powerpc-apple-darwin9.0)
libcurl/7.16.3 OpenSSL/0.9.7l zlib/1.2.3…Host:
127.0.0.1:8888…Accept: /…Content-Len
gth: 1…Content-Type: application/x-www-form-urlencoded…

T 127.0.0.1:61134 → 127.0.0.1:9999 [AP]
POST /i HTTP/1.0…X-Debug: nginx…Host: varnish…Connection:
close…User-Agent: curl/7.16.3 (powerpc-apple-darwin9.0)
libcurl/7.16.3 OpenSSL/0.9.7l zlib/1.2
.3…Accept: /…Content-Length: 1…Content-Type:
application/x-www-form-urlencoded…

T 127.0.0.1:61135 → 127.0.0.1:3000 [AP]
POST /i HTTP/1.1…X-Debug: nginx…Host: varnish…Connection:
close…User-Agent: curl/7.16.3 (powerpc-apple-darwin9.0)
libcurl/7.16.3 OpenSSL/0.9.7l zlib/1.2
.3…Accept: /…Content-Length: 1…Content-Type:
application/x-www-form-urlencoded…X-Varnish:
1814203833…X-Forwarded-for: 127.0.0.1…

T 127.0.0.1:3000 → 127.0.0.1:61135 [AP]
HTTP/1.1 404 Not Found…Connection: close…

T 127.0.0.1:3000 → 127.0.0.1:61135 [AP]
Date: Wed, 12 Mar 2008 23:58:50 GMT…Status: 404 Page Not
Found…Cache-Control: no-cache…Server: Mongrel 1.1.1…Content-Type:
text/html; charset=utf-8…Con
tent-Length: 616…

T 127.0.0.1:3000 → 127.0.0.1:61135 [AP]

.. Action Controller: Exception caught. . body { background-color: #fff; color: #333; }.. body, p, ol, ul, td {. font-family: verdana, arial, helvetica, sans-serif;. font-size: 13px;. line-height: 18px;. }.. pre {. background-color: #eee;. padding: 10px;. font-size: 11px;. }.. a { color: #000; }. a:visited { color: #666; }. a:hover { color: #fff; background-color:#000; }. ....

Routing Error 127.0.0.1:61135 [AP] h1>.

no route found to match "/i" with
{:method=>:post}

..... #### T 127.0.0.1:9999 -> 127.0.0.1:61134 [AP] HTTP/1.1 404 Not Found..Connection: close..Date: Wed, 12 Mar 2008 23:58:50 GMT..Status: 404 Page Not Found..Cache-Control: no-cache..Server: Mongrel 1.1.1.. Content-Type: text/html; charset=utf-8..Content-Length: 616...... Action Controller: Exception caught. . body { backg round-color: #fff; color: #333; }.. body, p, ol, ul, td {. font-family: verdana, arial, helvetica, sans-serif;. font-size: 13px;. line-h eight: 18px;. }.. pre {. background-color: #eee;. padding: 10px;. font-size: 11px;. }.. a { color: #000; }. a:visited { color: #666; }. a:hover { color: #fff; background-color:#000; }. ....

Routing Error

.

no route found
to match "/i&quot
  ; with {:method=>:post}

..... ########### T 127.0.0.1:61136 -> 127.0.0.1:9999 [AP] GET /i HTTP/1.0..X-Debug: nginx..Host: varnish..Connection: close..User-Agent: curl/7.16.3 (powerpc-apple-darwin9.0) libcurl/7.16.3 OpenSSL/0.9.7l zlib/1.2. 3..Accept: */*..Content-Length: 1..Content-Type: application/x-www-form-urlencoded.... ##### T 127.0.0.1:61137 -> 127.0.0.1:3000 [AP] GET /i HTTP/1.1..X-Debug: nginx..Host: varnish..User-Agent: curl/7.16.3 (powerpc-apple-darwin9.0) libcurl/7.16.3 OpenSSL/0.9.7l zlib/1.2.3..Accept: */*..Con tent-Length: 1..Content-Type: application/x-www-form-urlencoded..X-Varnish: 1814203834..X-Forwarded-for: 127.0.0.1.... #### T 127.0.0.1:8888 -> 127.0.0.1:61133 [AP] HTTP/1.1 504 Gateway Time-out..Server: nginx/0.5.34..Date: Wed, 12 Mar 2008 23:59:50 GMT..Content-Type: text/html..Content-Length: 183..Connection: keep-ali ve......504 Gateway Time-out....

504 Gateway Time-out

..
nginx/0. 5.34...... ######