From: Vladimír Čunát <vladimir.cunat@nic.cz>
Date: Thu, 25 Jan 2018 12:25:57 +0000 (+0100)
Subject: cache: fix logging after parent merge
X-Git-Tag: v2.0.0~6^2~13
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=a444fdb40b959f17563dec89db5e73d544b6e5b4;p=thirdparty%2Fknot-resolver.git

cache: fix logging after parent merge
---

diff --git a/lib/cache.c b/lib/cache.c
index bc8ef4dc1..9b38d0a60 100644
--- a/lib/cache.c
+++ b/lib/cache.c
@@ -329,9 +329,9 @@ static int cache_peek_real(kr_layer_t *ctx, knot_pkt_t *pkt)
 
 	struct key k_storage, *k = &k_storage;
 	if (!check_dname_for_lf(qry->sname)) {
-		WITH_VERBOSE {
-			VERBOSE_MSG(qry, "=> skipping zero-containing name ");
-			kr_dname_print(qry->sname, "", "\n");
+		WITH_VERBOSE(qry) {
+			auto_free char *sname_str = kr_dname_text(qry->sname);
+			VERBOSE_MSG(qry, "=> skipping zero-containing sname %s\n", sname_str);
 		}
 		return ctx->state;
 	}
@@ -371,9 +371,9 @@ static int cache_peek_real(kr_layer_t *ctx, knot_pkt_t *pkt)
 	}
 	switch (k->type) {
 	case KNOT_RRTYPE_NS:
-		WITH_VERBOSE {
-			VERBOSE_MSG(qry, "=> trying zone: ");
-			kr_dname_print(k->zname, "", "\n");
+		WITH_VERBOSE(qry) {
+			auto_free char *zname_str = kr_dname_text(k->zname);
+			VERBOSE_MSG(qry, "=> trying zone: %s\n", zname_str);
 		}
 		break;
 	case KNOT_RRTYPE_CNAME: {
@@ -517,9 +517,10 @@ static int cache_peek_real(kr_layer_t *ctx, knot_pkt_t *pkt)
 						ret, strerror(abs(ret)));
 				assert(false);
 			}
-			WITH_VERBOSE {
-				VERBOSE_MSG(qry, "=> wildcard: not found: ");
-				kr_dname_print(clencl_name, "*.", "\n");
+			WITH_VERBOSE(qry) {
+				auto_free char *clencl_str = kr_dname_text(clencl_name);
+				VERBOSE_MSG(qry, "=> wildcard: not found: *.%s\n",
+						clencl_str);
 			}
 			return ctx->state;
 		}
@@ -568,9 +569,8 @@ do_soa:
 		/* Check if the record is OK. */
 		int32_t new_ttl = get_new_ttl(eh, qry, k->zname, KNOT_RRTYPE_SOA);
 		if (new_ttl < 0 || eh->rank < lowest_rank || eh->is_packet) {
-			VERBOSE_MSG(qry, "=> SOA unfit %s: ",
-					eh->is_packet ? "packet" : "RR");
-			kr_log_verbose("rank 0%0.2o, new TTL %d\n",
+			VERBOSE_MSG(qry, "=> SOA unfit %s: rank 0%0.2o, new TTL %d\n",
+					(eh->is_packet ? "packet" : "RR"),
 					eh->rank, new_ttl);
 			return ctx->state;
 		}
@@ -697,9 +697,10 @@ static int stash_rrset(const ranked_rr_array_t *arr, int arr_i,
 		return kr_error(EINVAL);
 	}
 	if (!check_dname_for_lf(rr->owner)) {
-		WITH_VERBOSE {
-			VERBOSE_MSG(qry, "=> skipping zero-containing name ");
-			kr_dname_print(rr->owner, "", "\n");
+		WITH_VERBOSE(qry) {
+			auto_free char *owner_str = kr_dname_text(rr->owner);
+			VERBOSE_MSG(qry, "=> skipping zero-containing name %s\n",
+					owner_str);
 		}
 		return kr_ok();
 	}
@@ -816,14 +817,14 @@ static int stash_rrset(const ranked_rr_array_t *arr, int arr_i,
 	}
 	assert(entry_h_consistent(val_new_entry, rr->type));
 
-	WITH_VERBOSE {
-		VERBOSE_MSG(qry, "=> stashed rank: 0%0.2o, ", entry->rank);
-		kr_rrtype_print(rr->type, "", " ");
-		kr_dname_print(encloser, wild_labels ? "*." : "", " ");
-		kr_log_verbose("(%d B total, incl. %d RRSIGs)\n",
-				(int)val_new_entry.len,
-				(rr_sigs ? rr_sigs->rrs.rr_count : 0)
-				);
+	WITH_VERBOSE(qry) {
+		auto_free char *type_str = kr_rrtype_text(rr->type),
+			*encl_str = kr_dname_text(encloser);
+		VERBOSE_MSG(qry, "=> stashed rank: 0%0.2o, %s %s%s"
+			"(%d B total, incl. %d RRSIGs)\n",
+			entry->rank, type_str, (wild_labels ? "*." : ""), encl_str,
+			(int)val_new_entry.len, (rr_sigs ? rr_sigs->rrs.rr_count : 0)
+			);
 	}
 	return kr_ok();
 }
@@ -905,35 +906,23 @@ static int found_exact_hit(kr_layer_t *ctx, knot_pkt_t *pkt, knot_db_val_t val,
 	}
 }
 
-int kr_cache_peek_exact(struct kr_cache *cache, const knot_dname_t *name, uint16_t type,
+static int peek_exact_real(struct kr_cache *cache, const knot_dname_t *name, uint16_t type,
 			struct kr_cache_p *peek)
 {
 	struct key k_storage, *k = &k_storage;
 
-	WITH_VERBOSE {
-		VERBOSE_MSG(NULL, "_peek_exact: ");
-		kr_rrtype_print(type, "", " ");
-		kr_dname_print(name, "", " ");
-	}
-
 	int ret = kr_dname_lf(k->buf, name, false);
-	if (ret) {
-		kr_log_verbose("ERROR!\n");
-		return kr_error(ret);
-	}
+	if (ret) return kr_error(ret);
 
 	knot_db_val_t key = key_exact_type(k, type);
 	knot_db_val_t val = { NULL, 0 };
 	ret = cache_op(cache, read, &key, &val, 1);
 	if (!ret) ret = entry_h_seek(&val, type);
-	if (ret) {
-		kr_log_verbose("miss (ret: %d)\n", ret);
-		return ret;
-	}
+	if (ret) return kr_error(ret);
+
 	const struct entry_h *eh = entry_h_consistent(val, type);
 	if (!eh || eh->is_packet) {
 		// TODO: no packets, but better get rid of whole kr_cache_peek_exact().
-		kr_log_verbose("miss\n");
 		return kr_error(ENOENT);
 	}
 	*peek = (struct kr_cache_p){
@@ -943,9 +932,22 @@ int kr_cache_peek_exact(struct kr_cache *cache, const knot_dname_t *name, uint16
 		.raw_data = val.data,
 		.raw_bound = val.data + val.len,
 	};
-	kr_log_verbose("hit\n");
 	return kr_ok();
 }
+int kr_cache_peek_exact(struct kr_cache *cache, const knot_dname_t *name, uint16_t type,
+			struct kr_cache_p *peek)
+{	/* Just wrap with extra verbose logging. */
+	const int ret = peek_exact_real(cache, name, type, peek);
+	if (VERBOSE_STATUS) {
+		auto_free char *type_str = kr_rrtype_text(type),
+			*name_str = kr_dname_text(name);
+		const char *result_str = (ret == kr_ok() ? "hit" :
+				(ret == kr_error(ENOENT) ? "miss" : "error"));
+		VERBOSE_MSG(NULL, "_peek_exact: %s %s %s (ret: %d)",
+				type_str, name_str, result_str, ret);
+	}
+	return ret;
+}
 
 /** Find the longest prefix NS/xNAME (with OK time+rank), starting at k->*.
  * We store xNAME at NS type to lower the number of searches.
@@ -1034,12 +1036,15 @@ static knot_db_val_t closest_NS(kr_layer_t *ctx, struct key *k)
 			     * as insecure or even nonauth is OK */
 			    || (type != KNOT_RRTYPE_NS && eh->rank < rank_min)) {
 
-				WITH_VERBOSE {
-					VERBOSE_MSG(qry, "=> skipping unfit ");
-					kr_rrtype_print(type, "",
-							eh->is_packet ? " packet" : " RR");
-					kr_log_verbose(": rank 0%0.2o, new TTL %d\n",
-							eh->rank, new_ttl);
+				WITH_VERBOSE(qry) {
+					auto_free char *type_str =
+						kr_rrtype_text(type);
+					const char *packet_str =
+						eh->is_packet ? "packet" : "RR";
+					VERBOSE_MSG(qry, "=> skipping unfit %s %s: "
+						"rank 0%0.2o, new TTL %d\n",
+						type_str, packet_str,
+						eh->rank, new_ttl);
 				}
 				continue;
 			}
diff --git a/lib/cache/entry_list.c b/lib/cache/entry_list.c
index d4b1d7f39..4536a921b 100644
--- a/lib/cache/entry_list.c
+++ b/lib/cache/entry_list.c
@@ -19,6 +19,7 @@
  */
 
 #include "lib/cache/impl.h"
+#include "lib/utils.h"
 
 
 /** Given a valid entry header, find its length (i.e. offset of the next entry).
@@ -165,10 +166,11 @@ int entry_h_splice(
 		int32_t old_ttl = get_new_ttl(eh_orig, qry, NULL, 0);
 		if (old_ttl > 0 && !is_expiring(old_ttl, eh_orig->ttl)
 		    && rank <= eh_orig->rank) {
-			WITH_VERBOSE {
-				VERBOSE_MSG(qry, "=> not overwriting ");
-				kr_rrtype_print(type, "", " ");
-				kr_dname_print(owner, "", "\n");
+			WITH_VERBOSE(qry) {
+				auto_free char *type_str = kr_rrtype_text(type),
+					*owner_str = kr_dname_text(owner);
+				VERBOSE_MSG(qry, "=> not overwriting %s %s\n",
+						type_str, owner_str);
 			}
 			return kr_error(EEXIST);
 		}
diff --git a/lib/cache/entry_pkt.c b/lib/cache/entry_pkt.c
index 2491abd07..e355b2406 100644
--- a/lib/cache/entry_pkt.c
+++ b/lib/cache/entry_pkt.c
@@ -158,12 +158,13 @@ void stash_pkt(const knot_pkt_t *pkt, const struct kr_query *qry,
 	memcpy(eh->data, &pkt_size, sizeof(pkt_size));
 	memcpy(eh->data + sizeof(pkt_size), pkt->wire, pkt_size);
 
-	WITH_VERBOSE {
-		VERBOSE_MSG(qry, "=> stashed packet: rank 0%0.2o, TTL %d, ",
-				eh->rank, eh->ttl);
-		kr_rrtype_print(pkt_type, "", " ");
-		kr_dname_print(owner, "", " ");
-		kr_log_verbose("(%d B)\n", (int)val_new_entry.len);
+	WITH_VERBOSE(qry) {
+		auto_free char *type_str = kr_rrtype_text(pkt_type),
+			*owner_str = kr_dname_text(owner);
+		VERBOSE_MSG(qry, "=> stashed packet: rank 0%0.2o, TTL %d, "
+				"%s %s (%d B)\n",
+				eh->rank, eh->ttl,
+				type_str, owner_str, (int)val_new_entry.len);
 	}
 }
 
diff --git a/lib/cache/impl.h b/lib/cache/impl.h
index c4215716d..a3abfb2c8 100644
--- a/lib/cache/impl.h
+++ b/lib/cache/impl.h
@@ -27,6 +27,7 @@
 #include <libknot/db/db.h>
 #include <libknot/dname.h>
 
+#include "contrib/cleanup.h"
 #include "lib/cdb.h"
 #include "lib/resolve.h"
 
diff --git a/lib/cache/nsec1.c b/lib/cache/nsec1.c
index 10a2193a4..ce1c39f0d 100644
--- a/lib/cache/nsec1.c
+++ b/lib/cache/nsec1.c
@@ -343,11 +343,11 @@ int nsec1_encloser(struct key *k, struct answer *ans,
 		return ESKIP;
 	}
 	/* NXDOMAIN proven *except* for wildcards. */
-	WITH_VERBOSE {
-		VERBOSE_MSG(qry, "=> NSEC sname: covered by: ");
-		kr_dname_print(nsec_rr->owner, "", " -> ");
-		kr_dname_print(knot_nsec_next(&nsec_rr->rrs), "", ", ");
-		kr_log_verbose("new TTL %d\n", new_ttl);
+	WITH_VERBOSE(qry) {
+		auto_free char *owner_str = kr_dname_text(nsec_rr->owner),
+			  *next_str = kr_dname_text(knot_nsec_next(&nsec_rr->rrs));
+		VERBOSE_MSG(qry, "=> NSEC sname: covered by: %s -> %s, new TTL %d\n",
+				owner_str, next_str, new_ttl);
 	}
 
 	/* Find label count of the closest encloser.
@@ -477,11 +477,11 @@ int nsec1_src_synth(struct key *k, struct answer *ans, const knot_dname_t *clenc
 			goto clean_wild;
 		}
 		/* We have a record proving wildcard non-existence. */
-		WITH_VERBOSE {
-			VERBOSE_MSG(qry, "=> NSEC wildcard: covered by: ");
-			kr_dname_print(nsec_rr->owner, "", " -> ");
-			kr_dname_print(knot_nsec_next(&nsec_rr->rrs), "", ", ");
-			kr_log_verbose("new TTL %d\n", new_ttl_log);
+		WITH_VERBOSE(qry) {
+			auto_free char *owner_str = kr_dname_text(nsec_rr->owner),
+				  *next_str = kr_dname_text(knot_nsec_next(&nsec_rr->rrs));
+			VERBOSE_MSG(qry, "=> NSEC wildcard: covered by: %s -> %s, new TTL %d\n",
+					owner_str, next_str, new_ttl_log);
 		}
 		return AR_SOA;
 	}
@@ -489,14 +489,15 @@ int nsec1_src_synth(struct key *k, struct answer *ans, const knot_dname_t *clenc
 	/* The wildcard exists.  Find if it's NODATA - check type bitmap. */
 	if (kr_nsec_bitmap_nodata_check(bm, bm_size, qry->stype) == 0) {
 		/* NODATA proven; just need to add SOA+RRSIG later */
-		WITH_VERBOSE {
-			VERBOSE_MSG(qry, "=> NSEC wildcard: match proved NODATA");
+		WITH_VERBOSE(qry) {
+			const char *msg_start = "=> NSEC wildcard: match proved NODATA";
 			if (arw->set.rr) {
-				/* ^^ don't repeat the RR if it's the same */
-				kr_dname_print(nsec_rr->owner, ": ", ", ");
-				kr_log_verbose("new TTL %d\n", new_ttl_log);
+				auto_free char *owner_str = kr_dname_text(nsec_rr->owner);
+				VERBOSE_MSG(qry, "%s: %s, new TTL %d\n",
+						msg_start, owner_str, new_ttl_log);
 			} else {
-				kr_log_verbose(", by the same RR\n");
+				/* don't repeat the RR if it's the same */
+				VERBOSE_MSG(qry, "%s, by the same RR\n", msg_start);
 			}
 		}
 		ans->rcode = PKT_NODATA;
diff --git a/lib/layer/iterate.c b/lib/layer/iterate.c
index b8e646968..6579b00e2 100644
--- a/lib/layer/iterate.c
+++ b/lib/layer/iterate.c
@@ -278,9 +278,11 @@ static int update_cut(knot_pkt_t *pkt, const knot_rrset_t *rr,
 		const knot_dname_t *ns_name = knot_ns_name(&rr->rrs, i);
 		/* Glue is mandatory for NS below zone */
 		if (knot_dname_in(rr->owner, ns_name) && !has_glue(pkt, ns_name)) {
-			VERBOSE_MSG("<= authority: missing mandatory glue, skipping NS ");
-			WITH_VERBOSE {
-				kr_dname_print(ns_name, "", "\n");
+			const char *msg =
+				"<= authority: missing mandatory glue, skipping NS\n";
+			WITH_VERBOSE(qry) {
+				auto_free char *ns_str = kr_dname_text(ns_name);
+				VERBOSE_MSG("%s%s", msg, ns_str);
 			}
 			continue;
 		}
diff --git a/lib/zonecut.c b/lib/zonecut.c
index ce326da82..9e46a2e65 100644
--- a/lib/zonecut.c
+++ b/lib/zonecut.c
@@ -22,11 +22,14 @@
 
 #include "lib/zonecut.h"
 #include "lib/rplan.h"
+#include "contrib/cleanup.h"
 #include "lib/defines.h"
 #include "lib/layer.h"
 #include "lib/resolve.h"
 #include "lib/generic/pack.h"
 
+#define VERBOSE_MSG(qry, fmt...) QRVERBOSE(qry, "zcut", fmt)
+
 /* Root hint descriptor. */
 struct hint_info {
 	const knot_dname_t *name;
@@ -390,7 +393,7 @@ int kr_zonecut_find_cached(struct kr_context *ctx, struct kr_zonecut *cut,
 			   const knot_dname_t *name, const struct kr_query *qry,
 			   bool * restrict secured)
 {
-	kr_log_verbose("[     ][ *c ] kr_zonecut_find_cached\n");
+	VERBOSE_MSG(qry, "_find_cached\n");
 	if (!ctx || !cut || !name) {
 		return kr_error(EINVAL);
 	}
@@ -420,8 +423,9 @@ int kr_zonecut_find_cached(struct kr_context *ctx, struct kr_zonecut *cut,
 			update_cut_name(cut, label);
 			mm_free(cut->pool, qname);
 			kr_cache_sync(&ctx->cache);
-			WITH_VERBOSE {
-				kr_dname_print(label, "[     ][ *c ] and found cut: ", "\n");
+			WITH_VERBOSE(qry) {
+				auto_free char *label_str = kr_dname_text(label);
+				VERBOSE_MSG(qry, "  and found cut: %s\n", label_str);
 			}
 			return kr_ok();
 		}