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.

diff --git a/daemon/io.c b/daemon/io.c
index b105519b25a747cc47cab4d040bda6acdf4cf596..c1661bfd0aee0b50900c208c1b05ab30856a37cb 100644 (file)
--- 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 98168218a1d425f5892608ed5250053bd53a6d38..935870dfd02e31f79161ba62befceeba642793b0 100644 (file)
--- 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 a96e3a668bd6e479ac3e9284a65ce352f4c8708a..1c9e9ea39cf466c5a5b9df7dbedbdc02ea632c02 100644 (file)
--- 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 1c64094e63688eeca04d8fc899076d1bbabbfb34..61e5a864fcb1c22e88d6b54634db8dc4f4c6f132 100644 (file)
--- 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 e837d16ea90a5967446ecc24b9555c5ce305782d..b12e16b124fff597897a3b10a2056554394b58ed 100644 (file)
--- 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 ccf282c55844c000e7de601d166befd4ff0c77b7..3fcd05e830cd9b1741d4962cf03f8af1de4dc27c 100644 (file)
--- 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 5ea1c4d624ea1cb07a8971657a20902c61719a80..771d32b25fcde4ea5dad8c1db3dd0ea796f34046 100644 (file)
--- 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 65e932085b91a2665fe001078e4afbb2af4e6f9d..302cbfa0dcf166cabd16f1bef2b6ace0de548092 100644 (file)
--- 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 2aa6578d1e0fde7f38519347e3eb357615144db7..f20ed63484066f38ff4d2dcb5b41d5d5b0889e03 100644 (file)
--- 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 5e3050eb15520d2fec150eb0131b3c1e906ab4da..fb906efdbb4872f6b36fe54410a5e3bda057e051 100644 (file)
--- 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 3970e1a146dc4644d6572384446bfe3fe7c060c9..72e0f5918362f9a484128c6ae6f5d0c91a7b5917 100644 (file)
--- 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 8ef862cd05459b4e714407fd5e3765012ca49d3c..cf2ba03292ac492ac2d4681f70e66abd892f0b98 100644 (file)
--- 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 ad048d862376cb9ed97f0a357f986d1fcbd7e8f9..5f5904bad2183b1942bbe195b375fc277eec1bd6 100644 (file)
--- 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 dc72c474d4b7c8f6a9c54e53d762b105ad9cd208..ea6d6b07393dbac02a32405013860ef7c3c09a03 100644 (file)
--- 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 50b1707247e780a8266313aae2af993e33cf3767..1d284d8fbe5fecef75b8c2f1aba1737b721333dd 100644 (file)
--- 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 5ab4a461e2cf0b35f2be97c50c33c12d5759f2e1..9f0a86604a4a69b127546999d9ec50eb34320374 100644 (file)
--- 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 48dc101a84bd37169c163d44cf756151f1d696f5..7865471b552e482bafbe702f28a24ab214fc6133 100644 (file)
--- 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 */
+