Commit a444fdb4 authored by Vladimír Čunát's avatar Vladimír Čunát

cache: fix logging after parent merge

parent 41d3c634
......@@ -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 @@ static int cache_peek_real(kr_layer_t *ctx, knot_pkt_t *pkt)
/* 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;
}
......
......@@ -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);
}
......
......@@ -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);
}
}
......
......@@ -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"
......
......@@ -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;
......
......@@ -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;
}
......
......@@ -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();
}
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment