Custom event + timer regressions caused by the new release (Was Re: nginx-0.8.21)

[agentzh]

On Tue, Oct 27, 2009 at 4:27 PM, agentzh <agentzh at gmail.com> wrote:
>
> Sigh. All the regression tests for my "echo" module's echo_sleep in
> subrequests are hanging with this nginx version.
>

Sorry, the failures should be rephrased a bit:

"All the regression tests for my "echo" module's echo_sleep directive
that is used in subrequests chained by "post_subrequest" callback
accepted by ngx_http_subrequest."

Basically, it's a subrequest calling chain:

   /main content handler
        --> calls ngx_http_subrequest /sub1
        --> returns
   /sub1 content handler
        --> sleeps
        --> returns
   /sub1 post_subrequest called in /sub's own ngx_http_finalize_request call
        --> calls back /main content handler
   /main content handler resumed
        -- calls ngx_http_subrequest /sub2
        -- returns
   /sub2 content handler
        -- sleeps again
        -- returns
   /sub2 post_subrequest called in /sub2's own ngx_http_finalize_request call
        --> calls back /main content handler
        --> returns
   /main content handler resumed
        -- returns

It can be viewed as a calling chain using the Continuation Passing
Style where the "post_subrequest" argument fed into
ngx_http_subrequest is the "continuation" object being passed along.

In "echo" module's terms, the corresponding configuration looks like this:

    location /main {
        echo_reset_timer;
        echo_subrequest GET /sub1;
        echo_subrequest GET /sub2;
        echo "took $echo_timer_elapsed sec for total.";
    }
    location /sub1 {
        echo_sleep 0.02;
        echo hello;
    }
    location /sub2 {
        echo_sleep 0.01;
        echo world;
    }

Calling GET /main will hang in nginx 0.8.21 but not for those previous versions.

In my error.log, I can see the following additional messages when
using 0.8.21 after subrequest /sub2 completes and /main starts to
resume (for the last time):

2009/10/27 17:36:59 [debug] 16885#0: posted events 00000000
2009/10/27 17:36:59 [debug] 16885#0: worker cycle
2009/10/27 17:36:59 [debug] 16885#0: epoll timer: 59969
2009/10/27 17:37:01 [debug] 16885#0: epoll: fd:3 ev:0001 d:088C90C0
2009/10/27 17:37:01 [debug] 16885#0: *1 http run request: "/main?"
2009/10/27 17:37:01 [debug] 16885#0: *1 http test reading
2009/10/27 17:37:01 [info] 16885#0: *1 client closed prematurely
connection, client: 127.0.0.1, server: localhost, request: "GET /main
HTTP/1.1", host: "localhost:1984"
2009/10/27 17:37:01 [debug] 16885#0: *1 http finalize request: 0,
"/main?" a:1, c:1
2009/10/27 17:37:01 [debug] 16885#0: *1 http terminate request count:1

Sorry for exposing so many details. The manifest is more complicated
than I originally believed. "sleep" works in ordinary "parallel
subrequests" by the way :)

Thanks!
-agentzh