[PATCH] always process short preread body

Thu Sep 25 03:56:02 MSD 2008

John Fremlin <john at fremlin.org> writes:
> We are using nginx/0.6.22 on Ubuntu hardy or intrepid, i386 or
> amd64. nginx is in front of a mongrels rails app.
>
> For one particular request, the response from the rails app is received
> by nginx, with the header and the body together in one readv(2). However
> it waits for 60s and then sends out only the header to the client,
> without the body, but with the correct Content-Length, as if the body
> were included!
>
> This happens every time for this request but POSTs to other URLs
> resulting in 302 work fine.

The problem seems to be caused because the body gets stuck inside the
ngx_event_pipe. This patch fixes the problem. Any comments or
suggestions?

(The patch is copyright by Cerego and released under the same license as
nginx.)

-------------- next part --------------
A non-text attachment was scrubbed...
Name: nginx-0.6.32-small-proxy-body.patch
Type: text/x-diff
Size: 1246 bytes
Desc: not available
URL: <http://nginx.org/pipermail/nginx/attachments/20080925/b21847ab/attachment.patch>
-------------- next part --------------

>
> We have quite a complex config, and possibly that might be related. Any
> suggestions would be very much appreciated!
>
> Here is the strace (of nginx)
>
> 22:32:00.914649 write(3, "2008/09/21 22:32:00 [debug] 3432#0: epoll: fd:6 ev:0005 d:0000000000709271\n", 75) = 75 <0.000011>
> 22:32:00.914718 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http upstream process header\n", 68) = 68 <0.000005>
> 22:32:00.914749 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 malloc: 00000000006C7930:4096\n", 69) = 69 <0.000005>
> 22:32:00.914778 recvfrom(6, "HTTP/1.1 302 Moved Temporarily\r\nConnection: close\r\nDate: Mon, 22 Sep 2008 08:31:57 GMT\r\nSet-Cookie: uid=884s; path=/\r\nSet-Cookie: globalize_change_user_key=; path=/\r\nSet-Cookie: language_code=en; path=/\r\nSet-Cookie: _iknow_sid=baa1d09712a041eca1edb7f6c273ea96; path=/; expires=Mon, 06 Oct 2008 06:53:39 GMT\r\nStatus: 302 Found\r\nLocation: http://localhost/list/100005/build\r\nX-Runtime: 1.55355\r\nCache-Control: no-cache\r\nServer: Mongrel 1.0.1\r\nContent-Type: text/html; charset=utf-8\r\nContent-Length: 100\r\n\r\n<html><body>You are being <a href=\"http://localhost/list/100005/build\">redirected</a>.</body></html>", 4096, 0, NULL, NULL) = 604 <0.000006>
>
>
>
>
> 22:32:00.914845 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 recv: fd:6 604 of 4096\n", 62) = 62 <0.000005>
> 22:32:00.914875 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy status 302 \"302 Moved Temporarily\"\n", 85) = 85 <0.000005>
> 22:32:00.914907 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Connection: close\"\n", 78) = 78 <0.000005>
> 22:32:00.914937 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Date: Mon, 22 Sep 2008 08:31:57 GMT\"\n", 96) = 96 <0.000019>
> 22:32:00.914983 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Set-Cookie: uid=884s; path=/\"\n", 89) = 89 <0.000005>
> 22:32:00.915015 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Set-Cookie: globalize_change_user_key=; path=/\"\n", 107) = 107 <0.000005>
> 22:32:00.915047 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Set-Cookie: language_code=en; path=/\"\n", 97) = 97 <0.000005>
> 22:32:00.915079 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Set-Cookie: _iknow_sid=baa1d09712a041eca1edb7f6c273ea96; path=/; expires=Mon, 06 Oct 2008 06:53:39 GMT\"\n", 163) = 163 <0.000005>
> 22:32:00.915114 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Status: 302 Found\"\n", 78) = 78 <0.000005>
> 22:32:00.915144 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Location: http://localhost/list/100005/build\"\n", 105) = 105 <0.000005>
> 22:32:00.915176 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"X-Runtime: 1.55355\"\n", 79) = 79 <0.000005>
> 22:32:00.915206 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Cache-Control: no-cache\"\n", 84) = 84 <0.000005>
> 22:32:00.915236 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Server: Mongrel 1.0.1\"\n", 82) = 82 <0.000005>
> 22:32:00.915267 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Content-Type: text/html; charset=utf-8\"\n", 99) = 99 <0.000004>
> 22:32:00.915297 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header: \"Content-Length: 100\"\n", 80) = 80 <0.000004>
> 22:32:00.915326 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http proxy header done\n", 62) = 62 <0.000005>
> 22:32:00.915365 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 malloc: 0000000000763170:4096\n", 69) = 69 <0.000005>
> 22:32:00.915396 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 HTTP/1.1 302 Moved Temporarily\r\nServer: nginx/0.6.32\r\nDate: Mon, 22 Sep 2008 08:32:00 GMT\r\nContent-Type: text/html; charset=utf-8\r\nConnection: keep-alive\r\nSet-Cookie: uid=884s; path=/\r\nSet-Cookie: globalize_change_user_key=; path=/\r\nSet-Cookie: language_code=en; path=/\r\nSet-Cookie: _iknow_sid=baa1d09712a041eca1edb7f6c273ea96; path=/; expires=Mon, 06 Oct 2008 06:53:39 GMT\r\nStatus: 302 Found\r\nLocation: http://localhost/list/100005/build\r\nX-Runtime: 1.55355\r\nCache-Control: no-cache\r\nContent-Length: 100\r\n\n\n", 547) = 547 <0.000005>
> 22:32:00.915456 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 write new buf t:1 f:0 00000000007631B0, pos 00000000007631B0, size: 508 file: 0, size: 0\n", 128) = 128 <0.000006>
> 22:32:00.915498 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http write filter: l:0 f:0 s:508\n", 72) = 72 <0.000005>
> 22:32:00.915531 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http upstream process upstream\n", 70) = 70 <0.000005>
> 22:32:00.915559 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe read upstream: 1\n", 61) = 61 <0.000005>
> 22:32:00.915587 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe preread: 100\n", 57) = 57 <0.000005>
> 22:32:00.915615 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 readv: 1:3492\n", 53) = 53 <0.000005>
> 22:32:00.915641 readv(6, 0x7fff756d69b0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
> 22:32:00.915669 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 readv() not ready (11: Resource temporarily unavailable)\n", 96) = 96 <0.000004>
> 22:32:00.915699 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe recv chain: -2\n", 59) = 59 <0.000005>
> 22:32:00.915727 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe buf free s:0 t:1 f:0 00000000006C7930, pos 00000000006C7B28, size: 100 file: 0, size: 0\n", 132) = 132 <0.000005>
> 22:32:00.915760 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe write downstream: 1\n", 64) = 64 <0.000004>
> 22:32:00.915787 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe write busy: 0\n", 58) = 58 <0.000005>
> 22:32:00.915815 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe write: out:0000000000000000, f:0\n", 77) = 77 <0.000005>
> 22:32:00.915843 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe read upstream: 0\n", 61) = 61 <0.000005>
> 22:32:00.915871 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 pipe buf free s:0 t:1 f:0 00000000006C7930, pos 00000000006C7B28, size: 100 file: 0, size: 0\n", 132) = 132 <0.000005>
> 22:32:00.915904 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 event timer del: 6: 1222072377084\n", 73) = 73 <0.000005>
> 22:32:00.915933 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 event timer add: 6: 60000:1222072380914\n", 79) = 79 <0.000005>
> 22:32:00.915963 write(3, "2008/09/21 22:32:00 [debug] 3432#0: *4 http upstream dummy handler\n", 67) = 67 <0.000005>
> 22:32:00.915991 write(3, "2008/09/21 22:32:00 [debug] 3432#0: timer delta: 3830\n", 54) = 54 <0.000005>
> 22:32:00.916018 write(3, "2008/09/21 22:32:00 [debug] 3432#0: posted events 0000000000000000\n", 67) = 67 <0.000005>
> 22:32:00.916046 write(3, "2008/09/21 22:32:00 [debug] 3432#0: worker cycle\n", 49) = 49 <0.000005>
> 22:32:00.916073 write(3, "2008/09/21 22:32:00 [debug] 3432#0: epoll timer: 60000\n", 55) = 55 <0.000005>
>
>
>
>
>
> Why not respond now!?
>
>
> 22:32:00.916100 epoll_wait(8, {}, 512, 60000) = 0 <59.997826>
> 22:33:00.913995 write(3, "2008/09/21 22:33:00 [debug] 3432#0: timer delta: 59999\n", 55) = 55 <0.000010>
> 22:33:00.914046 write(3, "2008/09/21 22:33:00 [debug] 3432#0: posted events 0000000000000000\n", 67) = 67 <0.000005>
> 22:33:00.914076 write(3, "2008/09/21 22:33:00 [debug] 3432#0: worker cycle\n", 49) = 49 <0.000005>
> 22:33:00.914104 write(3, "2008/09/21 22:33:00 [debug] 3432#0: epoll timer: 1\n", 51) = 51 <0.000005>
> 22:33:00.914131 epoll_wait(8, {}, 512, 1) = 0 <0.010455>
> 22:33:00.924637 write(3, "2008/09/21 22:33:00 [debug] 3432#0: timer delta: 11\n", 52) = 52 <0.000008>
> 22:33:00.924693 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 event timer del: 6: 1222072380914\n", 73) = 73 <0.000005>
> 22:33:00.924723 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http upstream process upstream\n", 70) = 70 <0.000005>
> 22:33:00.924760 write(3, "2008/09/21 22:33:00 [error] 3432#0: *4 upstream timed out (110: Connection timed out) while reading upstream, client: 127.0.0.1, server: www.iknow.co.jp, request: \"POST /lists/new/theme HTTP/1.1\", upstream: \"http://127.0.0.1:3000/lists/new/theme\", host: \"localhost\", referrer: \"http://localhost/lists/new\"\n", 306) = 306 <0.000005>
> 22:33:00.924806 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http upstream exit: 0000000000000000\n", 76) = 76 <0.000027>
> 22:33:00.924858 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 finalize http upstream request: 0\n", 73) = 73 <0.000005>
> 22:33:00.924902 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 finalize http proxy request\n", 67) = 67 <0.000005>
> 22:33:00.924931 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 free rr peer 1 0\n", 56) = 56 <0.000005>
> 22:33:00.924959 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 close http upstream connection: 6\n", 73) = 73 <0.000005>
> 22:33:00.924987 close(6)                = 0 <0.000034>
> 22:33:00.925040 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http upstream temp fd: -1\n", 65) = 65 <0.000005>
> 22:33:00.925071 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http output filter \"/lists/new/theme?\"\n", 78) = 78 <0.000005>
> 22:33:00.925101 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 copy filter: \"/lists/new/theme?\"\n", 72) = 72 <0.000005>
> 22:33:00.925132 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http postpone filter \"/lists/new/theme?\" 00007FFF756D6D20\n", 97) = 97 <0.000005>
> 22:33:00.925163 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http postpone filter out \"/lists/new/theme?\"\n", 84) = 84 <0.000005>
> 22:33:00.925195 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 write old buf t:1 f:0 00000000007631B0, pos 00000000007631B0, size: 508 file: 0, size: 0\n", 128) = 128 <0.000005>
> 22:33:00.925229 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0\n", 126) = 126 <0.000005>
> 22:33:00.925262 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http write filter: l:1 f:0 s:508\n", 72) = 72 <0.000005>
> 22:33:00.925290 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http write filter limit 0\n", 65) = 65 <0.000005>
> 22:33:00.925319 writev(10, [{"HTTP/1.1 302 Moved Temporarily\r\nServer: nginx/0.6.32\r\nDate: Mon, 22 Sep 2008 08:32:00 GMT\r\nContent-Type: text/html; charset=utf-8\r\nConnection: keep-alive\r\nSet-Cookie: uid=884s; path=/\r\nSet-Cookie: globalize_change_user_key=; path=/\r\nSet-Cookie: language_code=en; path=/\r\nSet-Cookie: _iknow_sid=baa1d09712a041eca1edb7f6c273ea96; path=/; expires=Mon, 06 Oct 2008 06:53:39 GMT\r\nStatus: 302 Found\r\nLocation: http://localhost/list/100005/build\r\nX-Runtime: 1.55355\r\nCache-Control: no-cache\r\nContent-Length: 100\r\n\r\n", 508}], 1) = 508 <0.000100>
>
>
> The body is not sent!
>
>
>
> 22:33:00.925480 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 writev: 508\n", 51) = 51 <0.000004>
> 22:33:00.925510 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http write filter 0000000000000000\n", 74) = 74 <0.000005>
> 22:33:00.925540 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 copy filter: 0 \"/lists/new/theme?\"\n", 74) = 74 <0.000005>
> 22:33:00.925569 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http finalize request: 0, \"/lists/new/theme?\"\n", 85) = 85 <0.000005>
> 22:33:00.925600 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 set http keepalive handler\n", 66) = 66 <0.000005>
> 22:33:00.925629 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http close request\n", 58) = 58 <0.000005>
> 22:33:00.925657 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http log handler\n", 56) = 56 <0.000005>
> 22:33:00.925690 write(4, "127.0.0.1 - - [21/Sep/2008:22:33:00 -1000] \"POST /lists/new/theme HTTP/1.1\" 302 0 \"http://localhost/lists/new\" \"Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.0.1) Gecko/2008072820 Ubuntu/8.10 (intrepid) Firefox/3.0.1\" 63.844 \"-\" \"localhost\" \"-\" [_iknow_sid=baa1d09712a041eca1edb7f6c273ea96; Navicast_SessID=j8965.5ee1aa6e647d84.www2; language_code=en; ysm_bbk1SGMN8HHSPL0MNUPLPM0FI4M7BS=13172008; uid=884s; globalize_change_user_key=]\n", 438) = 438 <0.000009>
> 22:33:00.925749 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 free: 00000000006C7930\n", 62) = 62 <0.000005>
> 22:33:00.925778 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 free: 00000000006C5910, unused: 0\n", 73) = 73 <0.000005>
> 22:33:00.925807 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 free: 00000000006C6920, unused: 16\n", 74) = 74 <0.000005>
> 22:33:00.925837 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 free: 0000000000763170, unused: 3049\n", 76) = 76 <0.000005>
> 22:33:00.925874 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 event timer add: 10: 75000:1222072455924\n", 80) = 80 <0.000005>
> 22:33:00.925904 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 free: 00000000006CD330\n", 62) = 62 <0.000005>
> 22:33:00.925933 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 free: 00000000006CCD50\n", 62) = 62 <0.000005>
> 22:33:00.925961 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 hc free: 0000000000000000 0\n", 67) = 67 <0.000005>
> 22:33:00.925989 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 hc busy: 0000000000000000 0\n", 67) = 67 <0.000005>
> 22:33:00.926018 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 post event 000000000072F2F0\n", 67) = 67 <0.000005>
> 22:33:00.926047 write(3, "2008/09/21 22:33:00 [debug] 3432#0: posted events 000000000072F2F0\n", 67) = 67 <0.000004>
> 22:33:00.926075 write(3, "2008/09/21 22:33:00 [debug] 3432#0: posted event 000000000072F2F0\n", 66) = 66 <0.000005>
> 22:33:00.926104 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 delete posted event 000000000072F2F0\n", 76) = 76 <0.000005>
> 22:33:00.926133 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 http keepalive handler\n", 62) = 62 <0.000005>
> 22:33:00.926161 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 malloc: 00000000006CCD50:1024\n", 69) = 69 <0.000005>
> 22:33:00.926191 recvfrom(10, 0x6ccd50, 1024, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000003>
> 22:33:00.926215 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 recv: fd:10 -1 of 1024\n", 62) = 62 <0.000005>
> 22:33:00.926245 write(3, "2008/09/21 22:33:00 [debug] 3432#0: *4 recv() not ready (11: Resource temporarily unavailable)\n", 95) = 95 <0.000005>
> 22:33:00.926275 write(3, "2008/09/21 22:33:00 [debug] 3432#0: posted event 0000000000000000\n", 66) = 66 <0.000005>
> 22:33:00.926303 write(3, "2008/09/21 22:33:00 [debug] 3432#0: worker cycle\n", 49) = 49 <0.000005>
> 22:33:00.926331 write(3, "2008/09/21 22:33:00 [debug] 3432#0: epoll timer: 75000\n", 55) = 55 <0.000005>
> 22:33:00.926358 epoll_wait(8, {}, 512, 75000) = 0 <74.998182>
> 22:34:15.924609 write(3, "2008/09/21 22:34:15 [debug] 3432#0: timer delta: 75000\n", 55) = 55 <0.000010>
> 22:34:15.924661 write(3, "2008/09/21 22:34:15 [debug] 3432#0: *4 event timer del: 10: 1222072455924\n", 74) = 74 <0.000005>
> 22:34:15.924692 write(3, "2008/09/21 22:34:15 [debug] 3432#0: *4 http keepalive handler\n", 62) = 62 <0.000005>
> 22:34:15.924720 write(3, "2008/09/21 22:34:15 [debug] 3432#0: *4 close http connection: 10\n", 65) = 65 <0.000005>
> 22:34:15.924749 close(10)               = 0 <0.000102>