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

@@ -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)