r->headers_out.status = 0
Anatoli Marinov
toli at webforge.bg
Thu Sep 29 10:00:20 UTC 2011
I invested more time to investigate the issue and I found something.
Let's assume there is 2 nginx workers with pids 6362 and 6364 (they are
actually 4 but only these 2 are interested).
There are 3 parallel requests 10102, 10188 and 10232 for one and the
same file.
See the scenario. It describes the issue:
--- context switch to 6362---
6362 - 10102 - begin (connection accepted)
6362 - 10102 - file do not exist in the cache
6362 - 10102 - upstream peer found
--- context switch to 6364 ---
6364 - 10188 - begin (connection accepted)
6364 - 10188 - file do not exist in the cache
6364 - 10188 - upstream peer found
6364 - 10188 - header received (header size 369 bytes)
6364 - 10188 - file received
6364 - 10188 - file renamed (with header size 369 bytes)
6364 - 10188 - shared mem updated - header size 369 bytes
6364 - 10188 - success end
--- context switch to 6362 ---
6362 - 10102 - header received (header size 373 bytes)
6362 - 10102 - file received
6362 - 10102 - file renamed (with header size 373 bytes)
shared memory is not updated because the cpu context is switched or
the process works in parallel on different cpu
--- context switch to 6364 ---
6364 - 10232 - begin (connection accepted)
6364 - 10232 - record is found in shared memory - file exists (header
size is 369 from shared mem)
6364 - 10232 - header is read from the file (but only first 369 bytes)
--- context switch to 6362 ---
6362 - 10102 - shared mem updated - header size 373 bytes
....
....
--- context switch to 6364 ---
6364 - 10232 - http header could not be parsed because there are missing
4 bytes
6364 - 10232 - failed end
See the attached file. The scenario it taken from it.
In general it is very hard for reproduction.
I hit is 2-3 times for 10 000 000 requests. But the issue exists :).
Cheers
Toli
On 09/26/2011 02:09 PM, Maxim Dounin wrote:
> 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 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
>
>> _______________________________________________
>> 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: 1.log
Type: text/x-log
Size: 48715 bytes
Desc: not available
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20110929/1e9c8406/attachment-0001.bin>
More information about the nginx-devel
mailing list