Incorrect state after discard body for special response

[Igor Sysoev]

On Wed, Jan 28, 2009 at 01:50:10PM -0800, Eden Li wrote:

> I see nginx get into an incorrect state after it processes a request
> which has a body.  In my case it is happening when posting data to
> location which results in a redirect, the result is *TWO* responses
> returned from the connection.  It only occurs when nginx is handling
> many connections.  This problem does *NOT* occur if the request body
> is included in a single packet or if the client closes the connection
> after receiving the first response.
> 
> After switching into debug mode, I see that it tries to discard the
> request body (as expected), but the socket is not ready so it sets a
> keepalive handler.  The problem is that it goes back into the rewrite
> handler (generic phase 2) and writes the special response *again* to
> the socket.  The discard body event is not posted right away.
> 
> It seems like the event phase should be incremented or the connection
> state is incorrect after setting the keepalive handler from the
> special response handler.
> 
> Has anyone else seen this?  I don't know nginx well enough to know if
> I can fix this there or what part of my configuration to change.
> 
> 
> Below is a debug log of the connection:
> 
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 generic phase: 2
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http script regex: "^/(.*)$"
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http script copy: "http://host/"
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http script capture:
> "http://host/uri"
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http script regex end
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http finalize request: 302, "/uri?"
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http special response: 302, "/uri"
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http set discard body
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http read discarded body
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 recv: fd:34 -1 of 1
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 recv() not ready (11:
> Resource temporarily unavailable)
> 
> <snip>
> 
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 writev: 462
> 
> <snip>
> 
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http finalize request: 0, "/host/uri"
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 set http keepalive handler
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 event timer add: 34:
> 5000:1233176245399
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 generic phase: 2
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 http script regex: "^/(.*)$"
> 
> <snip, same as above, until, notice *TWO* `Location:` headers below>
> 
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 HTTP/1.1 302 Moved Temporarily
> Server: nginx
> Date: Wed, 28 Jan 2009 20:57:20 GMT
> Content-Type: text/html
> Content-Length: 154
> Connection: keep-alive
> Location: http://host/uri
> Expires: Wed, 28 Jan 2009 20:57:19 GMT
> Cache-Control: no-cache
> Location: http://host/uri
> 
> <snip>
> 
> 2009/01/28 12:57:20 [debug] 19443#0: *4852 writev: 549

I could not reproduce this on 0.6.35. Could you send me the whole log ?


-- 
Igor Sysoev
http://sysoev.ru/en/