Hello!

On Wed, Sep 21, 2011 at 03:18:05PM +0300, Anatoli Marinov wrote:

> Hello colleagues,
> Last week I wrote a module that generates custom access log and in
> general it works fine. I found several records with status core 0.
> In my test bed I have clear nginx 1.0.4 installation with configured
> proxy_cache. The instance is used as a reverse proxy.
>
> I found a strange case when in the log phase my log module receives
> r->headers_out.status == 0, r->connection->sent also is 0. What
> could be the reason for these values?
>
> In the log file I found :
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy status 200 "200 OK"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Server: nginx 1.0.4"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header: "Date:
> Wed, 21 Sep 2011 11:40:20 GMT"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Content-Type: application/octet-stream"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Connection: close"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Content-Length: 4312"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Last-Modified: Thu, 24 Mar 2011 14:32:53 GMT"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Expires: Wed, 21 Sep 2011 11:45:18 GMT"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Cache-Control: max-age=300"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Accept-Ranges: bytes"
>
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http finalize request:
> -2, "/s/169/file_906?" a:1, c:2
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http request count:2 blk:0
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http finalize request:
> -4, "/s/169/file_906?" a:1, c:1
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 set http keepalive handler
>
> First finalise request is called with NGX_AGAIN and second immediate
> call is made with NGX_DONE.
> There is not success at all and the client does not receive the file.
>
> Whole log segment:
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 delete posted event 962CE210
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 malloc: 0810BBE8:664
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 malloc: 081136D8:1024
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 posix_memalign: 08182280:8192 @16
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http process request line
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 recv: fd:20 64 of 1024
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http request line: "GET
> /s/169/file_906 HTTP/1.1"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http uri: "/s/169/file_906"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http args: ""
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http exten: ""
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http process request header line
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http header: "Host:
> alabalanica.info"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http header done
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 rewrite phase: 0
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 test location: "/"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 using configuration "/"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http cl:-1 max:1024
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 rewrite phase: 2
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 rewrite phase: 3
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 rewrite phase: 4
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 rewrite phase: 5
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 rewrite phase: 6
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http script complex value
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 post rewrite phase: 7
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 access phase: 8
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 access phase: 9
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 post access phase: 10
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http init upstream,
> client timer: 0
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 epoll add event: fd:20
> op:3 ev:80000005
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http script copy: "1.1"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http script var:
> "/s/169/file_906"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http cache key:
> "1.1/s/169/file_906"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 add cleanup: 08182CE0
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http file cache exists: 0 e:1
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 cache file:
> "/cache/59/eb/5d23017f16d094f3c0da5caad144eb59"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 add cleanup: 08182D20
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http file cache fd: 18
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 read: 18, 08182D6C, 355, 0
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http upstream cache: 0
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy status 200 "200 OK"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Server: nginx 1.0.4"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header: "Date:
> Wed, 21 Sep 2011 11:40:20 GMT"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Content-Type: application/octet-stream"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Connection: close"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Content-Length: 4312"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Last-Modified: Thu, 24 Mar 2011 14:32:53 GMT"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Expires: Wed, 21 Sep 2011 11:45:18 GMT"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Cache-Control: max-age=300"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http proxy header:
> "Accept-Ranges: bytes"
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http finalize request:
> -2, "/s/169/file_906?" a:1, c:2

Looks like cache item is corrupted and this isn't properly
handled. Could you please provide contents of

/cache/59/eb/5d23017f16d094f3c0da5caad144eb59

?

> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http request count:2 blk:0
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http finalize request:
> -4, "/s/169/file_906?" a:1, c:1
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 set http keepalive handler
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http close request
> 2011/09/21 11:40:21 [debug] 9246#0: *18075 http log handler
> 2011/09/21 11:40:21 [debug] 9246#0: *18075
> ngx_http_write_statistic:141 - r->uri.len [15] r->uri.data
> [/s/169/file_906]
> 2011/09/21 11:40:21 [debug] 9246#0: *18075
> ngx_http_write_statistic:160 - r->connection->sent [0]
> 2011/09/21 11:40:21 [debug] 9246#0: *18075
> ngx_http_write_statistic:164 - r->headers_out.status [0]
>
> What could be the reason for this behaviour?
>
> Thanks in advance
> Toli
>
>
> _______________________________________________
> nginx-devel mailing list
> nginx-devel@nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx-devel

_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-devel