policy: log selected actions

The following actions will now be logged in debug level (or request
tracing): ANSWER, DENY, DENY_MSG, DROP, REFUSE, TC

This can be useful for RPZ and other policy debugging.

Purposefully ommitted actions:
PASS - since it's the same as normal processing
REROUTE - the action itself comes from renumber module
STUB,FORWARD,TLS_FORWARD - this could be more confusing than useful
  (e.g. when response comes from cache)

NEWS

@@ -4,6 +4,7 @@ Knot Resolver 5.5.0 (2022-mm-dd)
 Improvements
 ------------
 - extended_errors: module for extended DNS error support, RFC8914 (!1234)
+- policy: new action policy.IPTRACE for logging request origin (!1239)
 
 Incompatible changes
 --------------------

daemon/lua/kres-gen-30.lua

@@ -393,6 +393,7 @@ int kr_rplan_pop(struct kr_rplan *, struct kr_query *);
 struct kr_query *kr_rplan_resolved(struct kr_rplan *);
 struct kr_query *kr_rplan_last(struct kr_rplan *);
 int kr_forward_add_target(struct kr_request *, const struct sockaddr *);
+_Bool kr_log_is_debug_fun(enum kr_log_group, const struct kr_request *);
 void kr_log_req1(const struct kr_request * const, uint32_t, const unsigned int, enum kr_log_group, const char *, const char *, ...);
 void kr_log_q1(const struct kr_query * const, enum kr_log_group, const char *, const char *, ...);
 const char *kr_log_grp2name(enum kr_log_group);

daemon/lua/kres-gen-31.lua

@@ -393,6 +393,7 @@ int kr_rplan_pop(struct kr_rplan *, struct kr_query *);
 struct kr_query *kr_rplan_resolved(struct kr_rplan *);
 struct kr_query *kr_rplan_last(struct kr_rplan *);
 int kr_forward_add_target(struct kr_request *, const struct sockaddr *);
+_Bool kr_log_is_debug_fun(enum kr_log_group, const struct kr_request *);
 void kr_log_req1(const struct kr_request * const, uint32_t, const unsigned int, enum kr_log_group, const char *, const char *, ...);
 void kr_log_q1(const struct kr_query * const, enum kr_log_group, const char *, const char *, ...);
 const char *kr_log_grp2name(enum kr_log_group);

daemon/lua/kres-gen.sh

@@ -215,6 +215,7 @@ ${CDEFS} ${LIBKRES} functions <<-EOF
 # Forwarding
 	kr_forward_add_target
 # Utils
+	kr_log_is_debug_fun
 	kr_log_req1
 	kr_log_q1
 	kr_log_grp2name

modules/policy/policy.lua

@@ -57,6 +57,17 @@ local function addr2sock(target, default_port)
 	return sock
 end
 
+-- Debug logging for taken policy actions
+local function log_policy_action(req, name)
+	if ffi.C.kr_log_is_debug_fun(ffi.C.LOG_GRP_POLICY, req) then
+		local qry = req:current()
+		ffi.C.kr_log_req1(
+			req, qry.uid, 2, ffi.C.LOG_GRP_POLICY, LOG_GRP_POLICY_TAG,
+			"%s applied for %s %s\n",
+			name, kres.dname2str(qry.sname), kres.tostring.type[qry.stype])
+	end
+end
+
 -- policy functions are defined below
 local policy = {}
 
@@ -247,6 +258,7 @@ function policy.ANSWER(rtable, nodata)
 			else
 				mkauth_soa(answer, kres.dname2wire(qry.sname), nil, ttl)
 			end
+			log_policy_action(req, 'ANSWER (nodata)')
 		else
 			answer:begin(kres.section.ANSWER)
 			if type(data.rdata) == 'table' then
@@ -256,6 +268,7 @@ function policy.ANSWER(rtable, nodata)
 			else
 				answer:put(qry.sname, ttl, qry.sclass, qry.stype, data.rdata)
 			end
+			log_policy_action(req, 'ANSWER (forged)')
 		end
 		return kres.DONE
 	end
@@ -672,6 +685,7 @@ function policy.DENY_MSG(msg, extended_error)
 	if extended_error == nil then
 		extended_error = kres.extended_error.BLOCKED
 	end
+	local action_name = msg and 'DENY_MSG' or 'DENY'
 
 	return function (_, req)
 		-- Write authority information
@@ -688,6 +702,7 @@ function policy.DENY_MSG(msg, extended_error)
 
 		end
 		req:set_extended_error(extended_error, "CR36")
+		log_policy_action(req, action_name)
 		return kres.DONE
 	end
 end
@@ -786,6 +801,7 @@ function policy.DROP(_, req)
 	local answer = answer_clear(req)
 	if answer == nil then return nil end
 	req:set_extended_error(kres.extended_error.PROHIBITED, "U5KL")
+	log_policy_action(req, 'DROP')
 	return kres.FAIL
 end
 
@@ -795,6 +811,7 @@ function policy.REFUSE(_, req)
 	answer:rcode(kres.rcode.REFUSED)
 	answer:ad(false)
 	req:set_extended_error(kres.extended_error.PROHIBITED, "EIM4")
+	log_policy_action(req, 'REFUSE')
 	return kres.DONE
 end
 
@@ -808,6 +825,7 @@ function policy.TC(state, req)
 	if answer == nil then return nil end
 	answer:tc(1)
 	answer:ad(false)
+	log_policy_action(req, 'TC')
 	return kres.DONE
 end