POST, memcached, 405, and gateway timeouts
nginx at thomer.com
nginx at thomer.com
Fri Jun 27 20:33:46 MSD 2008
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: https://YYYYYYY-YYYYYYY.XXXXXX.com/splash?mac=00%3A18%3A0A%3A01%3A05%3AE3&client_ip=10.14.182.125&a=752ae7bdbb96bf25280b559
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:<bogus>"
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: https://YYYYYYY-YYYYYYY.XXXXXX.com/splash?mac=00%3A18%3A0A%3A01%3A05%3AE3&client_ip=10.14.182.125&a=752ae7bdbb96bf25280b55990570beabf2048ce0&b=568813&auth_version=2&key=adaa52a
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: "https://YYYYYYY-YYYYYYY.XXXXXX.com/splash?mac=00%3A18%3A0A%3A01%3A05%3AE3&client_ip=10.14.182.125&a=752ae7bdbb96bf25280b55990570be
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 "/?"
More information about the nginx
mailing list