From 0e73960bb302f2b1c467c22375584fb85344483b Mon Sep 17 00:00:00 2001 From: =?utf8?q?Vladim=C3=ADr=20=C4=8Cun=C3=A1t?= Date: Tue, 13 Jul 2021 13:05:40 +0200 Subject: [PATCH] treewide: replace VERBOSE_STATUS, WITH_VERBOSE, etc. The main problem there was ignoring the log groups, and VERBOSE_STATUS also ignores trace-logging. Typically the new kr_log_is_debug*() are the best choice. In a couple places with heavy WITH_VERBOSE usage it's instead locally redefined to consider the right group. --- daemon/io.c | 6 +++--- daemon/tls.c | 2 +- daemon/worker.c | 20 ++++++++++-------- lib/cache/api.c | 10 ++++----- lib/cache/impl.h | 1 + lib/cache/nsec1.c | 6 ++---- lib/cache/peek.c | 2 +- lib/dnssec.c | 2 +- lib/layer/iterate.c | 6 +++--- lib/layer/validate.c | 2 +- lib/log.h | 6 +----- lib/resolve.c | 35 +++++++++++++++----------------- lib/rplan.c | 14 ++++++------- lib/selection.c | 48 +++++++++++++++++++++----------------------- lib/selection_iter.c | 2 +- lib/zonecut.c | 8 ++++---- utils/cache_gc/db.h | 4 ++++ 17 files changed, 85 insertions(+), 89 deletions(-) diff --git a/daemon/io.c b/daemon/io.c index b105519b2..c1661bfd0 100644 --- a/daemon/io.c +++ b/daemon/io.c @@ -281,7 +281,7 @@ static void tcp_recv(uv_stream_t *handle, ssize_t nread, const uv_buf_t *buf) } if (nread < 0 || !buf->base) { - if (KR_LOG_LEVEL_IS(LOG_DEBUG)) { + if (kr_log_is_debug(IO, NULL)) { struct sockaddr *peer = session_get_peer(s); char *peer_str = kr_straddr(peer); kr_log_debug(IO, "=> connection to '%s' closed by peer (%s)\n", @@ -300,7 +300,7 @@ static void tcp_recv(uv_stream_t *handle, ssize_t nread, const uv_buf_t *buf) Decode data free space in session wire buffer. */ consumed = tls_process_input_data(s, (const uint8_t *)buf->base, nread); if (consumed < 0) { - if (KR_LOG_LEVEL_IS(LOG_DEBUG)) { + if (kr_log_is_debug(IO, NULL)) { struct sockaddr *peer = session_get_peer(s); char *peer_str = kr_straddr(peer); kr_log_debug(IO, "=> connection to '%s': " @@ -319,7 +319,7 @@ static void tcp_recv(uv_stream_t *handle, ssize_t nread, const uv_buf_t *buf) if (session_flags(s)->has_http) { consumed = http_process_input_data(s, data, data_len); if (consumed < 0) { - if (KR_LOG_LEVEL_IS(LOG_DEBUG)) { + if (kr_log_is_debug(IO, NULL)) { struct sockaddr *peer = session_get_peer(s); char *peer_str = kr_straddr(peer); kr_log_debug(IO, "=> connection to '%s': " diff --git a/daemon/tls.c b/daemon/tls.c index 98168218a..935870dfd 100644 --- a/daemon/tls.c +++ b/daemon/tls.c @@ -926,7 +926,7 @@ static int client_verify_pin(const unsigned int cert_list_size, } #ifdef DEBUG - if (VERBOSE_STATUS) { + if (kr_log_is_debug(TLS, NULL)) { char pin_base64[TLS_SHA256_BASE64_BUFLEN]; /* DEBUG: additionally compute and print the base64 pin. * Not very efficient, but that's OK for DEBUG. */ diff --git a/daemon/worker.c b/daemon/worker.c index a96e3a668..1c9e9ea39 100644 --- a/daemon/worker.c +++ b/daemon/worker.c @@ -634,7 +634,8 @@ int qr_task_on_send(struct qr_task *task, const uv_handle_t *handle, int status) if (handle->type == UV_TCP) { if (status != 0) { // session probably not usable anymore; typically: ECONNRESET - if (VERBOSE_STATUS) { + const struct kr_request *req = &task->ctx->req; + if (kr_log_is_debug(WORKER, req)) { const char *peer_str = NULL; if (!session_flags(s)->outgoing) { peer_str = "hidden"; // avoid logging downstream IPs @@ -643,7 +644,8 @@ int qr_task_on_send(struct qr_task *task, const uv_handle_t *handle, int status) } if (!peer_str) peer_str = "unknown"; // probably shouldn't happen - kr_log_debug(WORKER, "=> disconnected from '%s': %s\n", + kr_log_req(req, 0, 0, WORKER, + "=> disconnected from '%s': %s\n", peer_str, uv_strerror(status)); } worker_end_tcp(s); @@ -976,6 +978,8 @@ static void on_connect(uv_connect_t *req, int status) return; } + const bool log_debug = kr_log_is_debug(WORKER, NULL); + /* Check if the connection is in the waiting list. * If no, most likely this is timeouted connection * which was removed from waiting list by @@ -984,7 +988,7 @@ static void on_connect(uv_connect_t *req, int status) if (!s || s != session) { /* session isn't on the waiting list. * it's timeouted session. */ - if (VERBOSE_STATUS) { + if (log_debug) { const char *peer_str = kr_straddr(peer); kr_log_debug(WORKER, "=> connected to '%s', but session " "is already timeouted, close\n", @@ -1001,7 +1005,7 @@ static void on_connect(uv_connect_t *req, int status) /* session already in the connected list. * Something went wrong, it can be due to races when kresd has tried * to reconnect to upstream after unsuccessful attempt. */ - if (VERBOSE_STATUS) { + if (log_debug) { const char *peer_str = kr_straddr(peer); kr_log_debug(WORKER, "=> connected to '%s', but peer " "is already connected, close\n", @@ -1014,7 +1018,7 @@ static void on_connect(uv_connect_t *req, int status) } if (status != 0) { - if (VERBOSE_STATUS) { + if (log_debug) { const char *peer_str = kr_straddr(peer); kr_log_debug(WORKER, "=> connection to '%s' failed (%s), flagged as 'bad'\n", peer_str ? peer_str : "", uv_strerror(status)); @@ -1047,7 +1051,7 @@ static void on_connect(uv_connect_t *req, int status) } } - if (VERBOSE_STATUS) { + if (log_debug) { const char *peer_str = kr_straddr(peer); kr_log_debug(WORKER, "=> connected to '%s'\n", peer_str ? peer_str : ""); } @@ -1102,7 +1106,7 @@ static void on_tcp_connect_timeout(uv_timer_t *timer) } struct kr_query *qry = task_get_last_pending_query(task); - WITH_VERBOSE (qry) { + if (kr_log_is_debug_qry(WORKER, qry)) { const char *peer_str = kr_straddr(peer); VERBOSE_MSG(qry, "=> connection to '%s' failed (internal timeout)\n", peer_str ? peer_str : ""); @@ -1522,7 +1526,7 @@ static int tcp_task_make_connection(struct qr_task *task, const struct sockaddr } struct kr_query *qry = task_get_last_pending_query(task); - WITH_VERBOSE (qry) { + if (kr_log_is_debug_qry(WORKER, qry)) { const char *peer_str = kr_straddr(peer); VERBOSE_MSG(qry, "=> connecting to: '%s'\n", peer_str ? peer_str : ""); } diff --git a/lib/cache/api.c b/lib/cache/api.c index 1c64094e6..61e5a864f 100644 --- a/lib/cache/api.c +++ b/lib/cache/api.c @@ -275,10 +275,10 @@ int32_t kr_cache_ttl(const struct kr_cache_p *peek, const struct kr_query *qry, static bool check_dname_for_lf(const knot_dname_t *n, const struct kr_query *qry/*logging*/) { const bool ret = knot_dname_size(n) == strlen((const char *)n) + 1; - if (!ret) { WITH_VERBOSE(qry) { + if (!ret && kr_log_is_debug_qry(CACHE, qry)) { auto_free char *n_str = kr_dname_text(n); VERBOSE_MSG(qry, "=> skipping zero-containing name %s\n", n_str); - } } + } return ret; } @@ -287,10 +287,10 @@ static bool check_rrtype(uint16_t type, const struct kr_query *qry/*logging*/) { const bool ret = !knot_rrtype_is_metatype(type) && type != KNOT_RRTYPE_RRSIG; - if (!ret) { WITH_VERBOSE(qry) { + if (!ret && kr_log_is_debug_qry(CACHE, qry)) { auto_free char *type_str = kr_rrtype_text(type); VERBOSE_MSG(qry, "=> skipping RR type %s\n", type_str); - } } + } return ret; } @@ -841,7 +841,7 @@ int kr_cache_peek_exact(struct kr_cache *cache, const knot_dname_t *name, uint16 struct kr_cache_p *peek) { /* Just wrap with extra verbose logging. */ const int ret = peek_exact_real(cache, name, type, peek); - if (false && VERBOSE_STATUS) { /* too noisy for usual --verbose */ + if (false && kr_log_is_debug(CACHE, NULL)) { /* too noisy for usual --verbose */ auto_free char *type_str = kr_rrtype_text(type), *name_str = kr_dname_text(name); const char *result_str = (ret == kr_ok() ? "hit" : diff --git a/lib/cache/impl.h b/lib/cache/impl.h index e837d16ea..b12e16b12 100644 --- a/lib/cache/impl.h +++ b/lib/cache/impl.h @@ -410,6 +410,7 @@ int nsec3_src_synth(struct key *k, struct answer *ans, const knot_dname_t *clenc #define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), CACHE, ## __VA_ARGS__) +#define WITH_VERBOSE(qry) if (kr_log_is_debug_qry(CACHE, (qry))) /** Shorthand for operations on cache backend */ #define cache_op(cache, op, ...) (cache)->api->op((cache)->db, &(cache)->stats, ## __VA_ARGS__) diff --git a/lib/cache/nsec1.c b/lib/cache/nsec1.c index ccf282c55..3fcd05e83 100644 --- a/lib/cache/nsec1.c +++ b/lib/cache/nsec1.c @@ -423,8 +423,6 @@ int nsec1_src_synth(struct key *k, struct answer *ans, const knot_dname_t *clenc if (kr_fails_assert(nsec_rr)) return kr_error(EFAULT); - const uint32_t new_ttl_log = - KR_LOG_LEVEL_IS(LOG_DEBUG) ? nsec_rr->ttl : -1; const uint8_t *bm = knot_nsec_bitmap(nsec_rr->rrs.rdata); uint16_t bm_size = knot_nsec_bitmap_len(nsec_rr->rrs.rdata); int ret; @@ -451,7 +449,7 @@ int nsec1_src_synth(struct key *k, struct answer *ans, const knot_dname_t *clenc auto_free char *owner_str = kr_dname_text(nsec_rr->owner), *next_str = kr_dname_text(knot_nsec_next(nsec_rr->rrs.rdata)); VERBOSE_MSG(qry, "=> NSEC wildcard: covered by: %s -> %s, new TTL %d\n", - owner_str, next_str, new_ttl_log); + owner_str, next_str, nsec_rr->ttl); } return AR_SOA; } @@ -464,7 +462,7 @@ int nsec1_src_synth(struct key *k, struct answer *ans, const knot_dname_t *clenc if (arw->set.rr) { 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); + msg_start, owner_str, nsec_rr->ttl); } else { /* don't repeat the RR if it's the same */ VERBOSE_MSG(qry, "%s, by the same RR\n", msg_start); diff --git a/lib/cache/peek.c b/lib/cache/peek.c index 5ea1c4d62..771d32b25 100644 --- a/lib/cache/peek.c +++ b/lib/cache/peek.c @@ -210,7 +210,7 @@ int peek_nosync(kr_layer_t *ctx, knot_pkt_t *pkt) for (int i = 0; ;) { int32_t log_new_ttl = -123456789; /* visually recognizable value */ ret = nsec_p_ttl(el[i], qry->timestamp.tv_sec, &log_new_ttl); - if (!ret || VERBOSE_STATUS) { + if (!ret || kr_log_is_debug_qry(CACHE, qry)) { nsec_p_init(&ans.nsec_p, el[i], !ret); } if (ret) { diff --git a/lib/dnssec.c b/lib/dnssec.c index 65e932085..302cbfa0d 100644 --- a/lib/dnssec.c +++ b/lib/dnssec.c @@ -251,7 +251,7 @@ static int kr_rrset_validate_with_key(kr_rrset_validation_ctx_t *vctx, const uint32_t ttl_max = MIN(knot_rrsig_original_ttl(rdata_j), knot_rrsig_sig_expiration(rdata_j) - timestamp); if (unlikely(covered->ttl > ttl_max)) { - if (VERBOSE_STATUS) { + if (kr_log_is_debug_qry(VALIDATOR, vctx->log_qry)) { auto_free char *name_str = kr_dname_text(covered->owner), *type_str = kr_rrtype_text(covered->type); diff --git a/lib/layer/iterate.c b/lib/layer/iterate.c index 2aa6578d1..f20ed6348 100644 --- a/lib/layer/iterate.c +++ b/lib/layer/iterate.c @@ -34,6 +34,7 @@ #define VERBOSE_MSG(...) QRVERBOSE(req->current_query, ITERATOR, __VA_ARGS__) #define QVERBOSE_MSG(qry, ...) QRVERBOSE(qry, ITERATOR, __VA_ARGS__) +#define WITH_VERBOSE(qry) if (kr_log_is_debug_qry(ITERATOR, (qry))) /* Iterator often walks through packet section, this is an abstraction. */ typedef int (*rr_callback_t)(const knot_rrset_t *, unsigned, struct kr_request *); @@ -1064,9 +1065,8 @@ static int resolve(kr_layer_t *ctx, knot_pkt_t *pkt) * The most important part is to check for spoofing: is_paired_to_query() */ query->flags.PKT_IS_SANE = true; - const knot_lookup_t *rcode = NULL; - if (KR_LOG_LEVEL_IS(LOG_DEBUG)) - rcode = knot_lookup_by_id(knot_rcode_names, knot_wire_get_rcode(pkt->wire)); + const knot_lookup_t *rcode = // just for logging but cheaper than a condition + knot_lookup_by_id(knot_rcode_names, knot_wire_get_rcode(pkt->wire)); // We can't return directly from the switch because we have to give feedback to server selection first int ret = 0; diff --git a/lib/layer/validate.c b/lib/layer/validate.c index 5e3050eb1..fb906efdb 100644 --- a/lib/layer/validate.c +++ b/lib/layer/validate.c @@ -68,7 +68,7 @@ static bool pkt_has_type(const knot_pkt_t *pkt, uint16_t type) static void log_bogus_rrsig(kr_rrset_validation_ctx_t *vctx, const knot_rrset_t *rr, const char *msg) { - WITH_VERBOSE(vctx->log_qry) { + if (kr_log_is_debug_qry(VALIDATOR, vctx->log_qry)) { auto_free char *name_text = kr_dname_text(rr->owner); auto_free char *type_text = kr_rrtype_text(rr->type); VERBOSE_MSG(vctx->log_qry, ">< %s: %s %s " diff --git a/lib/log.h b/lib/log.h index 3970e1a14..72e0f5918 100644 --- a/lib/log.h +++ b/lib/log.h @@ -227,10 +227,6 @@ void kr_log_req1(const struct kr_request * const req, uint32_t qry_uid, KR_EXPORT KR_PRINTF(4) void kr_log_q1(const struct kr_query *qry, enum kr_log_group group, const char *tag, const char *fmt, ...); -/** Block run in --verbose mode; optimized when not run. */ -#define VERBOSE_STATUS __builtin_expect(KR_LOG_LEVEL_IS(LOG_DEBUG), false) // TODO vyhodit -#define WITH_VERBOSE(query) if(__builtin_expect(KR_LOG_LEVEL_IS(LOG_DEBUG) || kr_log_qtrace_enabled(query), false)) - /** Return whether a particular log group in a request is in debug/verbose mode. * * Typically you use this as condition to compute some data to be logged, @@ -240,7 +236,7 @@ void kr_log_q1(const struct kr_query *qry, enum kr_log_group group, const char * */ #define kr_log_is_debug(grp, req) \ __builtin_expect(kr_log_is_debug_fun(LOG_GRP_ ## grp, (req)), false) -#define kr_log_is_debug_qry(grp, qry) kr_log_is_debug(grp, (qry)->request) +#define kr_log_is_debug_qry(grp, qry) kr_log_is_debug(grp, (qry) ? (qry)->request : NULL) KR_EXPORT bool kr_log_is_debug_fun(enum kr_log_group group, const struct kr_request *req); diff --git a/lib/resolve.c b/lib/resolve.c index 8ef862cd0..cf2ba0329 100644 --- a/lib/resolve.c +++ b/lib/resolve.c @@ -457,7 +457,7 @@ static int answer_padding(struct kr_request *request) static void answer_fail(struct kr_request *request) { /* Note: OPT in SERVFAIL response is still useful for cookies/additional info. */ - if (VERBOSE_STATUS || kr_log_rtrace_enabled(request)) + if (kr_log_is_debug(RESOLVER, request)) kr_log_req(request, 0, 0, RESOLVER, "request failed, answering with empty SERVFAIL\n"); knot_pkt_t *answer = request->answer; @@ -769,9 +769,7 @@ static bool resolution_time_exceeded(struct kr_query *qry, uint64_t now) { uint64_t resolving_time = now - qry->creation_time_mono; if (resolving_time > KR_RESOLVE_TIME_LIMIT) { - WITH_VERBOSE(qry) { - VERBOSE_MSG(qry, "query resolution time limit exceeded\n"); - } + VERBOSE_MSG(qry, "query resolution time limit exceeded\n"); return true; } return false; @@ -833,7 +831,7 @@ int kr_resolve_consume(struct kr_request *request, struct kr_transport **transpo if (!qry->flags.CACHED) { if (request->state & KR_STATE_FAIL) { if (++request->count_fail_row > KR_CONSUME_FAIL_ROW_LIMIT) { - if (VERBOSE_STATUS || kr_log_rtrace_enabled(request)) { + if (kr_log_is_debug(RESOLVER, request)) { kr_log_req(request, 0, 2, RESOLVER, "=> too many failures in a row, " "bail out (mitigation for NXNSAttack " @@ -1040,9 +1038,9 @@ static int forward_trust_chain_check(struct kr_request *request, struct kr_query kr_ta_get(trust_anchors, wanted_name)) { qry->flags.DNSSEC_WANT = true; want_secured = true; - WITH_VERBOSE(qry) { - KR_DNAME_GET_STR(qname_str, wanted_name); - VERBOSE_MSG(qry, ">< TA: '%s'\n", qname_str); + if (kr_log_is_debug_qry(RESOLVER, qry)) { + KR_DNAME_GET_STR(qname_str, wanted_name); + VERBOSE_MSG(qry, ">< TA: '%s'\n", qname_str); } } @@ -1116,9 +1114,9 @@ static int trust_chain_check(struct kr_request *request, struct kr_query *qry) mm_free(qry->zone_cut.pool, qry->zone_cut.trust_anchor); qry->zone_cut.trust_anchor = knot_rrset_copy(ta_rr, qry->zone_cut.pool); - WITH_VERBOSE(qry) { - KR_DNAME_GET_STR(qname_str, ta_rr->owner); - VERBOSE_MSG(qry, ">< TA: '%s'\n", qname_str); + if (kr_log_is_debug_qry(RESOLVER, qry)) { + KR_DNAME_GET_STR(qname_str, ta_rr->owner); + VERBOSE_MSG(qry, ">< TA: '%s'\n", qname_str); } } } @@ -1527,15 +1525,14 @@ int kr_resolve_checkout(struct kr_request *request, const struct sockaddr *src, } } - WITH_VERBOSE(qry) { - - KR_DNAME_GET_STR(qname_str, knot_pkt_qname(packet)); - KR_DNAME_GET_STR(ns_name, transport->ns_name); - KR_DNAME_GET_STR(zonecut_str, qry->zone_cut.name); - KR_RRTYPE_GET_STR(type_str, knot_pkt_qtype(packet)); - const char *ns_str = kr_straddr(&transport->address.ip); + if (kr_log_is_debug_qry(RESOLVER, qry)) { + KR_DNAME_GET_STR(qname_str, knot_pkt_qname(packet)); + KR_DNAME_GET_STR(ns_name, transport->ns_name); + KR_DNAME_GET_STR(zonecut_str, qry->zone_cut.name); + KR_RRTYPE_GET_STR(type_str, knot_pkt_qtype(packet)); + const char *ns_str = kr_straddr(&transport->address.ip); - VERBOSE_MSG(qry, + VERBOSE_MSG(qry, "=> id: '%05u' querying: '%s'@'%s' zone cut: '%s' " "qname: '%s' qtype: '%s' proto: '%s'\n", qry->id, ns_name, ns_str ? ns_str : "", zonecut_str, diff --git a/lib/rplan.c b/lib/rplan.c index ad048d862..5f5904bad 100644 --- a/lib/rplan.c +++ b/lib/rplan.c @@ -188,10 +188,8 @@ struct kr_query *kr_rplan_push_empty(struct kr_rplan *rplan, struct kr_query *pa return NULL; } - WITH_VERBOSE(qry) { VERBOSE_MSG(qry, "plan '%s' type '%s' uid [%05u.%02u]\n", "", "", qry->request ? qry->request->uid : 0, qry->uid); - } return qry; } @@ -210,12 +208,12 @@ struct kr_query *kr_rplan_push(struct kr_rplan *rplan, struct kr_query *parent, qry->sclass = cls; qry->stype = type; - WITH_VERBOSE(qry) { - KR_DNAME_GET_STR(name_str, name); - KR_RRTYPE_GET_STR(type_str, type); - VERBOSE_MSG(parent, "plan '%s' type '%s' uid [%05u.%02u]\n", - name_str, type_str, - qry->request ? qry->request->uid : 0, qry->uid); + if (kr_log_is_debug_qry(PLAN, qry)) { + KR_DNAME_GET_STR(name_str, name); + KR_RRTYPE_GET_STR(type_str, type); + VERBOSE_MSG(parent, "plan '%s' type '%s' uid [%05u.%02u]\n", + name_str, type_str, + qry->request ? qry->request->uid : 0, qry->uid); } return qry; } diff --git a/lib/selection.c b/lib/selection.c index dc72c474d..ea6d6b073 100644 --- a/lib/selection.c +++ b/lib/selection.c @@ -327,8 +327,7 @@ void update_address_state(struct address_state *state, union inaddr *address, state, qry->request->ctx->cache_rtt_tout_retry_interval); #ifdef SELECTION_CHOICE_LOGGING // This is sometimes useful for debugging, but usually too verbose - WITH_VERBOSE(qry) - { + if (kr_log_is_debug_qry(SELECTION, qry)) { const char *ns_str = kr_straddr(&address->ip); VERBOSE_MSG(qry, "rtt of %s is %d, variance is %d\n", ns_str, state->rtt_state.srtt, state->rtt_state.variance); @@ -538,18 +537,17 @@ void update_rtt(struct kr_query *qry, struct address_state *addr_state, if (transport->address_len == sizeof(struct in6_addr)) no6_success(qry); - WITH_VERBOSE(qry) - { - KR_DNAME_GET_STR(ns_name, transport->ns_name); - KR_DNAME_GET_STR(zonecut_str, qry->zone_cut.name); - const char *ns_str = kr_straddr(&transport->address.ip); + if (kr_log_is_debug_qry(SELECTION, qry)) { + KR_DNAME_GET_STR(ns_name, transport->ns_name); + KR_DNAME_GET_STR(zonecut_str, qry->zone_cut.name); + const char *ns_str = kr_straddr(&transport->address.ip); - VERBOSE_MSG( - qry, - "=> id: '%05u' updating: '%s'@'%s' zone cut: '%s'" - " with rtt %u to srtt: %d and variance: %d \n", - qry->id, ns_name, ns_str ? ns_str : "", zonecut_str, - rtt, new_rtt_state.srtt, new_rtt_state.variance); + VERBOSE_MSG( + qry, + "=> id: '%05u' updating: '%s'@'%s' zone cut: '%s'" + " with rtt %u to srtt: %d and variance: %d \n", + qry->id, ns_name, ns_str ? ns_str : "", zonecut_str, + rtt, new_rtt_state.srtt, new_rtt_state.variance); } } @@ -678,18 +676,18 @@ void error(struct kr_query *qry, struct address_state *addr_state, addr_state->error_count++; addr_state->errors[sel_error]++; - WITH_VERBOSE(qry) - { - KR_DNAME_GET_STR(ns_name, transport->ns_name); - KR_DNAME_GET_STR(zonecut_str, qry->zone_cut.name); - const char *ns_str = kr_straddr(&transport->address.ip); - const char *err_str = kr_selection_error_str(sel_error); - - VERBOSE_MSG( - qry, - "=> id: '%05u' noting selection error: '%s'@'%s' zone cut: '%s' error: %d %s\n", - qry->id, ns_name, ns_str ? ns_str : "", zonecut_str, - sel_error, err_str ? err_str : "??"); + if (kr_log_is_debug_qry(SELECTION, qry)) { + KR_DNAME_GET_STR(ns_name, transport->ns_name); + KR_DNAME_GET_STR(zonecut_str, qry->zone_cut.name); + const char *ns_str = kr_straddr(&transport->address.ip); + const char *err_str = kr_selection_error_str(sel_error); + + VERBOSE_MSG( + qry, + "=> id: '%05u' noting selection error: '%s'@'%s'" + " zone cut: '%s' error: %d %s\n", + qry->id, ns_name, ns_str ? ns_str : "", + zonecut_str, sel_error, err_str ? err_str : "??"); } } diff --git a/lib/selection_iter.c b/lib/selection_iter.c index 50b170724..1d284d8fb 100644 --- a/lib/selection_iter.c +++ b/lib/selection_iter.c @@ -303,7 +303,7 @@ void iter_choose_transport(struct kr_query *qry, struct kr_transport **transport qry->flags.DNSSEC_BOGUS = true; } - WITH_VERBOSE(qry) + if (kr_log_is_debug_qry(SELECTION, qry)) { KR_DNAME_GET_STR(zonecut_str, qry->zone_cut.name); if (*transport) { diff --git a/lib/zonecut.c b/lib/zonecut.c index 5ab4a461e..9f0a86604 100644 --- a/lib/zonecut.c +++ b/lib/zonecut.c @@ -406,7 +406,7 @@ static int fetch_ns(struct kr_context *ctx, struct kr_zonecut *cut, infos[1] = fetch_addr(*pack, ns_name, KNOT_RRTYPE_AAAA, cut->pool, qry); #if 0 /* rather unlikely to be useful unless changing some zcut code */ - WITH_VERBOSE(qry) { + if (kr_log_is_debug_qry(ZCUT, qry)) { auto_free char *ns_name_txt = kr_dname_text(ns_name); VERBOSE_MSG(qry, "NS %s infos: %d, %d\n", ns_name_txt, (int)infos[0], (int)infos[1]); @@ -444,11 +444,11 @@ static int fetch_ns(struct kr_context *ctx, struct kr_zonecut *cut, all_bad = all_bad && infos[0] <= AI_LAST_BAD && infos[1] <= AI_LAST_BAD; } - if (all_bad) { WITH_VERBOSE(qry) { + if (all_bad && kr_log_is_debug_qry(ZCUT, qry)) { auto_free char *name_txt = kr_dname_text(name); VERBOSE_MSG(qry, "cut %s: all NSs bad, count = %d\n", name_txt, (int)ns_rds.count); - } } + } knot_rdataset_clear(&ns_rds, cut->pool); return all_bad ? ELOOP : kr_ok(); } @@ -532,7 +532,7 @@ int kr_zonecut_find_cached(struct kr_context *ctx, struct kr_zonecut *cut, label, KNOT_RRTYPE_DNSKEY, cut->pool, qry); } update_cut_name(cut, label); - WITH_VERBOSE(qry) { + if (kr_log_is_debug_qry(ZCUT, qry)) { auto_free char *label_str = kr_dname_text(label); VERBOSE_MSG(qry, "found cut: %s (rank 0%.2o return codes: DS %d, DNSKEY %d)\n", diff --git a/utils/cache_gc/db.h b/utils/cache_gc/db.h index 48dc101a8..7865471b5 100644 --- a/utils/cache_gc/db.h +++ b/utils/cache_gc/db.h @@ -31,3 +31,7 @@ int kr_gc_key_consistent(knot_db_val_t key); /** Printf a *binary* string in a human-readable way. */ void debug_printbin(const char *str, unsigned int len); +/** Block run in --verbose mode; optimized when not run. */ +#define VERBOSE_STATUS __builtin_expect(KR_LOG_LEVEL_IS(LOG_DEBUG), false) +/* TODO: replace when solving GC logging properly */ + -- 2.47.2