From 54ab3f78bb30d615323dce27ac2ba82a921eafc4 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Vladim=C3=ADr=20=C4=8Cun=C3=A1t?= <vladimir.cunat@nic.cz>
Date: Fri, 6 Aug 2021 19:17:18 +0200
Subject: [PATCH] policy trace-logging improvements
The logs can be triggered from policy actions, in per-request fashion:
- they're on LOG_DEBUG level but always sent, regardless of log config
- those messages will show double group tags: "[reqdbg][foo ]"
(but they lack proper meta-data - about location of the log's origin)
- reqdbg is *in addition* to normal logs, so the lines may be duplicated
if that's how the logging was configured
---
modules/policy/policy.lua | 40 +++++++++++++++++++++++++++------------
1 file changed, 28 insertions(+), 12 deletions(-)
diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua
index b943dd408..41320adf8 100644
--- a/modules/policy/policy.lua
+++ b/modules/policy/policy.lua
@@ -2,6 +2,9 @@
local kres = require('kres')
local ffi = require('ffi')
+local LOG_GRP_POLICY_TAG = ffi.string(ffi.C.kr_log_grp2name(ffi.C.LOG_GRP_POLICY))
+local LOG_GRP_REQDBG_TAG = ffi.string(ffi.C.kr_log_grp2name(ffi.C.LOG_GRP_REQDBG))
+
local todname = kres.str2dname -- not available during module load otherwise
-- Counter of unique rules
@@ -643,31 +646,39 @@ end
local debug_logline_cb = ffi.cast('trace_log_f', function (_, msg)
jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
- -- msg typically ends with newline
- log_debug(ffi.C.LOG_GRP_POLICY, "%s", msg)
+ ffi.C.kr_log_fmt(
+ ffi.C.LOG_GRP_REQDBG, -- but the original [group] tag also remains in the string
+ LOG_DEBUG,
+ 'CODE_FILE=policy.lua', 'CODE_LINE=', 'CODE_FUNC=policy.DEBUG_ALWAYS', -- no meaningful locations
+ '[%-6s]%s', LOG_GRP_REQDBG_TAG, msg) -- msg should end with newline already
end)
ffi.gc(debug_logline_cb, free_cb)
+-- LOG_DEBUG without log_trace and without code locations
+local function log_notrace(req, fmt, ...)
+ ffi.C.kr_log_fmt(ffi.C.LOG_GRP_REQDBG, LOG_DEBUG,
+ 'CODE_FILE=policy.lua', 'CODE_LINE=', 'CODE_FUNC=', -- no meaningful locations
+ '%s', string.format( -- convert in lua, as integers in C varargs would pass as double
+ '[%-6s][%-6s][%05u.00] ' .. fmt,
+ LOG_GRP_REQDBG_TAG, LOG_GRP_POLICY_TAG, req.uid, ...)
+ )
+end
+
local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req)
jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
- log_req(req, 0, 0, ffi.C.LOG_GRP_POLICY,
- 'following rrsets were marked as interesting:\n' ..
+ log_notrace(req, 'following rrsets were marked as interesting:\n%s\n',
req:selected_tostring())
if req.answer ~= nil then
- log_req(req, 0, 0, ffi.C.LOG_GRP_POLICY,
- 'answer packet:\n' .. tostring(req.answer))
+ log_notrace(req, 'answer packet:\n%s\n', req.answer)
else
- log_req(req, 0, 0, ffi.C.LOG_GRP_POLICY,
- 'answer packet DROPPED\n')
+ log_notrace(req, 'answer packet DROPPED\n')
end
end)
ffi.gc(debug_logfinish_cb, free_cb)
-- log request packet
function policy.REQTRACE(_, req)
- log_req(req, 0, 0, ffi.C.LOG_GRP_POLICY,
- 'request packet:\n%s',
- tostring(req.qsource.packet))
+ log_notrace(req, 'request packet:\n%s', req.qsource.packet)
end
function policy.DEBUG_ALWAYS(state, req)
@@ -691,8 +702,13 @@ function policy.DEBUG_IF(test)
jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed
if test(cbreq) then
debug_logfinish_cb(cbreq) -- unconditional version
+
local stash = cbreq:vars()['policy_debug_stash']
- io.write(table.concat(stash, ''))
+ for _, line in ipairs(stash) do -- don't want one huge entry
+ ffi.C.kr_log_fmt(ffi.C.LOG_GRP_REQDBG, LOG_DEBUG,
+ 'CODE_FILE=policy.lua', 'CODE_LINE=', 'CODE_FUNC=', -- no meaningful locations
+ '[%-6s]%s', LOG_GRP_REQDBG_TAG, line)
+ end
end
end)
ffi.gc(debug_finish_cb, function (func) func:free() end)
--
GitLab