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

diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua
index b943dd408b5b57f01a4177a3419a7757dcc54dba..41320adf85ad177f5cc96d984b351d7446b91263 100644 (file)
--- 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)