From: Marek Vavruša <mvavrusa@cloudflare.com>
Date: Mon, 27 Nov 2017 22:19:10 +0000 (-0800)
Subject: lib/resolve: add support for per-request logging
X-Git-Tag: v2.0.0~16^2~23
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=0a04428ef02c8e237c6dcdd769e2e7c871572d6c;p=thirdparty%2Fknot-resolver.git

lib/resolve: add support for per-request logging

This is useful in many troubleshooting scenarios when you want debug logs
just for a single request. It's going to expand on TRACE flag functionality
in the next PRs, so that special requests can be invoked with various tracers attached.

Currently this is only available in the C modules that can set the callback,
it's not called anywhere in the library yet.
---

diff --git a/daemon/lua/kres-gen.lua b/daemon/lua/kres-gen.lua
index b76e5eb17..3cf3656a7 100644
--- a/daemon/lua/kres-gen.lua
+++ b/daemon/lua/kres-gen.lua
@@ -10,6 +10,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 enum {KNOT_ANSWER, KNOT_AUTHORITY, KNOT_ADDITIONAL} knot_section_t;
 typedef struct {
 	uint16_t pos;
@@ -159,6 +160,7 @@ struct kr_request {
 	_Bool auth_validated;
 	struct kr_rplan rplan;
 	int has_tls;
+	trace_log_f trace_log;
 	knot_mm_t pool;
 };
 enum kr_rank {KR_RANK_INITIAL, KR_RANK_OMIT, KR_RANK_TRY, KR_RANK_INDET = 4, KR_RANK_BOGUS, KR_RANK_MISMATCH, KR_RANK_MISSING, KR_RANK_INSECURE, KR_RANK_AUTH = 16, KR_RANK_SECURE = 32};
diff --git a/daemon/lua/kres-gen.sh b/daemon/lua/kres-gen.sh
index df066a2f6..26a454d51 100755
--- a/daemon/lua/kres-gen.sh
+++ b/daemon/lua/kres-gen.sh
@@ -32,6 +32,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 *);
 "
 
 ./scripts/gen-cdefs.sh libkres types <<-EOF
diff --git a/lib/resolve.c b/lib/resolve.c
index 04445afd3..cb3741695 100644
--- a/lib/resolve.c
+++ b/lib/resolve.c
@@ -719,6 +719,7 @@ int kr_resolve_begin(struct kr_request *request, struct kr_context *ctx, knot_pk
 	array_init(request->auth_selected);
 	request->answ_validated = false;
 	request->auth_validated = false;
+	request->trace_log = NULL;
 
 	/* Expect first query */
 	kr_rplan_init(&request->rplan, request, &request->pool);
diff --git a/lib/resolve.h b/lib/resolve.h
index ab7b53e19..f6a4a30f8 100644
--- a/lib/resolve.h
+++ b/lib/resolve.h
@@ -203,6 +203,7 @@ struct kr_request {
 	bool auth_validated; /**< see answ_validated ^^ ; TODO */
 	struct kr_rplan rplan;
 	int has_tls;
+	trace_log_f trace_log; /**< Logging tracepoint */
 	knot_mm_t pool;
 };
 
diff --git a/lib/utils.c b/lib/utils.c
index bb4b50e1e..3d618cff9 100644
--- a/lib/utils.c
+++ b/lib/utils.c
@@ -21,6 +21,7 @@
 #include <arpa/inet.h>
 #include <sys/time.h>
 #include <contrib/cleanup.h>
+#include <contrib/ccan/asprintf/asprintf.h>
 #include <ccan/isaac/isaac.h>
 #include <gnutls/gnutls.h>
 #include <libknot/descriptor.h>
@@ -106,6 +107,28 @@ void kr_log_verbose(const char *fmt, ...)
 	}
 }
 
+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;
+
+	va_list args;
+	va_start(args, fmt);
+	int len = vasprintf(&msg, fmt, args);
+	va_end(args);
+
+	/* Check formatting result before logging */
+	if (len < 0) {
+		return false;
+	}
+
+	query->request->trace_log(query, source, msg);
+	return true;
+}
+
 char* kr_strcatdup(unsigned n, ...)
 {
 	/* Calculate total length */
diff --git a/lib/utils.h b/lib/utils.h
index de727771a..35c739bb1 100644
--- a/lib/utils.h
+++ b/lib/utils.h
@@ -36,6 +36,10 @@ struct kr_query;
 /*
  * Logging and debugging.
  */
+
+/** @brief Callback for request logging handler. */
+typedef void *(*trace_log_f)(const struct kr_query *query, const char *source, const char *msg);
+
 #define kr_log_info(fmt, ...) do { printf((fmt), ## __VA_ARGS__); fflush(stdout); } while(0)
 #define kr_log_error(fmt, ...) fprintf(stderr, (fmt), ## __VA_ARGS__)
 
@@ -49,6 +53,20 @@ KR_EXPORT bool kr_verbose_set(bool status);
 /** Log a message if in --verbose mode. */
 KR_EXPORT void kr_log_verbose(const char *fmt, ...);
 
+/**
+ * @brief Return true if the query has request log handler installed.
+ */
+#define kr_log_trace_enabled(query) ((query) && (query)->request && (query)->request->trace_log)
+
+/**
+ * Log a message through the request log handler.
+ * @param  query current query
+ * @param  source message source
+ * @param  fmt message format
+ * @return true if the message was logged
+ */
+KR_EXPORT bool kr_log_trace(const struct kr_query *query, const char *source, const char *fmt, ...);
+
 #ifdef NOVERBOSELOG
 /* Efficient compile-time disabling of verbose messages. */
 #define kr_verbose_status false