policy.DEBUG_IF: avoid creating new callbacks on every request

This new approach uses per-request variables in Lua and creates new
callback for each DEBUG_IF call instead of each request.

diff --git a/daemon/lua/kres-gen.lua b/daemon/lua/kres-gen.lua
index 2a94e4d2445427c3a52afaa0b30722d4620bf0f3..37743387596be1a4e94a9caa601d1cae12135df7 100644 (file)
--- a/daemon/lua/kres-gen.lua
+++ b/daemon/lua/kres-gen.lua
@@ -15,7 +15,7 @@ typedef struct knot_mm {
 
 typedef void *(*map_alloc_f)(void *, size_t);
 typedef void (*map_free_f)(void *baton, void *ptr);
-typedef void (*trace_log_f) (const char *);
+typedef void (*trace_log_f) (const struct kr_request *, const char *);
 typedef void (*trace_callback_f)(struct kr_request *);
 typedef enum {KNOT_ANSWER, KNOT_AUTHORITY, KNOT_ADDITIONAL} knot_section_t;
 typedef struct {

diff --git a/daemon/lua/kres-gen.sh b/daemon/lua/kres-gen.sh
index accbdd0fcb13bde4e8a22c8bb30c6872c9bb6bf6..6dd0f2d63016a3f7da293af177271d936450517f 100755 (executable)
--- a/daemon/lua/kres-gen.sh
+++ b/daemon/lua/kres-gen.sh
@@ -69,7 +69,7 @@ typedef struct knot_mm {
 
 typedef void *(*map_alloc_f)(void *, size_t);
 typedef void (*map_free_f)(void *baton, void *ptr);
-typedef void (*trace_log_f) (const char *);
+typedef void (*trace_log_f) (const struct kr_request *, const char *);
 typedef void (*trace_callback_f)(struct kr_request *);
 "
 

diff --git a/daemon/lua/kres.lua b/daemon/lua/kres.lua
index 349e7c266c8f40145a2856711cb01b91f7db572c..a223a12b57742fd41a592941e8cf9cf7a45e31a3 100644 (file)
--- a/daemon/lua/kres.lua
+++ b/daemon/lua/kres.lua
@@ -726,13 +726,21 @@ ffi.metatype( kr_query_t, {
 
 -- helper for trace_chain_callbacks
 -- ignores return values from successfull calls but logs tracebacks for throws
-local function void_xpcall_log_tb(func, arg)
-       local ok, err = xpcall(func, debug.traceback, arg)
+local function void_xpcall_log_tb(func, req, msg)
+       local ok, err = xpcall(func, debug.traceback, req, msg)
        if not ok then
-               log('error: callback %s arg %s stack traceback:\n%s', func, arg, err)
+               log('error: callback %s req %s msg %s stack traceback:\n%s', func, req, msg, err)
        end
 end
 
+local function void_xpcall_finish_tb(func, req)
+       local ok, err = xpcall(func, debug.traceback, req)
+       if not ok then
+               log('error: callback %s req %s stack traceback:\n%s', func, req, err)
+       end
+end
+
+
 -- Metatype for request
 local kr_request_t = ffi.typeof('struct kr_request')
 ffi.metatype( kr_request_t, {
@@ -822,10 +830,10 @@ ffi.metatype( kr_request_t, {
                        else
                                local old_log = req.trace_log
                                log_wrapper = ffi.cast('trace_log_f',
-                               function(msg)
+                               function(cbreq, msg)
                                        jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
-                                       void_xpcall_log_tb(old_log, msg)
-                                       void_xpcall_log_tb(new_log, msg)
+                                       void_xpcall_log_tb(old_log, cbreq, msg)
+                                       void_xpcall_log_tb(new_log, cbreq, msg)
                                end)
                                req.trace_log = log_wrapper
                        end
@@ -838,10 +846,10 @@ ffi.metatype( kr_request_t, {
                                function(cbreq)
                                        jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
                                        if old_finish ~= nil then
-                                               void_xpcall_log_tb(old_finish, cbreq)
+                                               void_xpcall_finish_tb(old_finish, cbreq)
                                        end
                                        if new_finish ~= nil then
-                                               void_xpcall_log_tb(new_finish, cbreq)
+                                               void_xpcall_finish_tb(new_finish, cbreq)
                                        end
                                        -- beware: finish callbacks can call log callback
                                        if log_wrapper ~= nil then

diff --git a/lib/utils.c b/lib/utils.c
index 3998699f2c354ded9525868244873cc9f845addf..2755d65f66b1c7cd808407f612769212989605c0 100644 (file)
--- a/lib/utils.c
+++ b/lib/utils.c
@@ -134,7 +134,7 @@ static void kr_vlog_req(
        msg = mp_vprintf_append(mp, msg, fmt, args);
 
        if (kr_log_rtrace_enabled(req))
-               req->trace_log(msg);
+               req->trace_log(req, msg);
        else
                /* caller is responsible for detecting verbose mode, use QRVERBOSE() macro */
                printf("%s", msg);

diff --git a/lib/utils.h b/lib/utils.h
index a99170e690d56d84fe5bcbcc7a1ade3a6831efe1..2eb4b7636837cb582d113e4e7d65a74a1dfcf1bb 100644 (file)
--- a/lib/utils.h
+++ b/lib/utils.h
@@ -37,7 +37,7 @@ typedef void (*trace_callback_f)(struct kr_request *request);
 /**
  * @brief Callback for request logging handler.
  * @param[in] msg Log message. Pointer is not valid after handler returns. */
-typedef void (*trace_log_f)(const char *msg);
+typedef void (*trace_log_f)(const struct kr_request *request, const char *msg);
 
 #define kr_log_info printf
 #define kr_log_error(...) fprintf(stderr, ## __VA_ARGS__)

diff --git a/modules/http/http_trace.lua b/modules/http/http_trace.lua
index 153e072f4b4b7dad450664b9d3afaf924e823a4b..a9764d5a1e82981e987b872f249684b8bcaf9bd7 100644 (file)
--- a/modules/http/http_trace.lua
+++ b/modules/http/http_trace.lua
@@ -22,7 +22,7 @@ local function serve_trace(h, _)
 
        -- Create logging handler callback
        local buffer = {}
-       local buffer_log_cb = ffi.cast('trace_log_f', function (msg)
+       local buffer_log_cb = ffi.cast('trace_log_f', function (_, msg)
                table.insert(buffer, ffi.string(msg))
        end)
 

diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua
index 138a84680a7705620006ee467baceef3e4d02740..683c68a968e7d48268e24655afdd613b35ec08bc 100644 (file)
--- a/modules/policy/policy.lua
+++ b/modules/policy/policy.lua
@@ -528,11 +528,16 @@ function policy.DENY_MSG(msg)
        end
 end
 
-local debug_logline_cb = ffi.cast('trace_log_f', function (msg)
+local function free_cb(func)
+       func:free()
+end
+
+local debug_logline_cb = ffi.cast('trace_log_f', function (_, msg)
        jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
        -- msg typically ends with newline
        io.write(ffi.string(msg))
 end)
+ffi.gc(debug_logline_cb, free_cb)
 
 local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req)
        jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
@@ -543,6 +548,7 @@ local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req)
                'answer packet:\n' ..
                tostring(req.answer))
 end)
+ffi.gc(debug_logfinish_cb, free_cb)
 
 -- log request packet
 function policy.REQTRACE(_, req)
@@ -556,29 +562,31 @@ function policy.DEBUG_ALWAYS(state, req)
        policy.REQTRACE(state, req)
 end
 
+local debug_stashlog_cb = ffi.cast('trace_log_f', function (req, msg)
+       jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
+
+       -- stash messages for conditional logging in trace_finish
+       local stash = req:vars()['policy_debug_stash']
+       table.insert(stash, ffi.string(msg))
+end)
+ffi.gc(debug_stashlog_cb, free_cb)
+
 -- buffer verbose logs and print then only if test() returns a truthy value
 function policy.DEBUG_IF(test)
+       local debug_finish_cb = ffi.cast('trace_callback_f', function (cbreq)
+               jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
+               if test(cbreq) then
+                       debug_logfinish_cb(cbreq)  -- unconditional version
+                       local stash = cbreq:vars()['policy_debug_stash']
+                       io.write(table.concat(stash, ''))
+               end
+       end)
+       ffi.gc(debug_finish_cb, function (func) func:free() end)
+
        return function (state, req)
+               req:vars()['policy_debug_stash'] = {}
                policy.QTRACE(state, req)
-               local priv_log_buf = {}
-               local priv_log_cb = ffi.cast('trace_log_f', function (msg)
-                       jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
-
-                       -- stash messages for conditional logging in trace_finish
-                       table.insert(priv_log_buf, ffi.string(msg))
-               end)
-
-               local priv_finish_cb
-               priv_finish_cb = ffi.cast('trace_callback_f', function (cbreq)
-                       jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
-                       if test(cbreq) then
-                               debug_logfinish_cb(cbreq)  -- unconditional version
-                               io.write(table.concat(priv_log_buf, ''))
-                       end
-                       priv_log_cb:free()
-                       priv_finish_cb:free()
-               end)
-               req:trace_chain_callbacks(priv_log_cb, priv_finish_cb)
+               req:trace_chain_callbacks(debug_stashlog_cb, debug_finish_cb)
                policy.REQTRACE(state, req)
                return
        end

diff --git a/modules/watchdog/watchdog.lua b/modules/watchdog/watchdog.lua
index f51da18b4c4e45d98db3512fc84d0f2b8675a79c..1a8065fdd9e3d2ba4715b2d1c0afdcd1fa58334c 100644 (file)
--- a/modules/watchdog/watchdog.lua
+++ b/modules/watchdog/watchdog.lua
@@ -22,7 +22,7 @@ end
 -- logging
 local function add_tracer(logbuf)
        return function (req)
-               local function qrylogger(msg)
+               local function qrylogger(_, msg)
                        table.insert(logbuf, ffi.string(msg))
                end
                req.trace_log = ffi.cast('trace_log_f', qrylogger)