Why nginx log 502 status instead of 200 in access log #24

Closed
ycn opened this Issue Apr 3, 2013 · 8 comments

2 participants

@ycn
ycn commented Apr 3, 2013

 location ~ ^/test {
        include uwsgi_params;
        uwsgi_pass 127.0.0.1:3031;
 }

I can always get "HTTP/1.1 200 OK" when I access the location above, but nginx always log 502 status instead of 200 in the access log. My uWSGI service works fine and it returns "HTTP/1.1 200 OK" when I directly access the address 127.0.0.1:3031.

All my other proxy service such as php-fpm do not have such a problem.

That's weird.

My openresty version: 1.2.6.6

@agentzh
OpenResty member

First of all, please do not post Chinese text on this project's github issues page. If you really want to use Chinese, then please post to the openresty (Chinese) mailing list in the future: https://groups.google.com/group/openresty Thank you for your cooperation.

Regarding your problem, please check out your Nginx error log file to see if there is any errors. If not, please consider enable the Nginx debug logging as documented here: http://wiki.nginx.org/Debugging#Debugging_log

@ycn
ycn commented Apr 3, 2013

After enabled the debuggin_log, you can see that uwsgi response is 200 in the error.log as follows.


2013/04/03 16:24:50 [debug] 21090#0: 7 http cl:-1 max:1048576
2013/04/03 16:24:50 [debug] 21090#0: *7 rewrite phase: 3
2013/04/03 16:24:50 [debug] 21090#0: *7 lua rewrite handler, uri:"/api/logs/adf_log" c:1
2013/04/03 16:24:50 [debug] 21090#0: *7 rewrite phase: 3
2013/04/03 16:24:50 [debug] 21090#0: *7 rewrite phase: 4
2013/04/03 16:24:50 [debug] 21090#0: *7 rewrite phase: 5
2013/04/03 16:24:50 [debug] 21090#0: *7 lua rewrite handler, uri:"/api/logs/adf_log" c:1
2013/04/03 16:24:50 [debug] 21090#0: *7 post rewrite phase: 6
2013/04/03 16:24:50 [debug] 21090#0: *7 generic phase: 7
2013/04/03 16:24:50 [debug] 21090#0: *7 generic phase: 8
2013/04/03 16:24:50 [debug] 21090#0: *7 access phase: 9
2013/04/03 16:24:50 [debug] 21090#0: *7 lua access handler, uri:"/api/logs/adf_log" c:1
2013/04/03 16:24:50 [debug] 21090#0: *7 access phase: 9
2013/04/03 16:24:50 [debug] 21090#0: *7 access phase: 10
2013/04/03 16:24:50 [debug] 21090#0: *7 access phase: 11
2013/04/03 16:24:50 [debug] 21090#0: *7 access phase: 12
2013/04/03 16:24:50 [debug] 21090#0: *7 lua access handler, uri:"/api/logs/adf_log" c:1
2013/04/03 16:24:50 [debug] 21090#0: *7 post access phase: 13
2013/04/03 16:24:50 [debug] 21090#0: *7 http init upstream, client timer: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 epoll add event: fd:3 op:3 ev:80000005
2013/04/03 16:24:50 [debug] 21090#0: *7 posix_memalign: 0000000001BBD980:4096 @16
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "QUERY_STRING"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "QUERY_STRING: "
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "REQUEST_METHOD"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "GET"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "REQUEST_METHOD: GET"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "CONTENT_TYPE"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "CONTENT_TYPE: "
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "CONTENT_LENGTH"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "CONTENT_LENGTH: "
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "REQUEST_URI"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "/api/logs/adf_log"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "REQUEST_URI: /api/logs/adf_log"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "PATH_INFO"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "/api/logs/adf_log"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "PATH_INFO: /api/logs/adf_log"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "DOCUMENT_ROOT"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "/php"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "DOCUMENT_ROOT: /php"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "SERVER_PROTOCOL"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "HTTP/1.1"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "SERVER_PROTOCOL: HTTP/1.1"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: ""
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "REMOTE_ADDR"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "192.168.137.1"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "REMOTE_ADDR: 192.168.137.1"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "REMOTE_PORT"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "51754"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "REMOTE_PORT: 51754"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "SERVER_PORT"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "80"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "SERVER_PORT: 80"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script copy: "SERVER_NAME"
2013/04/03 16:24:50 [debug] 21090#0: *7 http script var: "local.com"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "SERVER_NAME: local.com"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "HTTP_USER_AGENT: curl/7.28.1"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "HTTP_HOST: 192.168.137.128"
2013/04/03 16:24:50 [debug] 21090#0: *7 uwsgi param: "HTTP_ACCEPT: */
"
2013/04/03 16:24:50 [debug] 21090#0: *7 http cleanup add: 0000000001BBDBC0
2013/04/03 16:24:50 [debug] 21090#0: *7 get rr peer, try: 1
2013/04/03 16:24:50 [debug] 21090#0: *7 socket 10
2013/04/03 16:24:50 [debug] 21090#0: *7 epoll add connection: fd:10 ev:80000005
2013/04/03 16:24:50 [debug] 21090#0: *7 connect to 127.0.0.1:3031, fd:10 #8
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream connect: -2
2013/04/03 16:24:50 [debug] 21090#0: *7 posix_memalign: 0000000001BC3CD0:128 @16
2013/04/03 16:24:50 [debug] 21090#0: *7 event timer add: 10: 60000:1364977550759
2013/04/03 16:24:50 [debug] 21090#0: *7 http finalize request: -4, "/api/logs/adf_log?" a:1, c:2
2013/04/03 16:24:50 [debug] 21090#0: *7 http request count:2 blk:0
2013/04/03 16:24:50 [debug] 21090#0: *7 post event 0000000001BDE390
2013/04/03 16:24:50 [debug] 21090#0: *7 post event 0000000001BDE3F8
2013/04/03 16:24:50 [debug] 21090#0: *7 delete posted event 0000000001BDE3F8
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream request: "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream send request handler
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream send request
2013/04/03 16:24:50 [debug] 21090#0: *7 chain writer buf fl:0 s:350
2013/04/03 16:24:50 [debug] 21090#0: *7 chain writer in: 0000000001BBDBF8
2013/04/03 16:24:50 [debug] 21090#0: *7 writev: 350
2013/04/03 16:24:50 [debug] 21090#0: *7 chain writer out: 0000000000000000
2013/04/03 16:24:50 [debug] 21090#0: *7 event timer del: 10: 1364977550759
2013/04/03 16:24:50 [debug] 21090#0: *7 event timer add: 10: 60000:1364977550760
2013/04/03 16:24:50 [debug] 21090#0: *7 delete posted event 0000000001BDE390
2013/04/03 16:24:50 [debug] 21090#0: *7 http run request: "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream check client, write event:1, "/api/logs/adf_log"
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream recv(): -1 (11: Resource temporarily unavailable)
2013/04/03 16:24:50 [debug] 21090#0: *7 post event 0000000001BC6EF8
2013/04/03 16:24:50 [debug] 21090#0: *7 post event 0000000001BDE3F8
2013/04/03 16:24:50 [debug] 21090#0: *7 delete posted event 0000000001BDE3F8
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream request: "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream dummy handler
2013/04/03 16:24:50 [debug] 21090#0: *7 delete posted event 0000000001BC6EF8
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream request: "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream process header
2013/04/03 16:24:50 [debug] 21090#0: *7 malloc: 0000000001BDA5D0:4096
2013/04/03 16:24:50 [debug] 21090#0: *7 recv: fd:10 80 of 4096
2013/04/03 16:24:50 [debug] 21090#0: *7 http uwsgi status 200 "200 OK"
2013/04/03 16:24:50 [debug] 21090#0: *7 http uwsgi header: "Content-Type: text/html; charset=utf-8"
2013/04/03 16:24:50 [debug] 21090#0: *7 http uwsgi header: "Content-Length: 2"
2013/04/03 16:24:50 [debug] 21090#0: *7 http uwsgi header done
2013/04/03 16:24:50 [debug] 21090#0: *7 lua capture header filter, uri "/api/logs/adf_log"
2013/04/03 16:24:50 [debug] 21090#0: *7 HTTP/1.1 200 OK
Server: ngx_openresty/1.2.6.6
Date: Wed, 03 Apr 2013 08:24:50 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 2
Connection: keep-alive

2013/04/03 16:24:50 [debug] 21090#0: *7 write new buf t:1 f:0 0000000001BBDE40, pos 0000000001BBDE40, size: 170 file: 0, size: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 http write filter: l:0 f:0 s:170
2013/04/03 16:24:50 [debug] 21090#0: *7 http cacheable: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream process upstream
2013/04/03 16:24:50 [debug] 21090#0: *7 pipe read upstream: 1
2013/04/03 16:24:50 [debug] 21090#0: *7 pipe preread: 2
2013/04/03 16:24:50 [debug] 21090#0: *7 readv: 1:4016
2013/04/03 16:24:50 [debug] 21090#0: *7 pipe recv chain: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 pipe buf free s:0 t:1 f:0 0000000001BDA5D0, pos 0000000001BDA61E, size: 2 file: 0, size: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 pipe length: -1
2013/04/03 16:24:50 [debug] 21090#0: *7 input buf #0
2013/04/03 16:24:50 [debug] 21090#0: *7 pipe write downstream: 1
2013/04/03 16:24:50 [debug] 21090#0: *7 pipe write downstream flush in
2013/04/03 16:24:50 [debug] 21090#0: *7 http output filter "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 http copy filter: "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 lua capture body filter, uri "/api/logs/adf_log"
2013/04/03 16:24:50 [debug] 21090#0: *7 http postpone filter "/api/logs/adf_log?" 0000000001BBE068
2013/04/03 16:24:50 [debug] 21090#0: *7 write old buf t:1 f:0 0000000001BBDE40, pos 0000000001BBDE40, size: 170 file: 0, size: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 write new buf t:1 f:0 0000000001BDA5D0, pos 0000000001BDA61E, size: 2 file: 0, size: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 http write filter: l:0 f:0 s:172
2013/04/03 16:24:50 [debug] 21090#0: *7 http copy filter: 0 "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 pipe write downstream done
2013/04/03 16:24:50 [debug] 21090#0: *7 event timer: 10, old: 1364977550760, new: 1364977550780
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream exit: 0000000000000000
2013/04/03 16:24:50 [debug] 21090#0: *7 finalize http upstream request: 502
2013/04/03 16:24:50 [debug] 21090#0: *7 finalize http uwsgi request
2013/04/03 16:24:50 [debug] 21090#0: *7 free rr peer 1 0
2013/04/03 16:24:50 [debug] 21090#0: *7 close http upstream connection: 10
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BC3CD0, unused: 48
2013/04/03 16:24:50 [debug] 21090#0: *7 event timer del: 10: 1364977550760
2013/04/03 16:24:50 [debug] 21090#0: *7 reusable connection: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 http upstream temp fd: -1
2013/04/03 16:24:50 [debug] 21090#0: *7 http output filter "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 http copy filter: "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 lua capture body filter, uri "/api/logs/adf_log"
2013/04/03 16:24:50 [debug] 21090#0: *7 http postpone filter "/api/logs/adf_log?" 00007FFF9B149550
2013/04/03 16:24:50 [debug] 21090#0: *7 write old buf t:1 f:0 0000000001BBDE40, pos 0000000001BBDE40, size: 170 file: 0, size: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 write old buf t:1 f:0 0000000001BDA5D0, pos 0000000001BDA61E, size: 2 file: 0, size: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 http write filter: l:1 f:0 s:172
2013/04/03 16:24:50 [debug] 21090#0: *7 http write filter limit 0
2013/04/03 16:24:50 [debug] 21090#0: *7 writev: 172
2013/04/03 16:24:50 [debug] 21090#0: *7 http write filter 0000000000000000
2013/04/03 16:24:50 [debug] 21090#0: *7 http copy filter: 0 "/api/logs/adf_log?"
2013/04/03 16:24:50 [debug] 21090#0: *7 http finalize request: 0, "/api/logs/adf_log?" a:1, c:1
2013/04/03 16:24:50 [debug] 21090#0: *7 set http keepalive handler
2013/04/03 16:24:50 [debug] 21090#0: *7 http close request
2013/04/03 16:24:50 [debug] 21090#0: *7 http log handler
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BDA5D0
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BBC970, unused: 8
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BBD980, unused: 1895
2013/04/03 16:24:50 [debug] 21090#0: *7 event timer add: 3: 65000:1364977555780
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BC32C0
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BC38C0
2013/04/03 16:24:50 [debug] 21090#0: *7 hc free: 0000000000000000 0
2013/04/03 16:24:50 [debug] 21090#0: *7 hc busy: 0000000000000000 0
2013/04/03 16:24:50 [debug] 21090#0: *7 tcp_nodelay
2013/04/03 16:24:50 [debug] 21090#0: *7 reusable connection: 1
2013/04/03 16:24:50 [debug] 21090#0: *7 post event 0000000001BC6E90
2013/04/03 16:24:50 [debug] 21090#0: *7 delete posted event 0000000001BC6E90
2013/04/03 16:24:50 [debug] 21090#0: *7 http keepalive handler
2013/04/03 16:24:50 [debug] 21090#0: *7 malloc: 0000000001BC32C0:1024
2013/04/03 16:24:50 [debug] 21090#0: *7 recv: fd:3 -1 of 1024
2013/04/03 16:24:50 [debug] 21090#0: *7 recv() not ready (11: Resource temporarily unavailable)
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BC32C0
2013/04/03 16:24:50 [debug] 21090#0: *7 post event 0000000001BC6E90
2013/04/03 16:24:50 [debug] 21090#0: *7 post event 0000000001BDE390
2013/04/03 16:24:50 [debug] 21090#0: *7 delete posted event 0000000001BDE390
2013/04/03 16:24:50 [debug] 21090#0: *7 http empty handler
2013/04/03 16:24:50 [debug] 21090#0: *7 delete posted event 0000000001BC6E90
2013/04/03 16:24:50 [debug] 21090#0: *7 http keepalive handler
2013/04/03 16:24:50 [debug] 21090#0: *7 malloc: 0000000001BC32C0:1024
2013/04/03 16:24:50 [debug] 21090#0: *7 recv: fd:3 0 of 1024
2013/04/03 16:24:50 [info] 21090#0: *7 client 192.168.137.1 closed keepalive connection
2013/04/03 16:24:50 [debug] 21090#0: *7 close http connection: 3
2013/04/03 16:24:50 [debug] 21090#0: *7 event timer del: 3: 1364977555780
2013/04/03 16:24:50 [debug] 21090#0: *7 reusable connection: 0
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BC32C0
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000000000000
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BBA5F0, unused: 8
2013/04/03 16:24:50 [debug] 21090#0: *7 free: 0000000001BC37B0, unused: 112

@agentzh
OpenResty member
@agentzh agentzh added a commit that referenced this issue Apr 5, 2013
@agentzh agentzh renamed the "nonbuffered-upstream-truncation" patch to "upstream-trun…
…cation" patch; also fixed issues with chunked upstream response bodies. thanks Andy Yuan for reporting this issue in #24.
042e2fd
@agentzh
OpenResty member

Okay, I think I've fixed the issue in the upstream-truncation patch. Could you please try ngx_openresty 1.2.7.5rc2 again?

http://openresty.org/download/ngx_openresty-1.2.7.5rc2.tar.gz

Thanks!

@ycn
ycn commented Apr 7, 2013

I'm afraid that the patch does slove the problem, but something else is wrong :(

CRUL output:


$ curl -v "http://192.168.137.128/api/logs/adf_log"
* About to connect() to 192.168.137.128 port 80 (#0)
*   Trying 192.168.137.128...
* connected
* Connected to 192.168.137.128 (192.168.137.128) port 80 (#0)
> GET /api/logs/adf_log HTTP/1.1
> User-Agent: curl/7.28.1
> Host: 192.168.137.128
> Accept: */*
>
* Empty reply from server
* Connection #0 to host 192.168.137.128 left intact
curl: (52) Empty reply from server
* Closing connection #0

Nginx access log:


192.168.137.1 - - [07/Apr/2013:10:26:34 +0800] "GET /api/logs/adf_log HTTP/1.1" 200 0 "-" "curl/7.28.1" "-" 0.005 0.005

Nginx debugging log:


2013/04/07 10:26:34 [debug] 13895#0: *3 http cl:-1 max:1048576
2013/04/07 10:26:34 [debug] 13895#0: *3 rewrite phase: 3
2013/04/07 10:26:34 [debug] 13895#0: *3 rewrite phase: 4
2013/04/07 10:26:34 [debug] 13895#0: *3 rewrite phase: 5
2013/04/07 10:26:34 [debug] 13895#0: *3 lua rewrite handler, uri:"/api/logs/adf_log" c:1
2013/04/07 10:26:34 [debug] 13895#0: *3 post rewrite phase: 6
2013/04/07 10:26:34 [debug] 13895#0: *3 generic phase: 7
2013/04/07 10:26:34 [debug] 13895#0: *3 generic phase: 8
2013/04/07 10:26:34 [debug] 13895#0: *3 access phase: 9
2013/04/07 10:26:34 [debug] 13895#0: *3 access phase: 10
2013/04/07 10:26:34 [debug] 13895#0: *3 access phase: 11
2013/04/07 10:26:34 [debug] 13895#0: *3 access phase: 12
2013/04/07 10:26:34 [debug] 13895#0: *3 lua access handler, uri:"/api/logs/adf_log" c:1
2013/04/07 10:26:34 [debug] 13895#0: *3 post access phase: 13
2013/04/07 10:26:34 [debug] 13895#0: *3 try files phase: 14
2013/04/07 10:26:34 [debug] 13895#0: *3 http init upstream, client timer: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 epoll add event: fd:15 op:3 ev:80000005
2013/04/07 10:26:34 [debug] 13895#0: *3 posix_memalign: 000000000198B2E0:4096 @16
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "QUERY_STRING"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "QUERY_STRING: "
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "REQUEST_METHOD"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "GET"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "REQUEST_METHOD: GET"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "CONTENT_TYPE"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "CONTENT_TYPE: "
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "CONTENT_LENGTH"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "CONTENT_LENGTH: "
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "REQUEST_URI"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "/api/logs/adf_log"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "REQUEST_URI: /api/logs/adf_log"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "PATH_INFO"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "/api/logs/adf_log"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "PATH_INFO: /api/logs/adf_log"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "DOCUMENT_ROOT"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "/php"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "DOCUMENT_ROOT: /php"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "SERVER_PROTOCOL"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "HTTP/1.1"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "SERVER_PROTOCOL: HTTP/1.1"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: ""
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "REMOTE_ADDR"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "192.168.137.1"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "REMOTE_ADDR: 192.168.137.1"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "REMOTE_PORT"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "52923"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "REMOTE_PORT: 52923"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "SERVER_PORT"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "80"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "SERVER_PORT: 80"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script copy: "SERVER_NAME"
2013/04/07 10:26:34 [debug] 13895#0: *3 http script var: "local.com"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "SERVER_NAME: local.com"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "HTTP_USER_AGENT: curl/7.28.1"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "HTTP_HOST: 192.168.137.128"
2013/04/07 10:26:34 [debug] 13895#0: *3 uwsgi param: "HTTP_ACCEPT: */*"
2013/04/07 10:26:34 [debug] 13895#0: *3 http cleanup add: 000000000198B528
2013/04/07 10:26:34 [debug] 13895#0: *3 get rr peer, try: 1
2013/04/07 10:26:34 [debug] 13895#0: *3 socket 16
2013/04/07 10:26:34 [debug] 13895#0: *3 epoll add connection: fd:16 ev:80000005
2013/04/07 10:26:34 [debug] 13895#0: *3 connect to 127.0.0.1:3031, fd:16 #4
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream connect: -2
2013/04/07 10:26:34 [debug] 13895#0: *3 posix_memalign: 0000000001978E30:128 @16
2013/04/07 10:26:34 [debug] 13895#0: *3 event timer add: 16: 60000:1365301654729
2013/04/07 10:26:34 [debug] 13895#0: *3 http finalize request: -4, "/api/logs/adf_log?" a:1, c:2
2013/04/07 10:26:34 [debug] 13895#0: *3 http request count:2 blk:0
2013/04/07 10:26:34 [debug] 13895#0: *3 post event 00000000019AE320
2013/04/07 10:26:34 [debug] 13895#0: *3 post event 00000000019AE388
2013/04/07 10:26:34 [debug] 13895#0: *3 delete posted event 00000000019AE388
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream request: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream send request handler
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream send request
2013/04/07 10:26:34 [debug] 13895#0: *3 chain writer buf fl:0 s:350
2013/04/07 10:26:34 [debug] 13895#0: *3 chain writer in: 000000000198B560
2013/04/07 10:26:34 [debug] 13895#0: *3 writev: 350
2013/04/07 10:26:34 [debug] 13895#0: *3 chain writer out: 0000000000000000
2013/04/07 10:26:34 [debug] 13895#0: *3 event timer del: 16: 1365301654729
2013/04/07 10:26:34 [debug] 13895#0: *3 event timer add: 16: 60000:1365301654729
2013/04/07 10:26:34 [debug] 13895#0: *3 delete posted event 00000000019AE320
2013/04/07 10:26:34 [debug] 13895#0: *3 http run request: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream check client, write event:1, "/api/logs/adf_log"
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream recv(): -1 (11: Resource temporarily unavailable)
2013/04/07 10:26:34 [debug] 13895#0: *3 post event 000000000199AB78
2013/04/07 10:26:34 [debug] 13895#0: *3 post event 00000000019AE388
2013/04/07 10:26:34 [debug] 13895#0: *3 delete posted event 00000000019AE388
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream request: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream dummy handler
2013/04/07 10:26:34 [debug] 13895#0: *3 delete posted event 000000000199AB78
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream request: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream process header
2013/04/07 10:26:34 [debug] 13895#0: *3 malloc: 000000000196E5E0:4096
2013/04/07 10:26:34 [debug] 13895#0: *3 recv: fd:16 78 of 4096
2013/04/07 10:26:34 [debug] 13895#0: *3 http uwsgi status 200 "200 OK"
2013/04/07 10:26:34 [debug] 13895#0: *3 http uwsgi header: "Content-Type: text/html; charset=utf-8"
2013/04/07 10:26:34 [debug] 13895#0: *3 http uwsgi header: "Content-Length: 2"
2013/04/07 10:26:34 [debug] 13895#0: *3 http uwsgi header done
2013/04/07 10:26:34 [debug] 13895#0: *3 lua capture header filter, uri "/api/logs/adf_log"
2013/04/07 10:26:34 [debug] 13895#0: *3 HTTP/1.1 200 OK
Server: ngx_openresty/1.2.7.5rc2
Date: Sun, 07 Apr 2013 02:26:34 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 2
Connection: keep-alive

2013/04/07 10:26:34 [debug] 13895#0: *3 write new buf t:1 f:0 000000000198B7A8, pos 000000000198B7A8, size: 173 file: 0, size: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 http write filter: l:0 f:0 s:173
2013/04/07 10:26:34 [debug] 13895#0: *3 http cacheable: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream process upstream
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe read upstream: 1
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe preread: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 readv: 1:4018
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe recv chain: 2
2013/04/07 10:26:34 [debug] 13895#0: *3 readv: 1:4016
2013/04/07 10:26:34 [debug] 13895#0: *3 readv() not ready (11: Resource temporarily unavailable)
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe recv chain: -2
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe buf free s:0 t:1 f:0 000000000196E5E0, pos 000000000196E62E, size: 2 file: 0, size: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe length: -1
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe write downstream: 1
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe write busy: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe write: out:0000000000000000, f:0
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe read upstream: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe buf free s:0 t:1 f:0 000000000196E5E0, pos 000000000196E62E, size: 2 file: 0, size: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe length: -1
2013/04/07 10:26:34 [debug] 13895#0: *3 event timer: 16, old: 1365301654729, new: 1365301654734
2013/04/07 10:26:34 [debug] 13895#0: *3 post event 00000000019AE388
2013/04/07 10:26:34 [debug] 13895#0: *3 delete posted event 00000000019AE388
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream request: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream dummy handler
2013/04/07 10:26:34 [debug] 13895#0: *3 post event 000000000199AB78
2013/04/07 10:26:34 [debug] 13895#0: *3 post event 00000000019AE388
2013/04/07 10:26:34 [debug] 13895#0: *3 delete posted event 00000000019AE388
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream request: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream dummy handler
2013/04/07 10:26:34 [debug] 13895#0: *3 delete posted event 000000000199AB78
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream request: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream process upstream
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe read upstream: 1
2013/04/07 10:26:34 [debug] 13895#0: *3 readv: 1:4016
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe recv chain: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe buf free s:0 t:1 f:0 000000000196E5E0, pos 000000000196E62E, size: 2 file: 0, size: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe length: -1
2013/04/07 10:26:34 [debug] 13895#0: *3 input buf #0
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe write downstream: 1
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe write downstream flush in
2013/04/07 10:26:34 [debug] 13895#0: *3 http output filter "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http copy filter: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 lua capture body filter, uri "/api/logs/adf_log"
2013/04/07 10:26:34 [debug] 13895#0: *3 http postpone filter "/api/logs/adf_log?" 000000000198B9D0
2013/04/07 10:26:34 [debug] 13895#0: *3 write old buf t:1 f:0 000000000198B7A8, pos 000000000198B7A8, size: 173 file: 0, size: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 write new buf t:1 f:0 000000000196E5E0, pos 000000000196E62E, size: 2 file: 0, size: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 http write filter: l:0 f:0 s:175
2013/04/07 10:26:34 [debug] 13895#0: *3 http copy filter: 0 "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 pipe write downstream done
2013/04/07 10:26:34 [debug] 13895#0: *3 event timer: 16, old: 1365301654729, new: 1365301654734
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream exit: 0000000000000000
2013/04/07 10:26:34 [debug] 13895#0: *3 finalize http upstream request: -1
2013/04/07 10:26:34 [debug] 13895#0: *3 finalize http uwsgi request
2013/04/07 10:26:34 [debug] 13895#0: *3 free rr peer 1 0
2013/04/07 10:26:34 [debug] 13895#0: *3 close http upstream connection: 16
2013/04/07 10:26:34 [debug] 13895#0: *3 free: 0000000001978E30, unused: 48
2013/04/07 10:26:34 [debug] 13895#0: *3 event timer del: 16: 1365301654729
2013/04/07 10:26:34 [debug] 13895#0: *3 reusable connection: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 http upstream temp fd: -1
2013/04/07 10:26:34 [debug] 13895#0: *3 http finalize request: -1, "/api/logs/adf_log?" a:1, c:1
2013/04/07 10:26:34 [debug] 13895#0: *3 http terminate request count:1
2013/04/07 10:26:34 [debug] 13895#0: *3 http terminate cleanup count:1 blk:0
2013/04/07 10:26:34 [debug] 13895#0: *3 http posted request: "/api/logs/adf_log?"
2013/04/07 10:26:34 [debug] 13895#0: *3 http terminate handler count:1
2013/04/07 10:26:34 [debug] 13895#0: *3 http request count:1 blk:0
2013/04/07 10:26:34 [debug] 13895#0: *3 http close request
2013/04/07 10:26:34 [debug] 13895#0: *3 http log handler
2013/04/07 10:26:34 [debug] 13895#0: *3 free: 000000000196E5E0
2013/04/07 10:26:34 [debug] 13895#0: *3 free: 000000000197E2A0, unused: 3
2013/04/07 10:26:34 [debug] 13895#0: *3 free: 000000000198B2E0, unused: 1983
2013/04/07 10:26:34 [debug] 13895#0: *3 close http connection: 15
2013/04/07 10:26:34 [debug] 13895#0: *3 reusable connection: 0
2013/04/07 10:26:34 [debug] 13895#0: *3 free: 0000000001978A20
2013/04/07 10:26:34 [debug] 13895#0: *3 free: 0000000001978420
2013/04/07 10:26:34 [debug] 13895#0: *3 free: 0000000001960440, unused: 8
2013/04/07 10:26:34 [debug] 13895#0: *3 free: 0000000001978910, unused: 112
@agentzh
OpenResty member
@ycn
ycn commented Apr 8, 2013

Great! The new patch fixed this issue.
Thanks!

@agentzh
OpenResty member

Thank you for the feedback! So I'm closing this :)

@agentzh agentzh closed this Apr 8, 2013
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment