From 81db7d9ec0964652dfae49e8778da4f62715e9b6 Mon Sep 17 00:00:00 2001 From: =?utf8?q?Vladim=C3=ADr=20=C4=8Cun=C3=A1t?= Date: Fri, 26 Feb 2021 17:44:46 +0100 Subject: [PATCH] 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. --- daemon/lua/kres.lua | 2 +- modules/policy/README.rst | 1 + modules/policy/policy.lua | 12 ++++++++---- 3 files changed, 10 insertions(+), 5 deletions(-) diff --git a/daemon/lua/kres.lua b/daemon/lua/kres.lua index 640d8427d..adb425333 100644 --- 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 d209f846c..7e4ecad39 100644 --- 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 fa9980ce0..c15a0599d 100644 --- 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 -- 2.47.2