From: Vladimír Čunát <vladimir.cunat@nic.cz>
Date: Fri, 20 Jul 2018 15:35:15 +0000 (+0200)
Subject: cache: better logging of NSEC3 parameters
X-Git-Tag: v2.4.1~7^2~3
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=bd7ffc25b24d85b8bd69b0ea43fe1f5985f62689;p=thirdparty%2Fknot-resolver.git

cache: better logging of NSEC3 parameters
---

diff --git a/lib/cache/api.c b/lib/cache/api.c
index 5d3974276..c7f632621 100644
--- a/lib/cache/api.c
+++ b/lib/cache/api.c
@@ -625,6 +625,13 @@ static int stash_nsec_p(const knot_dname_t *dname, const char *nsec_p_v,
 	static const int32_t ttl_margin = 3600;
 	const uint8_t *nsec_p = (const uint8_t *)nsec_p_v;
 	int data_stride = sizeof(valid_until) + nsec_p_rdlen(nsec_p);
+
+	unsigned int log_hash = 0xFeeeFeee; /* this type is simpler for printf args */
+	auto_free char *log_dname = NULL;
+	WITH_VERBOSE(qry) {
+		log_hash = nsec_p_v ? nsec_p_mkHash((const uint8_t *)nsec_p_v) : 0;
+		log_dname = kr_dname_text(dname);
+	}
 	/* Find what's in the cache. */
 	struct key k_storage, *k = &k_storage;
 	int ret = kr_dname_lf(k->buf, dname, false);
@@ -660,8 +667,9 @@ static int stash_nsec_p(const knot_dname_t *dname, const char *nsec_p_v,
 			memcpy(&valid_orig, el[i].data, sizeof(valid_orig));
 			const int32_t ttl_extended_by = valid_until - valid_orig;
 			if (ttl_extended_by < ttl_margin) {
-				VERBOSE_MSG(qry, "=> nsec_p stash skipped (extra TTL: %d)\n",
-						ttl_extended_by);
+				VERBOSE_MSG(qry,
+					"=> nsec_p stash for %s skipped (extra TTL: %d, hash: %x)\n",
+					log_dname, ttl_extended_by, log_hash);
 				return kr_ok();
 			}
 			i_replace = i;
@@ -694,9 +702,11 @@ static int stash_nsec_p(const knot_dname_t *dname, const char *nsec_p_v,
 		return kr_ok();
 	}
 	if (log_refresh_by) {
-		VERBOSE_MSG(qry, "=> nsec_p stashed (refresh by %d)\n", log_refresh_by);
+		VERBOSE_MSG(qry, "=> nsec_p stashed for %s (refresh by %d, hash: %x)\n",
+				log_dname, log_refresh_by, log_hash);
 	} else {
-		VERBOSE_MSG(qry, "=> nsec_p stashed (new)\n");
+		VERBOSE_MSG(qry, "=> nsec_p stashed for %s (new, hash: %x)\n",
+				log_dname, log_hash);
 	}
 	return kr_ok();
 }
diff --git a/lib/cache/peek.c b/lib/cache/peek.c
index 55a037a82..9c588a7d6 100644
--- a/lib/cache/peek.c
+++ b/lib/cache/peek.c
@@ -36,11 +36,12 @@ static int peek_encloser(
 	uint8_t lowest_rank, const struct kr_query *qry, struct kr_cache *cache);
 
 
-static int nsec_p_init(struct nsec_p *nsec_p, const uint8_t *nsec_p_raw)
+static int nsec_p_init(struct nsec_p *nsec_p, const uint8_t *nsec_p_raw, bool with_knot)
 {
 	nsec_p->raw = nsec_p_raw;
 	if (!nsec_p_raw) return kr_ok();
 	nsec_p->hash = nsec_p_mkHash(nsec_p->raw);
+	if (!with_knot) return kr_ok();
 	/* Convert NSEC3 params to another format. */
 	const dnssec_binary_t rdata = {
 		.size = nsec_p_rdlen(nsec_p->raw),
@@ -150,13 +151,11 @@ int peek_nosync(kr_layer_t *ctx, knot_pkt_t *pkt)
 	}
 
 	/* We have to try proving from NSEC*. */
+	auto_free char *log_zname = NULL;
 	WITH_VERBOSE(qry) {
-		auto_free char *zname_str = kr_dname_text(k->zname);
+		log_zname = kr_dname_text(k->zname);
 		if (!el[0].len) {
-			VERBOSE_MSG(qry, "=> no NSEC* cached for zone: %s\n", zname_str);
-		} else {
-			VERBOSE_MSG(qry, "=> trying zone: %s (first %s)\n", zname_str,
-					(el[0].len == 4 ? "NSEC" : "NSEC3"));
+			VERBOSE_MSG(qry, "=> no NSEC* cached for zone: %s\n", log_zname);
 		}
 	}
 
@@ -194,12 +193,22 @@ int peek_nosync(kr_layer_t *ctx, knot_pkt_t *pkt)
 		uint32_t stamp;
 		memcpy(&stamp, el[i].data, sizeof(stamp));
 		const int32_t remains = stamp - qry->timestamp.tv_sec; /* using SOA serial arith. */
-		if (remains < 0) goto cont;
-		{
+		if (remains >= 0 || VERBOSE_STATUS) {
 			const uint8_t *nsec_p_raw = el[i].len > sizeof(stamp)
 					? (uint8_t *)el[i].data + sizeof(stamp) : NULL;
-			nsec_p_init(&ans.nsec_p, nsec_p_raw);
+			nsec_p_init(&ans.nsec_p, nsec_p_raw, remains >= 0);
 		}
+		if (remains < 0) {
+			VERBOSE_MSG(qry, "=> skipping zone: %s, %s, hash %x;"
+				"outdated TTL %d\n",
+				log_zname, (ans.nsec_p.raw ? "NSEC3" : "NSEC"),
+				(unsigned)ans.nsec_p.hash, (int)remains);
+			/* no need for nsec_p_cleanup() in this case */
+			goto cont;
+		}
+		VERBOSE_MSG(qry, "=> trying zone: %s, %s, hash %x\n",
+				log_zname, (ans.nsec_p.raw ? "NSEC3" : "NSEC"),
+				(unsigned)ans.nsec_p.hash);
 		/**** 2. and 3. inside */
 		ret = peek_encloser(k, &ans, sname_labels,
 					lowest_rank, qry, cache);