r->headers_out.status = 0

Mon Sep 26 07:46:53 UTC 2011

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.

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 at nginx.org
>> http://mailman.nginx.org/mailman/listinfo/nginx-devel
> _______________________________________________
> nginx-devel mailing list
> nginx-devel at nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx-devel

-------------- next part --------------
A non-text attachment was scrubbed...
Name: 8d479f2f4ae1c5712ab76e0aafc7993d
Type: application/octet-stream
Size: 5119 bytes
Desc: not available
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20110926/c1e604ee/attachment.obj>