feature: when a timer fails to run we now log the location of its function's definition.

Signed-off-by: Thibault Charbonnier <thibaultcha@me.com>

Author: spacewander

src/ngx_http_lua_timer.c

@@ -16,6 +16,9 @@
 #include "ngx_http_lua_probe.h"
 
 
+#define NGX_HTTP_LUA_TIMER_ERRBUF_SIZE  128
+
+
 typedef struct {
     void        **main_conf;
     void        **srv_conf;
@@ -559,12 +562,20 @@ ngx_http_lua_timer_handler(ngx_event_t *ev)
     ngx_http_lua_main_conf_t        *lmcf;
     ngx_http_core_loc_conf_t        *clcf;
 
+    lua_Debug                ar;
+    u_char                  *p;
+    u_char                   errbuf[NGX_HTTP_LUA_TIMER_ERRBUF_SIZE];
+    const char              *source;
+    const char              *errmsg;
+
     ngx_log_debug0(NGX_LOG_DEBUG_HTTP, ngx_cycle->log, 0,
                    "lua ngx.timer expired");
 
     ngx_memcpy(&tctx, ev->data, sizeof(ngx_http_lua_timer_ctx_t));
     ngx_free(ev);
 
+    ngx_http_lua_assert(tctx.co_ref && tctx.co);
+
     lmcf = tctx.lmcf;
 
     lmcf->pending_timers--;
@@ -579,17 +590,17 @@ ngx_http_lua_timer_handler(ngx_event_t *ev)
     }
 
     if (lmcf->running_timers >= lmcf->max_running_timers) {
-        ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, 0,
-                      "%i lua_max_running_timers are not enough",
-                      lmcf->max_running_timers);
+        p = ngx_snprintf(errbuf, NGX_HTTP_LUA_TIMER_ERRBUF_SIZE - 1,
+                         "%i lua_max_running_timers are not enough",
+                         lmcf->max_running_timers);
+        *p = '\0';
+        errmsg = (const char *) errbuf;
         goto failed;
     }
 
     c = ngx_http_lua_create_fake_connection(tctx.pool);
     if (c == NULL) {
-        ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, 0,
-                      "failed to create fake connection to run timer (co: %p)",
-                      tctx.co);
+        errmsg = "could not create fake connection";
         goto failed;
     }
 
@@ -601,9 +612,7 @@ ngx_http_lua_timer_handler(ngx_event_t *ev)
 
     r = ngx_http_lua_create_fake_request(c);
     if (r == NULL) {
-        ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, 0,
-                      "failed to create fake request to run timer (co: %p)",
-                      tctx.co);
+        errmsg = "could not create fake request";
         goto failed;
     }
 
@@ -624,8 +633,7 @@ ngx_http_lua_timer_handler(ngx_event_t *ev)
 
     ctx = ngx_http_lua_create_ctx(r);
     if (ctx == NULL) {
-        ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, 0,
-                      "failed to create ctx to run timer (co: %p)", tctx.co);
+        errmsg = "could not create ctx";
         goto failed;
     }
 
@@ -634,9 +642,7 @@ ngx_http_lua_timer_handler(ngx_event_t *ev)
 
         pcln = ngx_pool_cleanup_add(r->pool, 0);
         if (pcln == NULL) {
-            ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, 0,
-                          "failed to add vm cleanup to run timer (co: %p)",
-                          tctx.co);
+            errmsg = "could not add vm cleanup";
             goto failed;
         }
 
@@ -650,9 +656,7 @@ ngx_http_lua_timer_handler(ngx_event_t *ev)
 
     cln = ngx_http_cleanup_add(r, 0);
     if (cln == NULL) {
-        ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, 0,
-                      "failed to add request cleanup to run timer (co: %p)",
-                      tctx.co);
+        errmsg = "could not add request cleanup";
         goto failed;
     }
 
@@ -709,14 +713,25 @@ ngx_http_lua_timer_handler(ngx_event_t *ev)
 
 failed:
 
-    if (tctx.co_ref && tctx.co) {
-        lua_pushlightuserdata(tctx.co, ngx_http_lua_lightudata_mask(
-                              coroutines_key));
-        lua_rawget(tctx.co, LUA_REGISTRYINDEX);
-        luaL_unref(tctx.co, -1, tctx.co_ref);
-        lua_settop(tctx.co, 0);
+    /* co stack: func [args] */
+    lua_getinfo(tctx.co, ">Sf", &ar);
+
+    source = ar.source;
+
+    if (source == NULL) {
+        source = "(unknown)";
     }
 
+    ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, 0,
+                  "lua failed to run timer with function defined at %s:%d: %s",
+                  source, ar.linedefined, errmsg);
+
+    lua_pushlightuserdata(tctx.co, ngx_http_lua_lightudata_mask(
+                          coroutines_key));
+    lua_rawget(tctx.co, LUA_REGISTRYINDEX);
+    luaL_unref(tctx.co, -1, tctx.co_ref);
+    lua_settop(tctx.co, 0);
+
     if (tctx.vm_state) {
         ngx_http_lua_cleanup_vm(tctx.vm_state);
     }

t/106-timer.t

@@ -12,7 +12,7 @@ our $StapScript = $t::StapThread::StapScript;
 
 repeat_each(2);
 
-plan tests => repeat_each() * (blocks() * 8 + 72);
+plan tests => repeat_each() * (blocks() * 8 + 63);
 
 #no_diff();
 no_long_string();
@@ -1932,7 +1932,7 @@ registered timer
 
 --- error_log eval
 [
-qr/\[alert\] .*? 1 lua_max_running_timers are not enough/,
+qr/\[alert\] .*? lua failed to run timer with function defined at =content_by_lua\(nginx.conf:\d+\):10: 1 lua_max_running_timers are not enough/,
 "lua ngx.timer expired",
 "http lua close fake http connection",
 ]
@@ -2193,3 +2193,132 @@ ok
 --- error_log
 Bad bad bad
 --- skip_nginx: 4: < 1.7.1
+
+
+
+=== TEST 33: log function location when failed to run a timer
+--- http_config
+    lua_max_running_timers 1;
+--- config
+    location /t {
+        content_by_lua_block {
+            local function g()
+                ngx.sleep(0.01)
+            end
+
+            local function f()
+                ngx.sleep(0.01)
+            end
+
+            local ok, err = ngx.timer.at(0, f)
+            if not ok then
+                ngx.say("failed to create timer f: ", err)
+                return
+            end
+
+            local ok, err = ngx.timer.at(0, g)
+            if not ok then
+                ngx.say("failed to create timer g: ", err)
+                return
+            end
+
+            ngx.say("ok")
+        }
+    }
+--- request
+GET /t
+--- response_body
+ok
+--- wait: 0.1
+--- error_log eval
+qr/\[alert\] .*? lua failed to run timer with function defined at =content_by_lua\(nginx.conf:\d+\):2: 1 lua_max_running_timers are not enough/
+--- no_error_log
+[crit]
+[error]
+
+
+
+=== TEST 34: log function location when failed to run a timer (anonymous function)
+--- http_config
+    lua_max_running_timers 1;
+--- config
+    location /t {
+        content_by_lua_block {
+            local function f()
+                ngx.sleep(0.01)
+            end
+
+            local ok, err = ngx.timer.at(0, f)
+            if not ok then
+                ngx.say("failed to set timer f: ", err)
+                return
+            end
+
+            local ok, err = ngx.timer.at(0, function()
+                ngx.sleep(0.01)
+            end)
+
+            if not ok then
+                ngx.say("failed to set timer: ", err)
+                return
+            end
+
+            ngx.say("ok")
+        }
+    }
+--- request
+GET /t
+--- response_body
+ok
+--- wait: 0.1
+--- error_log eval
+qr/\[alert\] .*? lua failed to run timer with function defined at =content_by_lua\(nginx.conf:\d+\):12: 1 lua_max_running_timers are not enough/
+--- no_error_log
+[crit]
+[error]
+
+
+
+=== TEST 35: log function location when failed to run a timer (lua file)
+--- user_files
+>>> test.lua
+local _M = {}
+
+function _M.run()
+    ngx.sleep(0.01)
+end
+
+return _M
+--- http_config
+    lua_package_path '$TEST_NGINX_HTML_DIR/?.lua;./?.lua;;';
+    lua_max_running_timers 1;
+--- config
+    location /t {
+        content_by_lua_block {
+            local test = require "test"
+
+            local ok, err = ngx.timer.at(0, test.run)
+            if not ok then
+                ngx.say("failed to set timer: ", err)
+                return
+            end
+
+            local ok, err = ngx.timer.at(0, test.run)
+            if not ok then
+                ngx.say("failed to set timer: ", err)
+                return
+            end
+
+            ngx.say("ok")
+        }
+    }
+--- request
+GET /t
+--- response_body
+ok
+--- wait: 0.1
+--- no_error_log
+[crit]
+[error]
+--- error_log eval
+qr/\[alert\] .*? lua failed to run timer with function defined at @.+\/test.lua:3: 1 lua_max_running_timers are not enough/