POST, memcached, 405, and gateway timeouts

Server NGINX
1

I have the following situation:

location ~ “foo” {
error_page 404 = /;
error_page 405 =200 /;

set $memcached_key "default";
if ($request_uri ~ "bar") {
  set $memcached_key "non-default";
}
memcached_pass ...;

}

location / {
proxy_pass …;
}

The “error_page 405 =200 /;” is there to make sure that POST requests
fall through to the “location /” block (since nginx returns 405s on
a POST when trying to serve cached content).

The problem is that this setup causes gateway timeouts. I verified that
the backend is up, though: if I comment out the first location block,
everything works fine. In other words, the backend is up.

Essentially, I’m trying to serve cached content for GET request and fall
back to the backend for POST requests.

Any help would be appreciated.

Thanks.

Thomer

2

On Thu, Jun 19, 2008 at 04:48:09PM -0400, [email protected] wrote:

memcached_pass ...;

The problem is that this setup causes gateway timeouts. I verified that
the backend is up, though: if I comment out the first location block,
everything works fine. In other words, the backend is up.

Essentially, I’m trying to serve cached content for GET request and fall
back to the backend for POST requests.

Could you create debug log ?

BTW, it better to split “foo” and “bar”:

location ~ “bar” {
error_page 404 = /;
error_page 405 =200 /;

   set $memcached_key "non-default";
   memcached_pass ...;

}

location ~ “foo” {
error_page 404 = /;
error_page 405 =200 /;

   set $memcached_key "default";
   memcached_pass ...;

}

3

Hi Igor,

Thanks for the reply.

You suggest I split the foo and bar case, but my example was bad.
Trying to “simplify” the example was a bad idea. What I’m actually
doing is (still simplified…):

location ~ “foo” {
error_page 404 = /;
error_page 405 =200 /;

 set $memcached_key "default";
 if ($request_uri ~ "bar(regexp1)baz(regexp2)") {
   set $memcached_key "$1:$2";
 }
 memcached_pass ...;

}

location / {
proxy_pass …;
}

My understanding is that I cannot use (…) in regular expressions in
the ‘location’ directive. That’s the reason why the if () is inside of
the location ~ “foo” part; I’m trying to ‘extract’ a part of the URL.
I couldn’t think of a better way to refactor the configuration.

But all that doesn’t explain the problem I’m seeing (i.e., POST requests
end up causing a Gateway Error 405). I’ll send a debug file on Monday,
as you requested.

Many thanks so far.

Thomer

4

Hi,

I looked at the debug log and it looks as though the POST gets rewritten
to a GET when it the request is passed on to the upstream proxy!

First the relevant part of the configuration:

location ~ "/splash" {
    default_type    text/html;
    error_page      404 = /;
    error_page      405 =200 /;

    set $memcached_key "production-splash:<bogus>";
    if ($request_uri ~ "client_ip=([^&]+).*continue_url=([^&]*)") {
        set $memcached_key "production-splash:$1:$2";
    }
    memcached_pass rack10:11211;
}

location / {
    proxy_pass http://abcabcabcabcabc-pool;
    proxy_set_header Host $http_host;
    proxy_set_header X-Forwarded-Proto https;
    proxy_set_header X-Forwarded-For $remote_addr;
    proxy_read_timeout 90;
}

Below are some interesting bits from the log. Let me know if you want
me to
send more.

Thanks,

Thomer

2008/06/27 09:14:37 [debug] 2567#0: *7 SSL_read: -1
2008/06/27 09:14:37 [debug] 2567#0: *7 SSL_get_error: 2
2008/06/27 09:14:37 [debug] 2567#0: *7 malloc: 080C5920:640
2008/06/27 09:14:37 [debug] 2567#0: *7 malloc: 08107B10:4096
2008/06/27 09:14:37 [debug] 2567#0: *7 http process request line
2008/06/27 09:14:37 [debug] 2567#0: *7 http request line: “POST
/splash/login?continue_url=http%253A%252F%252Fgoogle.com%252F HTTP/1.1”
2008/06/27 09:14:37 [debug] 2567#0: *7 http uri: “/splash/login”
2008/06/27 09:14:37 [debug] 2567#0: *7 http args:
“continue_url=http%253A%252F%252Fgoogle.com%252F”
2008/06/27 09:14:37 [debug] 2567#0: *7 http exten: “”
2008/06/27 09:14:37 [debug] 2567#0: *7 http process request header line
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Host:
YYYYYYY-YYYYYYY.XXXXXX.com”
2008/06/27 09:14:37 [debug] 2567#0: 7 http header: “User-Agent:
Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14)
Gecko/20080404 Firefox/2.0.0.14”
2008/06/27 09:14:37 [debug] 2567#0: 7 http header: "Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,/;q=0.5"
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Accept-Language:
en-us,en;q=0.5”
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Accept-Encoding:
gzip,deflate”
2008/06/27 09:14:37 [debug] 2567#0: 7 http header: "Accept-Charset:
ISO-8859-1,utf-8;q=0.7,;q=0.7"
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Keep-Alive: 300”
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Connection:
keep-alive”
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Referer:
xxxxx.com
90570beabf2048ce0&b=568813&auth_version=2&key=adaa52a73262264c25d990dcb99dedf5f5b151d4&node_ip=6.1.5.227&continue_url=http%3A%2F%2Fgoogle.com%2F”
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Cookie:
_session_id=735af32781907463a40c74fa58c86535”
2008/06/27 09:14:37 [debug] 2567#0: posted event 00000000
2008/06/27 09:14:37 [debug] 2567#0: worker cycle
2008/06/27 09:14:37 [debug] 2567#0: accept mutex locked
2008/06/27 09:14:37 [debug] 2567#0: epoll timer: 61456
2008/06/27 09:14:37 [debug] 2568#0: timer delta: 500
2008/06/27 09:14:37 [debug] 2568#0: posted events 00000000

[…]

2008/06/27 09:14:37 [debug] 2567#0: *7 http empty handler
2008/06/27 09:14:37 [debug] 2567#0: posted event B71201A8
2008/06/27 09:14:37 [debug] 2567#0: *7 delete posted event B71201A8
2008/06/27 09:14:37 [debug] 2567#0: *7 http process request header line
2008/06/27 09:14:37 [debug] 2567#0: *7 SSL_read: 49
2008/06/27 09:14:37 [debug] 2567#0: *7 SSL_read: 22
2008/06/27 09:14:37 [debug] 2567#0: *7 SSL_read: 69
2008/06/27 09:14:37 [debug] 2567#0: *7 SSL_read: -1
2008/06/27 09:14:37 [debug] 2567#0: *7 SSL_get_error: 2
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Content-Type:
application/x-www-form-urlencoded”
2008/06/27 09:14:37 [debug] 2567#0: *7 http header: “Content-Length: 69”
2008/06/27 09:14:37 [debug] 2567#0: *7 http header done
2008/06/27 09:14:37 [debug] 2567#0: *7 event timer del: 19: 3402560991
2008/06/27 09:14:37 [debug] 2567#0: *7 generic phase: 0
2008/06/27 09:14:37 [debug] 2567#0: *7 find location for “/splash/login”
2008/06/27 09:14:37 [debug] 2567#0: *7 find location: “/”
2008/06/27 09:14:37 [debug] 2567#0: *7 find location: ~ “/splash”
2008/06/27 09:14:37 [debug] 2567#0: *7 using configuration “/splash”
2008/06/27 09:14:37 [debug] 2567#0: *7 http cl:69 max:1048576
2008/06/27 09:14:37 [debug] 2567#0: *7 generic phase: 2
2008/06/27 09:14:37 [debug] 2567#0: *7 http script value:
“production-splash:”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script set var
2008/06/27 09:14:37 [debug] 2567#0: *7 http script var
2008/06/27 09:14:37 [debug] 2567#0: *7 http script var:
“/splash/login?continue_url=http%253A%252F%252Fgoogle.com%252F”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script regex:
“client_ip=([^&]+).continue_url=([^&])”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script if
2008/06/27 09:14:37 [debug] 2567#0: *7 http script if: false
2008/06/27 09:14:37 [debug] 2567#0: *7 post rewrite phase: 3
2008/06/27 09:14:37 [debug] 2567#0: *7 generic phase: 4
2008/06/27 09:14:37 [debug] 2567#0: *7 access phase: 5
2008/06/27 09:14:37 [debug] 2567#0: *7 access phase: 6
2008/06/27 09:14:37 [debug] 2567#0: *7 post access phase: 7
2008/06/27 09:14:37 [debug] 2567#0: *7 http finalize request: 405,
“/splash/login?continue_url=http%253A%252F%252Fgoogle.com%252F”
2008/06/27 09:14:37 [debug] 2567#0: *7 http special response: 405,
“/splash/login”
2008/06/27 09:14:37 [debug] 2567#0: *7 http set discard body
2008/06/27 09:14:37 [debug] 2567#0: *7 internal redirect: “/?”
2008/06/27 09:14:37 [debug] 2567#0: *7 generic phase: 0
2008/06/27 09:14:37 [debug] 2567#0: *7 find location for “/”
2008/06/27 09:14:37 [debug] 2567#0: *7 find location: “/”
2008/06/27 09:14:37 [debug] 2567#0: *7 find location: ~ “/splash”
2008/06/27 09:14:37 [debug] 2567#0: *7 using configuration “/”
2008/06/27 09:14:37 [debug] 2567#0: *7 http cl:0 max:1048576
2008/06/27 09:14:37 [debug] 2567#0: *7 generic phase: 2
2008/06/27 09:14:37 [debug] 2567#0: *7 post rewrite phase: 3
2008/06/27 09:14:37 [debug] 2567#0: *7 generic phase: 4
2008/06/27 09:14:37 [debug] 2567#0: *7 access phase: 5
2008/06/27 09:14:37 [debug] 2567#0: *7 access phase: 6
2008/06/27 09:14:37 [debug] 2567#0: *7 post access phase: 7
2008/06/27 09:14:37 [debug] 2567#0: *7 http init upstream, client timer:
0
2008/06/27 09:14:37 [debug] 2567#0: *7 http script copy: “”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script var: “”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script copy: “”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script copy: “”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script copy: “”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script var: “”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script copy: “”
2008/06/27 09:14:37 [debug] 2567#0: *7 http script copy: “”

[…]

2008/06/27 09:14:37 [debug] 2567#0: 7 http proxy header: “User-Agent:
Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14)
Gecko/20080404 Firefox/2.0.0.14”
2008/06/27 09:14:37 [debug] 2567#0: 7 http proxy header: "Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,/;q=0.5"
2008/06/27 09:14:37 [debug] 2567#0: *7 http proxy header:
“Accept-Language: en-us,en;q=0.5”
2008/06/27 09:14:37 [debug] 2567#0: *7 http proxy header:
“Accept-Encoding: gzip,deflate”
2008/06/27 09:14:37 [debug] 2567#0: 7 http proxy header:
"Accept-Charset: ISO-8859-1,utf-8;q=0.7,;q=0.7"
2008/06/27 09:14:37 [debug] 2567#0: *7 http proxy header: “Referer:
https://YYYYYYY-YYYYYYY.XXXXXX.com/splash?mac=00%3A18%3A0A%3A01%3A05%3AE3&client_ip=10.14.182.125&a=752ae7bdbb96bf252
80b55990570beabf2048ce0&b=568813&auth_version=2&key=adaa52a73262264c25d990dcb99dedf5f5b151d4&node_ip=6.1.5.227&continue_url=http%3A%2F%2Fgoogle.com%2F”
2008/06/27 09:14:37 [debug] 2567#0: *7 http proxy header: “Cookie:
_session_id=735af32781907463a40c74fa58c86535”
2008/06/27 09:14:37 [debug] 2567#0: 7 http proxy header: “Content-Type:
application/x-www-form-urlencoded”
2008/06/27 09:14:37 [debug] 2567#0: 7 http proxy header:
“Content-Length: 69”
2008/06/27 09:14:37 [debug] 2567#0: 7 http proxy header:
"GET /splash/login?continue_url=http%253A%252F%252Fgoogle.com%252F
HTTP/1.0
Host: YYYYYYY-YYYYYYY.XXXXXX.com
X-Forwarded-Proto: https
X-Forwarded-For: 68.160.52.36
Connection: close
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.14)
Gecko/20080404 Firefox/2.0.0.14
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,/;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,;q=0.7
Referer:
xxxxx.com
73262264c25d990dcb99dedf5f5b151d4&node_ip=6.1.5.227&continue_url=http%3A%2F%2Fgoogle.com%2F
Cookie: _session_id=735af32781907463a40c74fa58c86535
Content-Type: application/x-www-form-urlencoded
Content-Length: 69

"
2008/06/27 09:14:37 [debug] 2567#0: *7 http cleanup add: 08108778
2008/06/27 09:14:37 [debug] 2567#0: *7 get rr peer, try: 1
2008/06/27 09:14:37 [debug] 2567#0: *7 socket 20
2008/06/27 09:14:37 [debug] 2567#0: *7 epoll add connection: fd:20
ev:80000005
2008/06/27 09:14:37 [debug] 2567#0: *7 connect to 192.168.166.26:5001,
fd:20 #11
2008/06/27 09:14:37 [debug] 2567#0: *7 http upstream connect: -2
2008/06/27 09:14:37 [debug] 2567#0: *7 event timer add: 20:
60000:3402559712
2008/06/27 09:14:37 [debug] 2567#0: posted event 00000000
2008/06/27 09:14:37 [debug] 2567#0: worker cycle
2008/06/27 09:14:37 [debug] 2567#0: accept mutex locked
2008/06/27 09:14:37 [debug] 2567#0: epoll timer: 60000
2008/06/27 09:14:37 [debug] 2567#0: epoll: fd:20 ev:0004 d:B71872FC

[…]

2008/06/27 09:16:07 [debug] 2572#0: accept mutex lock failed: 0
2008/06/27 09:16:07 [debug] 2572#0: epoll timer: 500
2008/06/27 09:16:07 [debug] 2567#0: timer delta: 58207
2008/06/27 09:16:07 [debug] 2567#0: *7 event timer del: 20: 3402589713
2008/06/27 09:16:07 [debug] 2567#0: *7 http upstream process header
2008/06/27 09:16:07 [debug] 2567#0: *7 http next upstream, 4
2008/06/27 09:16:07 [debug] 2567#0: *7 free rr peer 1 4
2008/06/27 09:16:07 [error] 2567#0: *7 upstream timed out (110:
Connection timed out) while reading response header from upstream,
client: 68.160.52.36, server: YYYYYYY-YYYYYYY.XXXXXX.c
om, request: “POST
/splash/login?continue_url=http%253A%252F%252Fgoogle.com%252F HTTP/1.1”,
upstream:
“http://192.168.166.26:5001/splash/login?continue_url=http%253A%252F%252Fgoogle.com
%252F”, host: “YYYYYYY-YYYYYYY.XXXXXX.com”, referrer:
“xxxxx.com
abf2048ce0&b=568813&auth_version=2&key=adaa52a73262264c25d990dcb99dedf5f5b151d4&node_ip=6.1.5.227&continue_url=http%3A%2F%2Fgoogle.com%2F”
2008/06/27 09:16:07 [debug] 2567#0: *7 finalize http upstream request:
504
2008/06/27 09:16:07 [debug] 2567#0: *7 finalize http proxy request
2008/06/27 09:16:07 [debug] 2567#0: *7 free rr peer 0 0
2008/06/27 09:16:07 [debug] 2567#0: *7 close http upstream connection:
20
2008/06/27 09:16:07 [debug] 2567#0: *7 http finalize request: 504, “/?”
2008/06/27 09:16:07 [debug] 2567#0: *7 http special response: 504, “/”
2008/06/27 09:16:07 [debug] 2567#0: *7 http set discard body
2008/06/27 09:16:07 [debug] 2567#0: *7 HTTP/1.1 504 Gateway Time-out
Server: nginx/0.6.31
Date: Fri, 27 Jun 2008 16:16:07 GMT
Content-Type: text/html
Content-Length: 183
Connection: keep-alive

2008/06/27 09:16:07 [debug] 2567#0: *7 write new buf t:1 f:0 081087D0,
pos 081087D0, size: 162 file: 0, size: 0
2008/06/27 09:16:07 [debug] 2567#0: *7 http write filter: l:0 f:0 s:162
2008/06/27 09:16:07 [debug] 2567#0: *7 http output filter “/?”
2008/06/27 09:16:07 [debug] 2567#0: *7 copy filter: “/?”
2008/06/27 09:16:07 [debug] 2567#0: *7 http postpone filter “/?”
0810892C
2008/06/27 09:16:07 [debug] 2567#0: *7 http postpone filter out “/?”
2008/06/27 09:16:07 [debug] 2567#0: *7 write old buf t:1 f:0 081087D0,
pos 081087D0, size: 162 file: 0, size: 0
2008/06/27 09:16:07 [debug] 2567#0: *7 write new buf t:0 f:0 00000000,
pos 080A7EC0, size: 130 file: 0, size: 0
2008/06/27 09:16:07 [debug] 2567#0: *7 write new buf t:0 f:0 00000000,
pos 080A6D60, size: 53 file: 0, size: 0
2008/06/27 09:16:07 [debug] 2567#0: *7 http write filter: l:1 f:0 s:345
2008/06/27 09:16:07 [debug] 2567#0: *7 http write filter limit 0
2008/06/27 09:16:07 [debug] 2567#0: *7 malloc: 080F5490:16384
2008/06/27 09:16:07 [debug] 2567#0: *7 SSL buf copy: 162
2008/06/27 09:16:07 [debug] 2567#0: *7 SSL buf copy: 130
2008/06/27 09:16:07 [debug] 2567#0: *7 SSL buf copy: 53
2008/06/27 09:16:07 [debug] 2567#0: *7 SSL to write: 345
2008/06/27 09:16:07 [debug] 2567#0: *7 SSL_write: 345
2008/06/27 09:16:07 [debug] 2567#0: *7 http write filter 00000000
2008/06/27 09:16:07 [debug] 2567#0: *7 copy filter: 0 “/?”