From: Petr Špaček Date: Fri, 20 Mar 2020 13:40:44 +0000 (+0100) Subject: policy.DEBUG: fix to respect user-provided callbacks X-Git-Tag: v5.1.0~26^2~4 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=edde753893dcba0dd0eb4527e37d9073bbafbe08;p=thirdparty%2Fknot-resolver.git policy.DEBUG: fix to respect user-provided callbacks It creates new callback functions for every request which uses "callback chaining" but these should be rare. --- diff --git a/daemon/lua/kres.lua b/daemon/lua/kres.lua index a39e3fe45..349e7c266 100644 --- a/daemon/lua/kres.lua +++ b/daemon/lua/kres.lua @@ -723,6 +723,16 @@ ffi.metatype( kr_query_t, { end, }, }) + +-- 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) + if not ok then + log('error: callback %s arg %s stack traceback:\n%s', func, arg, err) + end +end + -- Metatype for request local kr_request_t = ffi.typeof('struct kr_request') ffi.metatype( kr_request_t, { @@ -800,6 +810,49 @@ ffi.metatype( kr_request_t, { return table.concat(buf, '') end, + -- chain new callbacks after the old ones + -- creates new wrapper functions as necessary + -- note: callbacks are FFI cdata pointers so tests must + -- use explicit "cb == nil", just "if cb" does not work + -- + trace_chain_callbacks = function (req, new_log, new_finish) + local log_wrapper + if req.trace_log == nil then + req.trace_log = new_log + else + local old_log = req.trace_log + log_wrapper = ffi.cast('trace_log_f', + function(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) + end) + req.trace_log = log_wrapper + end + local old_finish = req.trace_finish + if not (log_wrapper ~= nil or old_finish ~= nil) then + req.trace_finish = new_finish + else + local fin_wrapper + fin_wrapper = ffi.cast('trace_callback_f', + 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) + end + if new_finish ~= nil then + void_xpcall_log_tb(new_finish, cbreq) + end + -- beware: finish callbacks can call log callback + if log_wrapper ~= nil then + log_wrapper:free() + end + fin_wrapper:free() + end) + req.trace_finish = fin_wrapper + end + end, + -- Return per-request variable table -- The request can store anything in this Lua table and it will be freed -- when the request is closed, it doesn't have to worry about contents. diff --git a/modules/http/http_trace.lua b/modules/http/http_trace.lua index 7aec8453d..153e072f4 100644 --- a/modules/http/http_trace.lua +++ b/modules/http/http_trace.lua @@ -45,8 +45,7 @@ local function serve_trace(h, _) type = qtype, options = {'TRACE'}, init = function (req) - req.trace_log = buffer_log_cb - req.trace_finish = finish_cb + req:trace_chain_callbacks(buffer_log_cb, finish_cb) end } diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua index 19bbe6b63..138a84680 100644 --- a/modules/policy/policy.lua +++ b/modules/policy/policy.lua @@ -529,11 +529,13 @@ function policy.DENY_MSG(msg) 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) local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req) + jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed ffi.C.kr_log_req(req, 0, 0, 'dbg', 'following rrsets were marked as interesting:\n' .. req:selected_tostring()) @@ -548,32 +550,35 @@ function policy.REQTRACE(_, req) tostring(req.qsource.packet)) end -function policy.DEBUG_ALWAYS(_, req) - policy.QTRACE(_, req) - req.trace_log = debug_logline_cb - req.trace_finish = debug_logfinish_cb - policy.REQTRACE(_, req) - return +function policy.DEBUG_ALWAYS(state, req) + policy.QTRACE(state, req) + req:trace_chain_callbacks(debug_logline_cb, debug_logfinish_cb) + policy.REQTRACE(state, req) end -- buffer verbose logs and print then only if test() returns a truthy value function policy.DEBUG_IF(test) return function (state, req) policy.QTRACE(state, req) - local debug_log_buf = {} - req.trace_log = ffi.cast('trace_log_f', function (msg) + 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(debug_log_buf, ffi.string(msg)) + table.insert(priv_log_buf, ffi.string(msg)) end) - req.trace_finish = ffi.cast('trace_callback_f', function (cbreq) + 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(debug_log_buf, '')) + io.write(table.concat(priv_log_buf, '')) end - req.trace_log:free() - req.trace_finish:free() + priv_log_cb:free() + priv_finish_cb:free() end) + req:trace_chain_callbacks(priv_log_cb, priv_finish_cb) policy.REQTRACE(state, req) return end