From: Petr Špaček <petr.spacek@nic.cz>
Date: Wed, 18 Mar 2020 11:22:24 +0000 (+0100)
Subject: policy.DEBUG: generalize DEBUG_CACHE_MISS into DEBUG_IF
X-Git-Tag: v5.1.0~26^2~9
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=7c4aa34eeeed8c33eb2b7bc718c84e999316594d;p=thirdparty%2Fknot-resolver.git

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 6e1e966aa..a988b7121 100644
--- 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 f4dcce33d..2f8708d88 100644
--- 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