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 40588282f6c1866220330571476977fb7217a6e3..2a94e4d2445427c3a52afaa0b30722d4620bf0f3 100644 (file)
--- 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 785110e66124dde61646892c0b7d876b23d8a22c..accbdd0fcb13bde4e8a22c8bb30c6872c9bb6bf6 100755 (executable)
--- 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 35d0064ebb61dac4efa6a0fb66707221dc6ae43e..2a1328997404503079ab4c9aea6535dfc228e385 100644 (file)
--- 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 c48b2cfd003c05ef0fd3b8a634b21dfa0b3e5f4a..3998699f2c354ded9525868244873cc9f845addf 100644 (file)
--- 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 09b12197c3e5e31e8777ccd8c1672f2ddacd41d0..a99170e690d56d84fe5bcbcc7a1ade3a6831efe1 100644 (file)
--- 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 6d6ea1c95d56bef5f7c840b1ad74950b44b02bf1..f4dcce33dbfca851ebcb7dddf9e8bb0db473d812 100644 (file)
--- 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 9a4cfca49379672285ece646656dbd251937b46c..171e5edcdb1cbdf0dcdabf3345c9fe0634db936b 100644 (file)
--- 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)))