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.
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 {
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 *);
"
# Nameservers
kr_nsrep_set
# Utils
- kr_log_qverbose_impl
+ kr_qlog
kr_make_query
kr_pkt_make_auth_header
kr_pkt_put
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
==========
*/
#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
/* 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;
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, ...)
/** @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__)
/** 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.
*/
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. */
/** 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]; \
-- 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')
-- 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
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
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(_, _)
--]]
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)))
-- 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
projects / thirdparty / knot-resolver.git / commitdiff
