Hello!

On Mon, Sep 26, 2011 at 10:46:53AM +0300, Anatoli Marinov wrote:

> Thank you M-r Dounin,
>
> The attached file is the cached entry which I have. The file is
> different from the one in log file but the behaviour is the same.
> Today I have 4 return codes with 0 and all of them are only for this file!
> What should be wrong? Please advise me where I may add more log
> messages to isolate the issue. If I found the reason I will be able
> to fix it.

Cache file you've attached looks fine and works ok here. I need
corresponding debug log to investigate further.

BTW, do you have any local patches? If yes, you may want to
revert them and try to reproduce the problem with unmodified nginx.

Maxim Dounin

>
> Thanks in advance.
> Anatoli Marinov
>
>
>
> On 09/21/2011 07:19 PM, Maxim Dounin wrote:
> >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
>


> _______________________________________________
> 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