policy.DEBUG: generalize DEBUG_CACHE_MISS into DEBUG_IF

DEBUG_IF accepts user-supplied function which decides which requests
should be logged.

diff --git a/modules/policy/README.rst b/modules/policy/README.rst
index 6e1e966aad7b234f5af3fd491f91cd402f82900a..a988b71213397c913f1d4f75441e7ffef2163f30 100644 (file)
--- a/modules/policy/README.rst
+++ b/modules/policy/README.rst
@@ -178,6 +178,40 @@ Following actions act on request and then processing continue until first non-ch
         -- requests for example.net. and its subdomains
         policy.add(policy.suffix(policy.QTRACE, policy.todnames({'example.net'})))
 
+.. py:attribute:: DEBUG_ALWAYS
+
+   Enable extra verbose logging for all requests, including cache hits. See caveats for :func:`policy.DEBUG_IF`.
+
+.. py:data:: DEBUG_CACHE_MISS
+
+   Enable extra verbose logging but print logs only for requests which required information which was not available locally (i.e. requests which forced resolver to communicate over network). Intended usage is for debugging problems with remote servers. This action typically produces less logs than :func:`policy.DEBUG_ALWAYS` but all caveats from :func:`policy.DEBUG_IF` apply as well.
+
+   .. code-block:: lua
+
+        policy.add(policy.suffix(
+                policy.DEBUG_CACHE_MISS,
+                policy.todnames({'example.com.'})))
+
+.. py:function:: DEBUG_IF(test_function)
+
+   :param test_function: Function with single argument of type :c:type:`kr_request` which returns ``true`` if verbose logs for a given request should be printed and ``false`` otherwise.
+
+   Enable extra verbose logging but print logs only for requests which match condition specified by ``test_function``. This allows to fine-tune which requests should be printed.
+
+   .. 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.
+
+   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`).
+
+   .. code-block:: lua
+
+        policy.add(policy.suffix(
+                policy.DEBUG_IF(function(req)
+                                        return (req.state ~= kres.DONE)
+                                end),
+                policy.todnames({'dnssec-failed.org.'})))
+
 
 Custom actions
 ^^^^^^^^^^^^^^

diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua
index f4dcce33dbfca851ebcb7dddf9e8bb0db473d812..2f8708d88fb24dcefcb4ec4aaf67d8b1d9c3f5a7 100644 (file)
--- a/modules/policy/policy.lua
+++ b/modules/policy/policy.lua
@@ -542,14 +542,36 @@ local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req)
                tostring(req.answer))
 end)
 
-function policy.DEBUG(_, req)
+function policy.DEBUG_ALWAYS(_, req)
        policy.QTRACE(_, req)
        req.trace_log = debug_logline_cb
        req.trace_finish = debug_logfinish_cb
        return
 end
 
-local function request_answered_from_cache(req)
+-- 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)
+                       -- stash messages for conditional logging in trace_finish
+                       table.insert(debug_log_buf, ffi.string(msg))
+               end)
+
+               req.trace_finish = ffi.cast('trace_callback_f', function (cbreq)
+                       if test(cbreq) then
+                               debug_logfinish_cb(cbreq)  -- unconditional version
+                               io.write(table.concat(debug_log_buf, ''))
+                       end
+                       req.trace_log:free()
+                       req.trace_finish:free()
+               end)
+               return
+       end
+end
+
+local function is_request_answered_from_cache(req)
        local rplan = ffi.C.kr_resolve_plan(req)
        if tonumber(rplan.pending.len) > 0 then
                -- an unresolved query, i.e. something is missing from the cache
@@ -563,24 +585,11 @@ local function request_answered_from_cache(req)
        return true
 end
 
-function policy.DEBUG_CACHE_MISS(_, req)
-       policy.QTRACE(_, req)
-       local debug_log_buf = {}
-       req.trace_log = ffi.cast('trace_log_f', function (msg)
-               -- stash messages for conditional logging in trace_finish
-               table.insert(debug_log_buf, ffi.string(msg))
-       end)
-
-       req.trace_finish = ffi.cast('trace_callback_f', function (cbreq)
-               if not request_answered_from_cache(cbreq) then
-                       debug_logfinish_cb(cbreq)  -- unconditional version
-                       io.write(table.concat(debug_log_buf, ''))
-               end
-               req.trace_log:free()
-               req.trace_finish:free()
-       end)
-       return
-end
+policy.DEBUG_CACHE_MISS = policy.DEBUG_IF(
+       function(req)
+               return not is_request_answered_from_cache(req)
+       end
+)
 
 policy.DENY = policy.DENY_MSG() -- compatibility with < 2.0