404 then upstream timeout

Thu Mar 13 03:18:22 MSK 2008

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]
  <html>.<head>.  <title>Action Controller: Exception caught</title>.
<style>.    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; }.
  </style>.</head>.<body>..<h1>Routing Error</
##
T 127.0.0.1:3000 -> 127.0.0.1:61135 [AP]
  h1>.<p><pre>no route found to match &quot;/i&quot; with
{:method=&gt;:post}</pre></p>....</body>.</html>
####
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....<html>.<head>.  <title>Action Controller: Exception
caught</title>.  <style>.    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; }.
</style>.</head>.<body>..<h1>Routing Error</h1>.<p><pre>no route found
to match &quot;/i&quot
  ; with {:method=&gt;:post}</pre></p>....</body>.</html>
###########
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....<html>..<head><title>504 Gateway
Time-out</title></head>..<body bgcolor="white">..<center><h1>504
Gateway Time-out</h1></center>..<hr><center>nginx/0.
  5.34</center>..</body>..</html>..
######

On Thu, Mar 6, 2008 at 10:57 PM, Dave Cheney <dave at cheney.net> wrote:
> Can you sniff the traffic between nginx and varnish with ngrep ? What does
> it indicate ?
>
> Cheers
>
> Dave
>
>
> On 07/03/2008, at 1:53 PM, Eden Li wrote:
>
> 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.
>