policy.DEBUG_*: tweak verbosity

One issue I saw in verbose(true) mode is that using DEBUG_IF with
a false condition would turn off verbosity for those requests,
and that seemed surprising.
Also, if we know in advance that we want to print the verbose lines,
let them be printed directly instead of using the complex mechanism.

diff --git a/daemon/lua/kres.lua b/daemon/lua/kres.lua
index 640d8427d734966ef19595711993fc60a09d7e64..adb4253337c3080621761a8a32d1ec98dc6d5026 100644 (file)
--- a/daemon/lua/kres.lua
+++ b/daemon/lua/kres.lua
@@ -822,7 +822,7 @@ ffi.metatype( kr_request_t, {
                        local log_wrapper
                        if req.trace_log == nil then
                                req.trace_log = new_log
-                       else
+                       elseif new_log ~= nil then
                                local old_log = req.trace_log
                                log_wrapper = ffi.cast('trace_log_f',
                                function(cbreq, msg)

diff --git a/modules/policy/README.rst b/modules/policy/README.rst
index d209f846c01dbb12133ed394b78025ae05ad3d6d..7e4ecad3957b6deb35c74bca9e60e5ffced9bd5b 100644 (file)
--- a/modules/policy/README.rst
+++ b/modules/policy/README.rst
@@ -238,6 +238,7 @@ Following actions act on request and then processing continue until first non-ch
    .. warning:: Verbose logging has significant performance impact on resolver and might also overload you logging system because one request can easily generate tens of kilobytes of logs. Always use appropriate `Filters`_ to limit number of requests triggering this action to a minimum!
 
    .. note:: ``test_function`` is evaluated only when request is finished. As a result verbose logs for all requests must be collected until request is finished because it is not possible to know beforehand how ``test_function`` at the end evaluates given request. When a request is finalized logs are either printed or thrown away.
+     In globally-set verbose mode those lines get printed regardless of the test function and immediately.
 
    Example usage which gathers verbose logs for all requests in subtree ``dnssec-failed.org.`` and prints verbose logs for all requests finished with states different than ``kres.DONE`` (most importantly ``kres.FAIL``, see :c:type:`kr_layer_state`).
 

diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua
index fa9980ce0b6e48964f2d53f6e1d35fb8556830e3..c15a0599df6766f2cccda688c0cd7885b8043dac 100644 (file)
--- a/modules/policy/policy.lua
+++ b/modules/policy/policy.lua
@@ -670,7 +670,9 @@ end
 
 function policy.DEBUG_ALWAYS(state, req)
        policy.QTRACE(state, req)
-       req:trace_chain_callbacks(debug_logline_cb, debug_logfinish_cb)
+       local logline_maybe = nil -- verbose() is immediate and cheaper than callback
+       if not verbose() then logline_maybe = debug_logline_cb end
+       req:trace_chain_callbacks(logline_maybe, debug_logfinish_cb)
        policy.REQTRACE(state, req)
 end
 
@@ -683,11 +685,11 @@ local debug_stashlog_cb = ffi.cast('trace_log_f', function (req, msg)
 end)
 ffi.gc(debug_stashlog_cb, free_cb)
 
--- buffer verbose logs and print then only if test() returns a truthy value
+-- buffer verbose logs and print then if test() returns a truthy value (or in verbose mode)
 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
+               if verbose() or test(cbreq) then
                        debug_logfinish_cb(cbreq)  -- unconditional version
                        local stash = cbreq:vars()['policy_debug_stash']
                        io.write(table.concat(stash, ''))
@@ -698,7 +700,9 @@ function policy.DEBUG_IF(test)
        return function (state, req)
                req:vars()['policy_debug_stash'] = {}
                policy.QTRACE(state, req)
-               req:trace_chain_callbacks(debug_stashlog_cb, debug_finish_cb)
+               local logline_maybe = nil -- verbose() is immediate and cheaper than callback
+               if not verbose() then logline_maybe = debug_logline_cb end
+               req:trace_chain_callbacks(logline_maybe, debug_finish_cb)
                policy.REQTRACE(state, req)
                return
        end