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!
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
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
which repeats with http static fd incremented each time until file descriptors
run out and it reaches a steady state:
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: 00007FC6418DDDB0
2013/01/20 11:28:13 [crit] 11635#0: *7 open() "/usr/local/nginx/html/50x.html" failed (24: Too many open files) 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: 500, "/50x.html?" a:1, c:3
2013/01/20 11:28:13 [debug] 11635#0: *7 http special response: 500, "/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
I expect I can deal with this in my module, but how come there's no
handler of last resort that would prevent this happening?
--
Nick Kew
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-devel
