r->headers_out.status = 0

[Anatoli Marinov]

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