cache: better logging of NSEC3 parameters

diff --git a/lib/cache/api.c b/lib/cache/api.c
index 5d3974276343cc47441a667bb8bd9b6fe798624d..c7f6326217ccc70f0af34ea4e648d3b60a2803ed 100644 (file)
--- 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 55a037a82f4d256eb59bd2c8eeba2ca57ba57aac..9c588a7d61464938610267599f0d506cca09b5cd 100644 (file)
--- 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);