No handler of last resort?

Sun Jan 20 22:06:19 UTC 2013

Hello!

On Sun, Jan 20, 2013 at 01:04:44PM +0000, Nick Kew wrote:

> In test-driving my plugin, I tried provoking a gateway timeout,
> whereupon I find nginx unexpectedly eats the system before
> crashing.
> 
> Executive summary: it goes into an internal redirect to serve an
> errordocument.  But the errordocument fails, leading into an
> infinite loop as it tries to invoke the error for that failure.
> It seems nginx has no handler of last resort!

There is, but it looks like output chain was broken due to some 
incorrect output filter module installed.  See below.

> The error log shows the original timeout and error:
> 
> 2013/01/20 11:17:07 [debug] 11635#0: kevent timer: 60000, changes: 3
> 2013/01/20 11:28:13 [debug] 11635#0: kevent events: 1
> 2013/01/20 11:28:13 [debug] 11635#0: kevent: 3: ft:-2 fl:0025 ff:00000000 d:146988 ud:00007FC64188B6E1
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http run request: "/?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http upstream check client, write event:1, "/"
> 2013/01/20 11:28:13 [debug] 11635#0: timer delta: 666881
> 2013/01/20 11:28:13 [debug] 11635#0: *7 event timer del: 11: 1358680687001
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http upstream request: "/?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http upstream send request handler
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http next upstream, 4
> 2013/01/20 11:28:13 [debug] 11635#0: *7 free rr peer 1 4
> 2013/01/20 11:28:13 [error] 11635#0: *7 upstream timed out (60: Operation timed out) while connecting to upstream, client: 127.0.0.1, server: localhost, request: "POST / HTTP/1.1", upstream: "http://xx.xx.xx.xx:80/", host: "127.0.0.1"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 finalize http upstream request: 504
> 2013/01/20 11:28:13 [debug] 11635#0: *7 finalize http proxy request
> 2013/01/20 11:28:13 [debug] 11635#0: *7 free rr peer 0 0
> 2013/01/20 11:28:13 [debug] 11635#0: *7 close http upstream connection: 11
> 2013/01/20 11:28:13 [debug] 11635#0: *7 free: 00007FC64142D510, unused: 48
> 2013/01/20 11:28:13 [debug] 11635#0: *7 reusable connection: 0
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http finalize request: 504, "/?" a:1, c:2
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http special response: 504, "/?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 internal redirect: "/50x.html?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 rewrite phase: 1
> 2013/01/20 11:28:13 [debug] 11635#0: *7 test location: "/"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 test location: "50x.html"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 using configuration "=/50x.html"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http cl:1034 max:1048576
> 2013/01/20 11:28:13 [debug] 11635#0: *7 rewrite phase: 3
> 2013/01/20 11:28:13 [debug] 11635#0: *7 post rewrite phase: 4
> 2013/01/20 11:28:13 [debug] 11635#0: *7 generic phase: 5
> 2013/01/20 11:28:13 [debug] 11635#0: *7 generic phase: 6
> 2013/01/20 11:28:13 [debug] 11635#0: *7 generic phase: 7
> 2013/01/20 11:28:13 [debug] 11635#0: *7 access phase: 8
> 2013/01/20 11:28:13 [debug] 11635#0: *7 access phase: 9
> 2013/01/20 11:28:13 [debug] 11635#0: *7 post access phase: 10
> 2013/01/20 11:28:13 [debug] 11635#0: *7 content phase: 11
> 2013/01/20 11:28:13 [debug] 11635#0: *7 content phase: 12

So far so good.

> leading into a loop:
> 
> 2013/01/20 11:28:13 [debug] 11635#0: *7 content phase: 13
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http filename: "/usr/local/nginx/html/50x.html"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 add cleanup: 00007FC641837E08
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http static fd: 11
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http output filter "/50x.html?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http copy filter: "/50x.html?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http copy filter: -5 "/50x.html?"
> 2013/01/20 11:28:13 [error] 11635#0: *7 no handler found while sending response to client, client: 127.0.0.1, server: localhost, request: "POST / HTTP/1.1", upstream: "http://**.**.**.**:80/", host: "127.0.0.1"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http finalize request: 404, "/50x.html?" a:1, c:3
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http special response: 404, "/50x.html?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http output filter "/50x.html?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http copy filter: "/50x.html?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http copy filter: -5 "/50x.html?"
> 2013/01/20 11:28:13 [debug] 11635#0: *7 http finalize request: -5, "/50x.html?" a:1, c:3
> 2013/01/20 11:28:13 [debug] 11635#0: *7 content phase: 13

Strange thing happens here: output filter chain returned -5,
NGX_DECLINED, which should never happen and results in an   
undefined behaviour.  I would suggest it's incorrect filter in a
chain which breaks things.

The "no handler found" error logged is already result of this (it 
should never happen unless static module isn't compiled in, which 
requires manual intervention into build process).  As output 
filter chain is broken, even returning predefined response from 
memory doesn't work - it still results in NGX_DECLINED, which 
again leads to an undefined behaviour.

Please note that it's very easy to break things by writing
incorrect code in your module.  If you see something wierd, it's 
usually good idea to try to reproduce what you see without any 
your or 3rd party modules compiled in, even if you are sure your 
module isn't guilty.

-- 
Maxim Dounin
http://nginx.com/support.html