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 a39e3fe459c369cd0472a3cd78bc9d00021de9d1..349e7c266c8f40145a2856711cb01b91f7db572c 100644 (file)
--- 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 7aec8453d0f701375687a2f0304659e1866b98aa..153e072f4b4b7dad450664b9d3afaf924e823a4b 100644 (file)
--- 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 19bbe6b637b67e131e0ae3fe970bdb72540ea59b..138a84680a7705620006ee467baceef3e4d02740 100644 (file)
--- 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