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)

diff --git a/NEWS b/NEWS
index 2999b1d21fb5e96f3b9a382b328eb1de0d9dea83..88d588db2766bf769ee0c1fe6e639f96fefe3676 100644 (file)
--- a/NEWS
+++ b/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
 --------------------

diff --git a/daemon/lua/kres-gen-30.lua b/daemon/lua/kres-gen-30.lua
index a80bf362432605938c7111df9cb2e527bc703389..cc2ca7b4601cb1316e458c220d3944af283c5952 100644 (file)
--- a/daemon/lua/kres-gen-30.lua
+++ b/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);

diff --git a/daemon/lua/kres-gen-31.lua b/daemon/lua/kres-gen-31.lua
index 65002a4cafec7903111aaf693ef7b83884680dc6..c81f0c559028a39b1d5b7f9958ae5294a213250a 100644 (file)
--- a/daemon/lua/kres-gen-31.lua
+++ b/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);

diff --git a/daemon/lua/kres-gen.sh b/daemon/lua/kres-gen.sh
index 064fb0e4bd5cd5da419436681369f18025abbc46..aa07da41ce1ef72f9d01043dc54de685edcc9ac5 100755 (executable)
--- a/daemon/lua/kres-gen.sh
+++ b/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

diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua
index 306c4cf8a7dc9e162981efc55815834a5f8ce383..8d9afbc3f93fda67526db8c5e4488dbf83524794 100644 (file)
--- a/modules/policy/policy.lua
+++ b/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