From: Petr Špaček Date: Fri, 13 Mar 2020 17:23:33 +0000 (+0100) Subject: policy.DEBUG: log also final answer X-Git-Tag: v5.1.0~26^2~11 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=75bc47be522468e240c815659dbf37aacd8ee51a;p=thirdparty%2Fknot-resolver.git policy.DEBUG: log also final answer Attempt to avoid duplicating ten lines in debug_logfinish_cb lead me to splitting kr_log_qverbose_impl into two functions kr_log_q and kr_log_req. This is another minor change to API exposed to modules. --- diff --git a/daemon/lua/kres-gen.lua b/daemon/lua/kres-gen.lua index 40588282f..2a94e4d24 100644 --- a/daemon/lua/kres-gen.lua +++ b/daemon/lua/kres-gen.lua @@ -327,7 +327,8 @@ int kr_rplan_pop(struct kr_rplan *, struct kr_query *); struct kr_query *kr_rplan_resolved(struct kr_rplan *); struct kr_query *kr_rplan_last(struct kr_rplan *); int kr_nsrep_set(struct kr_query *, size_t, const struct sockaddr *); -void kr_log_qverbose_impl(const struct kr_query *, const char *, const char *, ...); +void kr_log_req(const struct kr_request * const, uint32_t, const unsigned int, const char *, const char *, ...); +void kr_log_q(const struct kr_query * const, const char *, const char *, ...); int kr_make_query(struct kr_query *, knot_pkt_t *); void kr_pkt_make_auth_header(knot_pkt_t *); int kr_pkt_put(knot_pkt_t *, const knot_dname_t *, uint32_t, uint16_t, uint16_t, const uint8_t *, uint16_t); diff --git a/daemon/lua/kres-gen.sh b/daemon/lua/kres-gen.sh index 785110e66..accbdd0fc 100755 --- a/daemon/lua/kres-gen.sh +++ b/daemon/lua/kres-gen.sh @@ -190,7 +190,8 @@ ${CDEFS} ${LIBKRES} functions <<-EOF # Nameservers kr_nsrep_set # Utils - kr_qlog + kr_log_req + kr_log_q kr_make_query kr_pkt_make_auth_header kr_pkt_put diff --git a/lib/layer.h b/lib/layer.h index 35d0064eb..2a1328997 100644 --- a/lib/layer.h +++ b/lib/layer.h @@ -18,8 +18,8 @@ */ #define QRVERBOSE(_query, _cls, ...) do { \ const struct kr_query *_qry = (_query); \ - if (VERBOSE_STATUS || kr_log_trace_enabled(_qry)) { \ - kr_qlog(_qry, (_cls), __VA_ARGS__); \ + if (VERBOSE_STATUS || kr_log_qtrace_enabled(_qry)) { \ + kr_log_q(_qry, (_cls), __VA_ARGS__); \ } \ } while (false) #endif diff --git a/lib/utils.c b/lib/utils.c index c48b2cfd0..3998699f2 100644 --- a/lib/utils.c +++ b/lib/utils.c @@ -120,31 +120,50 @@ bool kr_verbose_set(bool status) return kr_verbose_status; } -void kr_qlog(const struct kr_query *qry, const char *source, const char *fmt, ...) +static void kr_vlog_req( + const struct kr_request * const req, uint32_t qry_uid, + const unsigned int indent, const char *source, const char *fmt, + va_list args) { struct mempool *mp = mp_new(512); - 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; + const uint32_t req_uid = req ? req->uid : 0; + char *msg = mp_printf(mp, "[%05u.%02u][%-4s] %*s", + req_uid, qry_uid, source, indent, ""); - char *msg = mp_printf(mp, "[%05u.%02u][%s] %*s", req_uid, qry_uid, source, ind, ""); - - va_list args; - va_start(args, fmt); msg = mp_vprintf_append(mp, msg, fmt, args); - va_end(args); - if (kr_log_trace_enabled(qry)) - qry->request->trace_log(msg); + if (kr_log_rtrace_enabled(req)) + req->trace_log(msg); else /* caller is responsible for detecting verbose mode, use QRVERBOSE() macro */ printf("%s", msg); mp_delete(mp); - return; +} + +void kr_log_req(const struct kr_request * const req, uint32_t qry_uid, + const unsigned int indent, const char *source, const char *fmt, ...) +{ + va_list args; + va_start(args, fmt); + kr_vlog_req(req, qry_uid, indent, source, fmt, args); + va_end(args); +} + +void kr_log_q(const struct kr_query * const qry, + const char *source, const char *fmt, ...) +{ + unsigned ind = 0; + for (const struct kr_query *q = qry; q; q = q->parent) + ind += 2; + const uint32_t qry_uid = qry ? qry->uid : 0; + const struct kr_request *req = qry ? qry->request : NULL; + + va_list args; + va_start(args, fmt); + kr_vlog_req(req, qry_uid, ind, source, fmt, args); + va_end(args); } char* kr_strcatdup(unsigned n, ...) diff --git a/lib/utils.h b/lib/utils.h index 09b12197c..a99170e69 100644 --- a/lib/utils.h +++ b/lib/utils.h @@ -53,10 +53,26 @@ KR_EXPORT bool kr_verbose_set(bool status); /** * @brief Return true if the query has request log handler installed. */ -#define kr_log_trace_enabled(query) (__builtin_expect( \ - (query) && (query)->request && (query)->request->trace_log, \ +#define kr_log_rtrace_enabled(req) (__builtin_expect( \ + (req) && (req)->trace_log, \ false)) +#define kr_log_qtrace_enabled(qry) (__builtin_expect( \ + (qry) && kr_log_rtrace_enabled(qry->request), \ + false)) + +/** + * Log a message through the request log handler or stdout. + * Caller is responsible for detecting verbose mode, use QRVERBOSE() macro. + * @param qry_uid query ID to append to request ID, 0 means "no query" + * @param indent level of indentation between [req.qry][source] and message + * @param source message source + * @param fmt message format + */ +void kr_log_req(const struct kr_request * const req, uint32_t qry_uid, + const unsigned int indent, const char *source, const char *fmt, ...) +KR_EXPORT KR_PRINTF(5); + /** * Log a message through the request log handler or stdout. * Caller is responsible for detecting verbose mode, use QRVERBOSE() macro. @@ -64,7 +80,7 @@ KR_EXPORT bool kr_verbose_set(bool status); * @param source message source * @param fmt message format */ -void kr_qlog(const struct kr_query *query, const char *source, const char *fmt, ...) +void kr_log_q(const struct kr_query *qry, const char *source, const char *fmt, ...) KR_EXPORT KR_PRINTF(3); #ifdef NOVERBOSELOG @@ -75,7 +91,7 @@ KR_EXPORT KR_PRINTF(3); /** 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 WITH_VERBOSE(query) if(__builtin_expect(kr_verbose_status || kr_log_qtrace_enabled(query), false)) #define kr_log_verbose if(VERBOSE_STATUS) printf #define KR_DNAME_GET_STR(dname_str, dname) \ diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua index 6d6ea1c95..f4dcce33d 100644 --- a/modules/policy/policy.lua +++ b/modules/policy/policy.lua @@ -533,14 +533,19 @@ local debug_logline_cb = ffi.cast('trace_log_f', function (msg) io.write(ffi.string(msg)) end) -local debug_logselected_cb = ffi.cast('trace_callback_f', function (req) - print(req:selected_tostring()) +local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req) + ffi.C.kr_log_req(req, 0, 0, 'dbg', + 'following rrsets were marked as interesting:\n' .. + req:selected_tostring()) + ffi.C.kr_log_req(req, 0, 0, 'dbg', + 'answer packet:\n' .. + tostring(req.answer)) end) function policy.DEBUG(_, req) policy.QTRACE(_, req) req.trace_log = debug_logline_cb - req.trace_finish = debug_logselected_cb + req.trace_finish = debug_logfinish_cb return end @@ -568,8 +573,8 @@ function policy.DEBUG_CACHE_MISS(_, req) 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()) + debug_logfinish_cb(cbreq) -- unconditional version + io.write(table.concat(debug_log_buf, '')) end req.trace_log:free() req.trace_finish:free() diff --git a/modules/rebinding/rebinding.lua b/modules/rebinding/rebinding.lua index 9a4cfca49..171e5edcd 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_qlog(qry, 'rebinding', + ffi.C.kr_log_q(qry, 'rebinding', 'blocking blacklisted IP in RR \'%s\' received from IP %s\n', kres.rr2str(bad_rr), tostring(kres.sockaddr_t(req.upstream.addr)))