cache: fix logging after parent merge

diff --git a/lib/cache.c b/lib/cache.c
index bc8ef4dc1db043909fad8e400298ae5d4ae89f38..9b38d0a6069a9c129cdf78535950ad9482e8e9f8 100644 (file)
--- 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 d4b1d7f3909ed267c623d364eb302cdeb7aa2f9d..4536a921bd49551ac9fa37b67819ff0b45b51b69 100644 (file)
--- 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 2491abd0780acf598fb14879b650c380b631efcd..e355b2406118c527d6516f79f529b9e0e009c065 100644 (file)
--- 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 c4215716dc35dc511470890c5463f4b13d3ad7ba..a3abfb2c8b089ef830e51f0cfe81251ea25a08a5 100644 (file)
--- 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 10a2193a4c872e56ba3ecbf50b49594bd001ffb4..ce1c39f0dea9cb83928857c937f4017ea811c892 100644 (file)
--- 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 b8e64696865cb230388a5e9f41bac662b88dd32f..6579b00e2254fa2be2415b96b92e17f554f0d070 100644 (file)
--- 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 ce326da825d70511cf5bc3db1f5a6d8efef462eb..9e46a2e65973fae4b2d6c0bf5077331e7277dc43 100644 (file)
--- 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();
                }