From 912741e665cb6b3353174668c409a3c95338abbe Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Petr=20=C5=A0pa=C4=8Dek?= <petr.spacek@nic.cz>
Date: Thu, 12 Mar 2020 13:41:49 +0100
Subject: [PATCH] unify verbose logging and request tracing
Formerly both logs used slightly different formats and duplicated code.
From now on verbose log and request tracing are generated using the same
code.
This required a small change to request trace_log_f definition so it
might affect external modules.
---
daemon/lua/kres-gen.lua | 2 +-
daemon/lua/kres-gen.sh | 4 +--
doc/upgrading.rst | 9 ++++++
lib/layer.h | 6 ++--
lib/utils.c | 44 ++++++++---------------------
lib/utils.h | 24 ++++++----------
modules/http/http_trace.lua | 40 +++-----------------------
modules/policy/policy.lua | 50 +++++++++++++++++++++++++++++++++
modules/rebinding/rebinding.lua | 2 +-
modules/watchdog/watchdog.lua | 10 ++-----
10 files changed, 91 insertions(+), 100 deletions(-)
diff --git a/daemon/lua/kres-gen.lua b/daemon/lua/kres-gen.lua
index 973a7cfa0..40588282f 100644
--- a/daemon/lua/kres-gen.lua
+++ b/daemon/lua/kres-gen.lua
@@ -15,7 +15,7 @@ typedef struct knot_mm {
typedef void *(*map_alloc_f)(void *, size_t);
typedef void (*map_free_f)(void *baton, void *ptr);
-typedef void (*trace_log_f) (const struct kr_query *, const char *, const char *);
+typedef void (*trace_log_f) (const char *);
typedef void (*trace_callback_f)(struct kr_request *);
typedef enum {KNOT_ANSWER, KNOT_AUTHORITY, KNOT_ADDITIONAL} knot_section_t;
typedef struct {
diff --git a/daemon/lua/kres-gen.sh b/daemon/lua/kres-gen.sh
index c213eead9..785110e66 100755
--- a/daemon/lua/kres-gen.sh
+++ b/daemon/lua/kres-gen.sh
@@ -69,7 +69,7 @@ typedef struct knot_mm {
typedef void *(*map_alloc_f)(void *, size_t);
typedef void (*map_free_f)(void *baton, void *ptr);
-typedef void (*trace_log_f) (const struct kr_query *, const char *, const char *);
+typedef void (*trace_log_f) (const char *);
typedef void (*trace_callback_f)(struct kr_request *);
"
@@ -190,7 +190,7 @@ ${CDEFS} ${LIBKRES} functions <<-EOF
# Nameservers
kr_nsrep_set
# Utils
- kr_log_qverbose_impl
+ kr_qlog
kr_make_query
kr_pkt_make_auth_header
kr_pkt_put
diff --git a/doc/upgrading.rst b/doc/upgrading.rst
index 8f349c526..541b0044c 100644
--- a/doc/upgrading.rst
+++ b/doc/upgrading.rst
@@ -9,6 +9,15 @@ Upgrading
This section summarizes steps required for upgrade to newer Knot Resolver versions.
We advise users to also read :ref:`release_notes` for respective versions.
+5.0 to 5.1
+==========
+
+Module changes
+--------------
+
+* Custom modules which use :c:type:`trace_log_f` handler in request structure :c:type:`kr_request` need update to simplified handler API.
+
+
4.x to 5.x
==========
diff --git a/lib/layer.h b/lib/layer.h
index 128d7a128..35d0064eb 100644
--- a/lib/layer.h
+++ b/lib/layer.h
@@ -18,10 +18,8 @@
*/
#define QRVERBOSE(_query, _cls, ...) do { \
const struct kr_query *_qry = (_query); \
- if (kr_log_trace_enabled(_qry)) { \
- kr_log_trace(_qry, (_cls), __VA_ARGS__); \
- } else if (VERBOSE_STATUS) { \
- kr_log_qverbose_impl(_qry, (_cls), __VA_ARGS__); \
+ if (VERBOSE_STATUS || kr_log_trace_enabled(_qry)) { \
+ kr_qlog(_qry, (_cls), __VA_ARGS__); \
} \
} while (false)
#endif
diff --git a/lib/utils.c b/lib/utils.c
index 34f80cc5f..c48b2cfd0 100644
--- a/lib/utils.c
+++ b/lib/utils.c
@@ -35,7 +35,6 @@
/* Always compile-in log symbols, even if disabled. */
#undef kr_verbose_status
#undef kr_verbose_set
-#undef kr_log_verbose
/* Logging & debugging */
bool kr_verbose_status = false;
@@ -121,52 +120,31 @@ bool kr_verbose_set(bool status)
return kr_verbose_status;
}
-void kr_log_verbose(const char *fmt, ...)
+void kr_qlog(const struct kr_query *qry, const char *source, const char *fmt, ...)
{
- if (unlikely(kr_verbose_status)) {
- va_list args;
- va_start(args, fmt);
- vprintf(fmt, args);
- va_end(args);
- }
-}
+ struct mempool *mp = mp_new(512);
-void kr_log_qverbose_impl(const struct kr_query *qry, const char *cls, const char *fmt, ...)
-{
unsigned ind = 0;
for (const struct kr_query *q = qry; q; q = q->parent)
ind += 2;
uint32_t qry_uid = qry ? qry->uid : 0;
uint32_t req_uid = qry && qry->request ? qry->request->uid : 0;
- /* Simplified kr_log_verbose() calls, first prefix then passed fmt...
- * Calling it would take about the same amount of code. */
- printf("[%05u.%02u][%s] %*s", req_uid, qry_uid, cls, ind, "");
- va_list args;
- va_start(args, fmt);
- vprintf(fmt, args);
- va_end(args);
-}
-
-bool kr_log_trace(const struct kr_query *query, const char *source, const char *fmt, ...)
-{
- if (!kr_log_trace_enabled(query)) {
- return false;
- }
- auto_free char *msg = NULL;
+ char *msg = mp_printf(mp, "[%05u.%02u][%s] %*s", req_uid, qry_uid, source, ind, "");
va_list args;
va_start(args, fmt);
- int len = vasprintf(&msg, fmt, args);
+ msg = mp_vprintf_append(mp, msg, fmt, args);
va_end(args);
- /* Check formatting result before logging */
- if (len < 0) {
- return false;
- }
+ if (kr_log_trace_enabled(qry))
+ qry->request->trace_log(msg);
+ else
+ /* caller is responsible for detecting verbose mode, use QRVERBOSE() macro */
+ printf("%s", msg);
- query->request->trace_log(query, source, msg);
- return true;
+ mp_delete(mp);
+ return;
}
char* kr_strcatdup(unsigned n, ...)
diff --git a/lib/utils.h b/lib/utils.h
index 1a5e3aafd..09b12197c 100644
--- a/lib/utils.h
+++ b/lib/utils.h
@@ -34,8 +34,10 @@ struct kr_request;
/** @brief Callback for request events. */
typedef void (*trace_callback_f)(struct kr_request *request);
-/** @brief Callback for request logging handler. */
-typedef void (*trace_log_f)(const struct kr_query *query, const char *source, const char *msg);
+/**
+ * @brief Callback for request logging handler.
+ * @param[in] msg Log message. Pointer is not valid after handler returns. */
+typedef void (*trace_log_f)(const char *msg);
#define kr_log_info printf
#define kr_log_error(...) fprintf(stderr, ## __VA_ARGS__)
@@ -48,14 +50,6 @@ KR_EXPORT extern bool kr_verbose_status;
/** Set --verbose mode. Not available if compiled with -DNOVERBOSELOG. */
KR_EXPORT bool kr_verbose_set(bool status);
-/** Log a message if in --verbose mode. */
-KR_EXPORT KR_PRINTF(1)
-void kr_log_verbose(const char *fmt, ...);
-
-/** Utility for QRVERBOSE - use that instead. */
-KR_EXPORT KR_PRINTF(3)
-void kr_log_qverbose_impl(const struct kr_query *qry, const char *cls, const char *fmt, ...);
-
/**
* @brief Return true if the query has request log handler installed.
*/
@@ -64,14 +58,14 @@ void kr_log_qverbose_impl(const struct kr_query *qry, const char *cls, const cha
false))
/**
- * Log a message through the request log handler.
+ * Log a message through the request log handler or stdout.
+ * Caller is responsible for detecting verbose mode, use QRVERBOSE() macro.
* @param query current query
* @param source message source
* @param fmt message format
- * @return true if the message was logged
*/
-KR_EXPORT KR_PRINTF(3)
-bool kr_log_trace(const struct kr_query *query, const char *source, const char *fmt, ...);
+void kr_qlog(const struct kr_query *query, const char *source, const char *fmt, ...)
+KR_EXPORT KR_PRINTF(3);
#ifdef NOVERBOSELOG
/* Efficient compile-time disabling of verbose messages. */
@@ -82,7 +76,7 @@ bool kr_log_trace(const struct kr_query *query, const char *source, const char *
/** Block run in --verbose mode; optimized when not run. */
#define VERBOSE_STATUS __builtin_expect(kr_verbose_status, false)
#define WITH_VERBOSE(query) if(__builtin_expect(kr_verbose_status || kr_log_trace_enabled(query), false))
-#define kr_log_verbose if(VERBOSE_STATUS) kr_log_verbose
+#define kr_log_verbose if(VERBOSE_STATUS) printf
#define KR_DNAME_GET_STR(dname_str, dname) \
char dname_str[KR_DNAME_STR_MAXLEN]; \
diff --git a/modules/http/http_trace.lua b/modules/http/http_trace.lua
index 2e89aa2d6..7aec8453d 100644
--- a/modules/http/http_trace.lua
+++ b/modules/http/http_trace.lua
@@ -1,33 +1,7 @@
-- SPDX-License-Identifier: GPL-3.0-or-later
local ffi = require('ffi')
-local bit = require('bit')
local condition = require('cqueues.condition')
--- Buffer selected record information to a table
-local function add_selected_records(dst, records)
- for _, rec in ipairs(records) do
- local rank = rec.rank
- -- Separate the referral chain verified flag
- local verified = bit.band(rec.rank, kres.rank.AUTH)
- if verified then
- rank = bit.band(rank, bit.bnot(kres.rank.AUTH))
- end
- local rank_name = kres.tostring.rank[rank] or tostring(rank)
- -- Write out each individual RR
- for rr in tostring(rec.rr):gmatch('[^\n]+\n?') do
- local row = string.format('cached: %s, rank: %s, record: %s',
- rec.cached, rank_name:lower(), rr)
- table.insert(dst, row)
- end
- end
-end
-
-local function format_selected_records(header, records)
- if #records == 0 then return '' end
- return string.format('%s\n%s\n', header, string.rep('-', #header))
- .. table.concat(records, '') .. '\n'
-end
-
-- Trace execution of DNS queries
local function serve_trace(h, _)
local path = h:get(':path')
@@ -48,21 +22,17 @@ local function serve_trace(h, _)
-- Create logging handler callback
local buffer = {}
- local buffer_log_cb = ffi.cast('trace_log_f', function (query, source, msg)
- local message = string.format('[%5s] [%s] %s',
- query.id, ffi.string(source), ffi.string(msg))
- table.insert(buffer, message)
+ local buffer_log_cb = ffi.cast('trace_log_f', function (msg)
+ table.insert(buffer, ffi.string(msg))
end)
-- Wait for the result of the query
-- Note: We can't do non-blocking write to stream directly from resolve callbacks
-- because they don't run inside cqueue.
- local answers, authority = {}, {}
local cond = condition.new()
local waiting, done = false, false
local finish_cb = ffi.cast('trace_callback_f', function (req)
- add_selected_records(answers, req.answ_selected)
- add_selected_records(authority, req.auth_selected)
+ table.insert(buffer, req:selected_tostring())
if waiting then
cond:signal()
end
@@ -90,9 +60,7 @@ local function serve_trace(h, _)
finish_cb:free()
-- Build the result
- local result = table.concat(buffer, '') .. '\n'
- .. format_selected_records('Used records from answer:', answers)
- .. format_selected_records('Used records from authority:', authority)
+ local result = table.concat(buffer, '')
-- Return buffered data
if not done then
return 504, result
diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua
index 2cc8f5ed6..6d6ea1c95 100644
--- a/modules/policy/policy.lua
+++ b/modules/policy/policy.lua
@@ -527,6 +527,56 @@ function policy.DENY_MSG(msg)
return kres.DONE
end
end
+
+local debug_logline_cb = ffi.cast('trace_log_f', function (msg)
+ -- msg typically ends with newline
+ io.write(ffi.string(msg))
+end)
+
+local debug_logselected_cb = ffi.cast('trace_callback_f', function (req)
+ print(req:selected_tostring())
+end)
+
+function policy.DEBUG(_, req)
+ policy.QTRACE(_, req)
+ req.trace_log = debug_logline_cb
+ req.trace_finish = debug_logselected_cb
+ return
+end
+
+local function request_answered_from_cache(req)
+ local rplan = ffi.C.kr_resolve_plan(req)
+ if tonumber(rplan.pending.len) > 0 then
+ -- an unresolved query, i.e. something is missing from the cache
+ return false
+ end
+ for idx=0, tonumber(rplan.resolved.len) - 1 do
+ if not rplan.resolved.at[idx].flags.CACHED then
+ return false
+ end
+ end
+ return true
+end
+
+function policy.DEBUG_CACHE_MISS(_, req)
+ policy.QTRACE(_, req)
+ local debug_log_buf = {}
+ req.trace_log = ffi.cast('trace_log_f', function (msg)
+ -- stash messages for conditional logging in trace_finish
+ table.insert(debug_log_buf, ffi.string(msg))
+ end)
+
+ req.trace_finish = ffi.cast('trace_callback_f', function (cbreq)
+ if not request_answered_from_cache(cbreq) then
+ log(table.concat(debug_log_buf, ''))
+ log(cbreq:selected_tostring())
+ end
+ req.trace_log:free()
+ req.trace_finish:free()
+ end)
+ return
+end
+
policy.DENY = policy.DENY_MSG() -- compatibility with < 2.0
function policy.DROP(_, _)
diff --git a/modules/rebinding/rebinding.lua b/modules/rebinding/rebinding.lua
index 3ba9db6d0..9a4cfca49 100644
--- a/modules/rebinding/rebinding.lua
+++ b/modules/rebinding/rebinding.lua
@@ -114,7 +114,7 @@ function M.layer.consume(state, req, pkt)
--]]
if qry.parent == nil then refuse(req) end
if verbose() then
- ffi.C.kr_log_qverbose_impl(qry, 'rebinding',
+ ffi.C.kr_qlog(qry, 'rebinding',
'blocking blacklisted IP in RR \'%s\' received from IP %s\n',
kres.rr2str(bad_rr),
tostring(kres.sockaddr_t(req.upstream.addr)))
diff --git a/modules/watchdog/watchdog.lua b/modules/watchdog/watchdog.lua
index fc22dfda3..f51da18b4 100644
--- a/modules/watchdog/watchdog.lua
+++ b/modules/watchdog/watchdog.lua
@@ -22,14 +22,8 @@ end
-- logging
local function add_tracer(logbuf)
return function (req)
- local function qrylogger(qry, src, msg)
- local req_uid = (qry and qry.request and qry.request.uid) or 0
- local qry_uid = (qry and qry.uid) or 0
- local logline = string.format("[%05u.%02u][%s] %s", req_uid, qry_uid, ffi.string(src), ffi.string(msg))
- table.insert(logbuf, logline)
- if verbose() then -- without this message would be missing in verbose log
- ffi.C.kr_log_qverbose_impl(qry, src, msg)
- end
+ local function qrylogger(msg)
+ table.insert(logbuf, ffi.string(msg))
end
req.trace_log = ffi.cast('trace_log_f', qrylogger)
end
--
GitLab