timer not cancelled with `premature`

thijs · 2016-01-26T09:24:07+00:00

Hello, everyone,Today I have a problem when building OpenResty projects.When I entered into the OpenResty release dir, and do the "make" command to...

timer not cancelled with `premature`

thijs

when running this code (snippet)

local do_timer
do_timer = function(premature)
    local ok, err
errlog("doing a timer")    
    if premature then
errlog("exiting premature...")      
        _M.post(MODULE_NAME, EVENT_EXIT)
    end
    
    _M.poll()
    
    if _interval ~= 0 and not premature then
        ok, err = new_timer(_interval, do_timer)
        if not ok then
            if err == "process exiting" then
errlog("exiting premature...")      
                _M.post(MODULE_NAME, EVENT_EXIT)
            end
            err = "failed to create timer: " .. tostring(err)
            errlog(err)
            return nil, err
        end
errlog("created a new timer")        
    end
    return true
end

I get unexpected results;

2016/01/25 17:15:59 [notice] 1859#0: using the "epoll" event method
2016/01/25 17:15:59 [notice] 1859#0: openresty/1.9.7.1
2016/01/25 17:15:59 [notice] 1859#0: built by gcc 4.9.2 (Debian 4.9.2-10) 
2016/01/25 17:15:59 [notice] 1859#0: OS: Linux 3.16.0-4-amd64
2016/01/25 17:15:59 [notice] 1859#0: getrlimit(RLIMIT_NOFILE): 65536:65536
2016/01/25 17:15:59 [debug] 1860#0: [lua] init_worker_by_lua:5: source=resty-worker-events, event=started, pid=1860, data="">
2016/01/25 17:15:59 [error] 1860#0: [lua] events.lua:85: errlog(): worker-events: doing a timer, context: init_worker_by_lua*
2016/01/25 17:15:59 [error] 1860#0: [lua] events.lua:85: errlog(): worker-events: created a new timer, context: init_worker_by_lua*
2016/01/25 17:16:00 [error] 1860#0: [lua] events.lua:85: errlog(): worker-events: doing a timer, context: ngx.timer
2016/01/25 17:16:00 [error] 1860#0: [lua] events.lua:85: errlog(): worker-events: created a new timer, context: ngx.timer
2016/01/25 17:16:01 [error] 1860#0: [lua] events.lua:85: errlog(): worker-events: doing a timer, context: ngx.timer
2016/01/25 17:16:01 [error] 1860#0: [lua] events.lua:85: errlog(): worker-events: created a new timer, context: ngx.timer
2016/01/25 17:16:02 [notice] 1860#0: signal 3 (SIGQUIT) received, shutting down
2016/01/25 17:16:02 [info] 1860#0: epoll_wait() failed (4: Interrupted system call)
2016/01/25 17:16:02 [notice] 1860#0: exit

What I get from the log is that the timer is not being called with the `premature` flag.

Am I missing something? any help is appreciated.

Thijs

thijs

btw; this is using the openresty test tooling

agentzh

Hello!

On Mon, Jan 25, 2016 at 5:35 PM, Thijs Schreijer wrote:
> btw; this is using the openresty test tooling
>

If you are using the Test::Nginx test scaffold, then you need to put a
"master_on();" call before "run_tests()" in the test file prologue.
This is because the premature timer invocation requires nginx graceful
shutdown which is not available when master process is disabled (which
is the default used by the Test::Nginx test scaffold).

Best regards,
-agentzh

thijs

If you are using the Test::Nginx test scaffold, then you need to put a
"master_on();" call before "run_tests()" in the test file prologue.
This is because the premature timer invocation requires nginx graceful
shutdown which is not available when master process is disabled (which
is the default used by the Test::Nginx test scaffold).

Best regards,
-agentzh

Thx! that did it.

But... still some test issues.

Here's the logout of the test;
2016/01/27 15:31:12 [notice] 5230#0: using the "epoll" event method
2016/01/27 15:31:12 [notice] 5230#0: openresty/1.9.7.1
2016/01/27 15:31:12 [notice] 5230#0: built by gcc 4.9.2 (Debian 4.9.2-10)
2016/01/27 15:31:12 [notice] 5230#0: OS: Linux 3.16.0-4-amd64
2016/01/27 15:31:12 [notice] 5230#0: getrlimit(RLIMIT_NOFILE): 65536:65536
2016/01/27 15:31:12 [notice] 5231#0: start worker processes
2016/01/27 15:31:12 [notice] 5231#0: start worker process 5232
2016/01/27 15:31:12 [debug] 5232#0: [lua] events.lua:98: debug(): worker-events: handling event; source=resty-worker-events, event=started, pid=5232, data="">2016/01/27 15:31:12 [debug] 5232#0: [lua] init_worker_by_lua:5: worker-events: handler event; source=resty-worker-events, event=started, pid=5232, data="">2016/01/27 15:31:13 [notice] 5231#0: signal 3 (SIGQUIT) received, shutting down
2016/01/27 15:31:13 [notice] 5232#0: gracefully shutting down
2016/01/27 15:31:13 [debug] 5232#0: [lua] events.lua:98: debug(): worker-events: handling event; source=resty-worker-events, event=stopping, pid=5232, data="">2016/01/27 15:31:13 [debug] 5232#0: [lua] init_worker_by_lua:5: worker-events: handler event; source=resty-worker-events, event=stopping, pid=5232, data="">2016/01/27 15:31:13 [notice] 5232#0: exiting
2016/01/27 15:31:13 [notice] 5232#0: exit
2016/01/27 15:31:13 [notice] 5231#0: signal 17 (SIGCHLD) received
2016/01/27 15:31:13 [notice] 5231#0: worker process 5232 exited with code 0
2016/01/27 15:31:13 [notice] 5231#0: exit

The test grabs: --- grep_error_log eval: qr/worker-events: .*/

But the test output shows this;

#   Failed test 'TEST 1: worker.events starting and stopping, with its own events - grep_error_log_out (req 0)'
#   at /home/thijs/perl5/lib/perl5/Test/Nginx/Socket.pm line 1041.
#                   'worker-events: handling event; source=resty-worker-events, event=started, pid=5232, data=""># worker-events: handler event; source=resty-worker-events, event=started, pid=5232, data=""># '
#     doesn't match '

So the test only grabs 2 lines from the output, where it should grab 4 imo.

any ideas?

Thijs

agentzh

Hello!

On Wed, Jan 27, 2016 at 3:52 PM, Thijs Schreijer wrote:
>
> The test grabs:   --- grep_error_log eval: qr/worker-events: .*/
>
> But the test output shows this;
>
> #   Failed test 'TEST 1: worker.events starting and stopping, with its own
> events - grep_error_log_out (req 0)'

Yes, I was about to mention this in my previous mail but forgot.
Basically the error log checking of Test::Nginx::Socket is done before
shutting down nginx (so as to support repeated_request, for example).
Maybe we should add new sections like `--- shutdown_error_log`, `---
shutdown_grep_error_log`, and etc for this?

Regards,
-agentzh

thijs


> -----Oorspronkelijk bericht-----
> Van: openresty-en@googlegroups.com [mailto:openresty-en@googlegroups.com]
> Namens Yichun Zhang (agentzh)
> Verzonden: Wednesday, 27 January, 2016 16:16
> Aan: openresty-en
> Onderwerp: Re: [openresty-en] Re: timer not cancelled with `premature`
> 
> Hello!
> 
> On Wed, Jan 27, 2016 at 3:52 PM, Thijs Schreijer wrote:
> >
> > The test grabs:   --- grep_error_log eval: qr/worker-events: .*/
> >
> > But the test output shows this;
> >
> > #   Failed test 'TEST 1: worker.events starting and stopping, with its
> own
> > events - grep_error_log_out (req 0)'
> 
> Yes, I was about to mention this in my previous mail but forgot.
> Basically the error log checking of Test::Nginx::Socket is done before
> shutting down nginx (so as to support repeated_request, for example).
> Maybe we should add new sections like `--- shutdown_error_log`, `---
> shutdown_grep_error_log`, and etc for this?
> 
> Regards,
> -agentzh

Ok. So basically nothing I can do about that at the moment. I'll document the one test marked as "--- SKIP", referring to this issue for now.

Thx.
Thijs

agentzh

Hello!

On Wed, Jan 27, 2016 at 7:23 PM, Thijs Schreijer wrote:
>
> Ok. So basically nothing I can do about that at the moment. I'll document the one test marked as "--- SKIP", referring to this issue for now.
>

Sorry, I forgot again to mention that there exists a work-around for
this which I used in ngx_lua's test suite already. Consider the
following test file:

    use Test::Nginx::Socket::Lua 'no_plan';

    repeat_each(2);

    master_on();
    run_tests();

    __DATA__

    === TEST 1: timer premature expiry
    --- http_config
        init_worker_by_lua_block {
            local function f(premature)
                print("timer fired: premature: ", premature)
            end

            local ok, err = ngx.timer.at(3600, f)
            if not ok then
                error("failed to create timer: ", err)
            end
            print("created a timer")
        }
    --- config
        location = /t {
            content_by_lua_block {
                f = assert(io.open("t/servroot/logs/nginx.pid"))
                local pid = assert(tonumber(f:read()), "read pid")
                f:close()

                local cmd = "kill -HUP " .. pid
                assert(os.execute(cmd))
            }
        }
    --- request
    GET /t
    --- error_log
    created a timer
    timer fired: premature: true
    --- response_body
    --- no_error_log
    [error]
    --- wait: 0.2

It passes successfully on my side :)

Best regards,
-agentzh

thijs

Thx for your help. Finally fixed it.

Stared at it for some hours, only to find that I missed the very last ` --- wait: 0.2 `. After adding that, it worked.

regards

Thijs

Op donderdag 28 januari 2016 05:12:43 UTC+1 schreef agentzh:

Hello!

On Wed, Jan 27, 2016 at 7:23 PM, Thijs Schreijer wrote:
>
> Ok. So basically nothing I can do about that at the moment. I'll document the one test marked as "--- SKIP", referring to this issue for now.
>

Sorry, I forgot again to mention that there exists a work-around for
this which I used in ngx_lua's test suite already. Consider the
following test file:

use Test::Nginx::Socket::Lua 'no_plan';

repeat_each(2);

master_on();
run_tests();

__DATA__

=== TEST 1: timer premature expiry
--- http_config
init_worker_by_lua_block {
local function f(premature)
print("timer fired: premature: ", premature)
end

local ok, err = ngx.timer.at(3600, f)
if not ok then
error("failed to create timer: ", err)
end
print("created a timer")
}
--- config
location = /t {
content_by_lua_block {
f = assert(io.open("t/servroot/logs/nginx.pid"))
local pid = assert(tonumber(f:read()), "read pid")
f:close()

local cmd = "kill -HUP " .. pid
assert(os.execute(cmd))
}
}
--- request
GET /t
--- error_log
created a timer
timer fired: premature: true
--- response_body
--- no_error_log
[error]
--- wait: 0.2

It passes successfully on my side :)

Best regards,
-agentzh