bugfix: timers created by ngx.timer.at() might not be aborted prematurely upon nginx worker exit. thanks Hamish Forbes for the report.

Author: agentzh

src/ngx_http_lua_timer.c

@@ -462,8 +462,8 @@ ngx_http_lua_abort_pending_timers(ngx_event_t *ev)
 
     sentinel = ngx_event_timer_rbtree.sentinel;
 
-    prev = NULL;
     cur = ngx_event_timer_rbtree.root;
+    prev = cur->parent;
 
     events = ngx_pcalloc(ngx_cycle->pool,
                          lmcf->pending_timers * sizeof(ngx_event_t));
@@ -475,14 +475,17 @@ ngx_http_lua_abort_pending_timers(ngx_event_t *ev)
 
     dd("root: %p, root parent: %p, sentinel: %p", cur, cur->parent, sentinel);
 
-    while (lmcf->pending_timers > n) {
+    while (n < lmcf->pending_timers) {
         if  (cur == sentinel || cur == NULL) {
             ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, 0,
                           "lua pending timer counter got out of sync: %i",
                           lmcf->pending_timers);
             break;
         }
 
+        dd("prev: %p, cur: %p, cur parent: %p, cur left: %p, cur right: %p",
+           prev, cur, cur->parent, cur->left, cur->right);
+
         if (prev == cur->parent) {
             next = cur->left;
             if (next == sentinel) {
@@ -519,6 +522,10 @@ ngx_http_lua_abort_pending_timers(ngx_event_t *ev)
         cur = next;
     }
 
+    ngx_log_debug1(NGX_LOG_DEBUG_HTTP, ngx_cycle->log, 0,
+                   "lua found %i pending timers to be aborted prematurely",
+                   n);
+
     for (i = 0; i < n; i++) {
         ev = events[i];
 
@@ -537,6 +544,7 @@ ngx_http_lua_abort_pending_timers(ngx_event_t *ev)
         tctx = ev->data;
         tctx->premature = 1;
 
+        dd("calling timer handler prematurely");
         ev->handler(ev);
     }
 

t/109-timer-hup.t

@@ -28,7 +28,7 @@ our $StapScript = $t::StapThread::StapScript;
 
 repeat_each(2);
 
-plan tests => repeat_each() * 60;
+plan tests => repeat_each() * 76;
 
 #no_diff();
 no_long_string();
@@ -279,3 +279,163 @@ f: exiting=true
 g: timer prematurely expired: false
 g: exiting=true
 
+
+
+=== TEST 5: HUP reload should abort pending timers
+--- config
+    location /t {
+        content_by_lua '
+            local f, err = io.open("t/servroot/logs/nginx.pid", "r")
+            if not f then
+                ngx.say("failed to open nginx.pid: ", err)
+                return
+            end
+
+            local pid = f:read()
+            -- ngx.say("master pid: [", pid, "]")
+
+            f:close()
+
+            local function f(premature)
+                print("f: timer prematurely expired: ", premature)
+                print("f: exiting=", ngx.worker.exiting())
+            end
+
+            for i = 1, 100 do
+                local ok, err = ngx.timer.at(3 + i, f)
+                if not ok then
+                    ngx.say("failed to set timer: ", err)
+                    return
+                end
+            end
+            ngx.say("ok")
+            os.execute("kill -HUP " .. pid)
+        ';
+    }
+--- request
+GET /t
+
+--- response_body
+ok
+
+--- wait: 0.3
+--- no_error_log
+[error]
+[alert]
+[crit]
+in callback: hello, 2
+failed to register a new timer after reload
+
+--- grep_error_log eval: qr/lua found \d+ pending timers/
+--- grep_error_log_out
+lua found 100 pending timers
+
+
+
+=== TEST 6: HUP reload should abort pending timers (coroutine + cosocket)
+--- http_config
+    lua_shared_dict test_dict 1m;
+
+    server {
+        listen 54123;
+        location = /foo {
+            echo 'foo';
+        }
+    }
+
+--- config
+    location /t {
+        content_by_lua '
+            local http_req = {"GET /foo HTTP/1.1", "Host: localhost:1234", "", ""}
+            http_req = table.concat(http_req, "\\r\\n")
+
+            -- Connect the socket
+            local sock = ngx.socket.tcp()
+            local ok,err = sock:connect("127.0.0.1", 54123)
+            if not ok then
+                ngx.log(ngx.ERR, err)
+            end
+
+            -- Send the request
+            local ok,err = sock:send(http_req)
+
+            -- Get Headers
+            repeat
+                local line, err = sock:receive("*l")
+            until string.find(line, "^%s*$")
+
+            function foo()
+                repeat
+                    -- Get and read chunk
+                    local line, err = sock:receive("*l")
+                    local len = tonumber(line)
+                    if len > 0 then
+                        local chunk, err = sock:receive(len)
+                        coroutine.yield(chunk)
+                        sock:receive(2)
+                    else
+                        -- Read last newline
+                        sock:receive(2)
+                    end
+                until len == 0
+            end
+
+            co = coroutine.create(foo)
+            repeat
+                local chunk = select(2,coroutine.resume(co))
+            until chunk == nil
+
+            -- Breaks the timer
+            sock:setkeepalive()
+            ngx.say("ok")
+        ';
+
+        log_by_lua '
+            local background_thread
+            background_thread = function(premature)
+                ngx.log(ngx.DEBUG, premature)
+                if premature then
+                    ngx.shared["test_dict"]:delete("background_flag")
+                    return
+                end
+                local ok, err = ngx.timer.at(1, background_thread)
+
+                local f, err = io.open("t/servroot/logs/nginx.pid", "r")
+                if not f then
+                    ngx.say("failed to open nginx.pid: ", err)
+                    return
+                end
+                local pid = f:read()
+                -- ngx.say("master pid: [", pid, "]")
+                f:close()
+
+                os.execute("kill -HUP " .. pid)
+            end
+            local dict = ngx.shared["test_dict"]
+
+            if dict:get("background_flag") == nil then
+                local ok, err = ngx.timer.at(0, background_thread)
+                if ok then
+                    dict:set("test_dict", 1)
+                end
+            end
+        ';
+    }
+--- request
+GET /t
+
+--- response_body
+ok
+
+--- wait: 0.3
+--- no_error_log
+[error]
+[alert]
+[crit]
+in callback: hello, 2
+failed to register a new timer after reload
+
+--- grep_error_log eval: qr/lua found \d+ pending timers/
+--- grep_error_log_out
+lua found 1 pending timers
+