From: Lukáš Ježek Date: Tue, 15 Jun 2021 10:35:53 +0000 (+0200) Subject: log: add level prefix to each message X-Git-Tag: v5.4.0~2^2~52 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=6b737321adeb1b3b588c51095cf261e2c5258488;p=thirdparty%2Fknot-resolver.git log: add level prefix to each message --- diff --git a/daemon/lua/kres-gen-29.lua b/daemon/lua/kres-gen-29.lua index e885c815d..3ca1184b8 100644 --- a/daemon/lua/kres-gen-29.lua +++ b/daemon/lua/kres-gen-29.lua @@ -306,6 +306,7 @@ struct kr_server_selection { void (*error)(struct kr_query *, const struct kr_transport *, enum kr_selection_error); struct local_state *local_state; }; +typedef unsigned int log_groups_t; kr_layer_t kr_layer_t_static; _Bool kr_dbg_assertion_abort; @@ -383,8 +384,8 @@ int kr_rplan_pop(struct kr_rplan *, struct kr_query *); struct kr_query *kr_rplan_resolved(struct kr_rplan *); struct kr_query *kr_rplan_last(struct kr_rplan *); int kr_forward_add_target(struct kr_request *, const struct sockaddr *); -void kr_log_req(const struct kr_request * const, uint32_t, const unsigned int, const char *, const char *, ...); -void kr_log_q(const struct kr_query * const, const char *, const char *, ...); +void kr_log_req1(const struct kr_request * const, uint32_t, const unsigned int, log_groups_t, const char *, const char *, ...); +void kr_log_q1(const struct kr_query * const, log_groups_t, const char *, const char *, ...); int kr_make_query(struct kr_query *, knot_pkt_t *); void kr_pkt_make_auth_header(knot_pkt_t *); int kr_pkt_put(knot_pkt_t *, const knot_dname_t *, uint32_t, uint16_t, uint16_t, const uint8_t *, uint16_t); diff --git a/daemon/lua/kres-gen.sh b/daemon/lua/kres-gen.sh index 5018973a1..afaa19b9c 100755 --- a/daemon/lua/kres-gen.sh +++ b/daemon/lua/kres-gen.sh @@ -138,6 +138,7 @@ ${CDEFS} ${LIBKRES} types <<-EOF struct kr_prop struct kr_module struct kr_server_selection + log_groups_t EOF # static variables; these lines might not be simple to generate @@ -210,8 +211,8 @@ ${CDEFS} ${LIBKRES} functions <<-EOF # Forwarding kr_forward_add_target # Utils - kr_log_req - kr_log_q + kr_log_req1 + kr_log_q1 kr_make_query kr_pkt_make_auth_header kr_pkt_put diff --git a/daemon/worker.c b/daemon/worker.c index b44663d8d..06b48452c 100644 --- a/daemon/worker.c +++ b/daemon/worker.c @@ -51,7 +51,7 @@ #define MAX_PIPELINED 100 #endif -#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, "wrkr", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_WORKER, __VA_ARGS__) /** Client request state. */ struct request_ctx diff --git a/daemon/zimport.c b/daemon/zimport.c index 51181c057..de05e88d9 100644 --- a/daemon/zimport.c +++ b/daemon/zimport.c @@ -47,7 +47,7 @@ #include "lib/generic/map.h" #include "lib/generic/array.h" -#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, "zimport", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_ZIMPORT, __VA_ARGS__) /* Pause between parse and import stages, milliseconds. * See comment in zi_zone_import() */ diff --git a/lib/cache/impl.h b/lib/cache/impl.h index cddd0b748..54815fe2d 100644 --- a/lib/cache/impl.h +++ b/lib/cache/impl.h @@ -409,7 +409,7 @@ int nsec3_src_synth(struct key *k, struct answer *ans, const knot_dname_t *clenc -#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), "cach", ## __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), LOG_GRP_CACHE, ## __VA_ARGS__) /** Shorthand for operations on cache backend */ #define cache_op(cache, op, ...) (cache)->api->op((cache)->db, &(cache)->stats, ## __VA_ARGS__) diff --git a/lib/dnssec.c b/lib/dnssec.c index 4acc9717c..138e2f16c 100644 --- a/lib/dnssec.c +++ b/lib/dnssec.c @@ -255,7 +255,7 @@ static int kr_rrset_validate_with_key(kr_rrset_validation_ctx_t *vctx, auto_free char *name_str = kr_dname_text(covered->owner), *type_str = kr_rrtype_text(covered->type); - QRVERBOSE(NULL, "vldr", + QRVERBOSE(NULL, LOG_GRP_VALIDATOR, "trimming TTL of %s %s: %d -> %d\n", name_str, type_str, (int)covered->ttl, (int)ttl_max); diff --git a/lib/layer.h b/lib/layer.h index 40e62c7d4..3ac844e01 100644 --- a/lib/layer.h +++ b/lib/layer.h @@ -13,10 +13,10 @@ * \param _cls identifying string, typically of length exactly four (padded) * \param ... printf-compatible list of parameters */ -#define QRVERBOSE(_query, _cls, ...) do { \ +#define QRVERBOSE(_query, grp, ...) do { \ const struct kr_query *_qry = (_query); \ if (VERBOSE_STATUS || kr_log_qtrace_enabled(_qry)) { \ - kr_log_q(_qry, (_cls), __VA_ARGS__); \ + kr_log_q1(_query, grp, grp ## _TAG, __VA_ARGS__); \ } \ } while (false) diff --git a/lib/layer/iterate.c b/lib/layer/iterate.c index 7be969b8f..91a4da445 100644 --- a/lib/layer/iterate.c +++ b/lib/layer/iterate.c @@ -32,8 +32,8 @@ #include "lib/module.h" #include "lib/dnssec/ta.h" -#define VERBOSE_MSG(...) QRVERBOSE(req->current_query, "iter", __VA_ARGS__) -#define QVERBOSE_MSG(qry, ...) QRVERBOSE(qry, "iter", __VA_ARGS__) +#define VERBOSE_MSG(...) QRVERBOSE(req->current_query, LOG_GRP_ITERATOR, __VA_ARGS__) +#define QVERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_ITERATOR, __VA_ARGS__) /* Iterator often walks through packet section, this is an abstraction. */ typedef int (*rr_callback_t)(const knot_rrset_t *, unsigned, struct kr_request *); diff --git a/lib/layer/validate.c b/lib/layer/validate.c index 5f8a60085..08f96e814 100644 --- a/lib/layer/validate.c +++ b/lib/layer/validate.c @@ -25,7 +25,7 @@ #include "lib/module.h" #include "lib/selection.h" -#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, "vldr", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_VALIDATOR, __VA_ARGS__) #define MAX_REVALIDATION_CNT 2 @@ -583,7 +583,7 @@ static const knot_dname_t *find_first_signer(ranked_rr_array_t *arr, struct kr_q return signame; } else { /* otherwise it's some nonsense, so we skip it */ - kr_log_q(qry, "vldr", "protocol violation: " + kr_log_q(qry, LOG_GRP_VALIDATOR, "protocol violation: " "out-of-bailwick RRSIG signer, skipping\n"); } } diff --git a/lib/log.c b/lib/log.c index 4b335b3b4..5feb42b69 100644 --- a/lib/log.c +++ b/lib/log.c @@ -6,7 +6,9 @@ #include #include +#include "contrib/ucw/mempool.h" #include "lib/log.h" +#include "lib/resolve.h" #if ENABLE_LIBSYSTEMD #include @@ -20,21 +22,23 @@ log_level_t kr_log_level = LOG_CRIT; log_target_t kr_log_target = LOG_TARGET_STDOUT; log_groups_t kr_log_groups = 0; +#define GRP_NAME_ITEM(grp) { grp ## _TAG, grp } + log_group_names_t log_group_names[] = { - { "system", LOG_GRP_SYSTEM }, - { "cache", LOG_GRP_CACHE }, - { "io", LOG_GRP_IO }, - { "network", LOG_GRP_NETWORK }, - { "ta", LOG_GRP_TA }, - { "tls", LOG_GRP_TLS }, - { "gnutls", LOG_GRP_GNUTLS }, - { "tlsclient", LOG_GRP_TLSCLIENT }, - { "xdp", LOG_GRP_XDP }, - { "zimport", LOG_GRP_ZIMPORT }, - { "zscanner", LOG_GRP_ZSCANNER }, - { "doh", LOG_GRP_DOH }, - { "dnssec", LOG_GRP_DNSSEC }, - { "hint", LOG_GRP_HINT }, + GRP_NAME_ITEM(LOG_GRP_SYSTEM), + GRP_NAME_ITEM(LOG_GRP_CACHE), + GRP_NAME_ITEM(LOG_GRP_IO), + GRP_NAME_ITEM(LOG_GRP_NETWORK), + GRP_NAME_ITEM(LOG_GRP_TA), + GRP_NAME_ITEM(LOG_GRP_TLS), + GRP_NAME_ITEM(LOG_GRP_GNUTLS), + GRP_NAME_ITEM(LOG_GRP_TLSCLIENT), + GRP_NAME_ITEM(LOG_GRP_XDP), + GRP_NAME_ITEM(LOG_GRP_ZIMPORT), + GRP_NAME_ITEM(LOG_GRP_ZSCANNER), + GRP_NAME_ITEM(LOG_GRP_DOH), + GRP_NAME_ITEM(LOG_GRP_DNSSEC), + GRP_NAME_ITEM(LOG_GRP_HINT), { NULL, -1 }, }; @@ -199,3 +203,55 @@ void kr_log_init(log_level_t level, log_target_t target) kr_log_level_set(level); } + +/* + * Cleanup callbacks. + */ +static void kr_vlog_req( + const struct kr_request * const req, uint32_t qry_uid, + const unsigned int indent, log_groups_t group, const char *tag, const char *fmt, + va_list args) +{ + if (!(KR_LOG_LEVEL_IS(LOG_DEBUG) || group_is_set(group))) + return; // skip alloc and string copy + + struct mempool *mp = mp_new(512); + + const uint32_t req_uid = req ? req->uid : 0; + char *msg = mp_printf(mp, "[%05u.%02u] %*s", + req_uid, qry_uid, indent, ""); + + msg = mp_vprintf_append(mp, msg, fmt, args); + + if (kr_log_rtrace_enabled(req)) + req->trace_log(req, msg); + else + kr_log_fmt(group, LOG_DEBUG, SD_JOURNAL_METADATA, "[%s]%s", tag, msg); + + mp_delete(mp); +} + +void kr_log_req1(const struct kr_request * const req, uint32_t qry_uid, + const unsigned int indent, log_groups_t group, const char *tag, const char *fmt, ...) +{ + va_list args; + va_start(args, fmt); + kr_vlog_req(req, qry_uid, indent, group, tag, fmt, args); + va_end(args); +} + +void kr_log_q1(const struct kr_query * const qry, + log_groups_t group, const char *tag, const char *fmt, ...) +{ + unsigned ind = 0; + for (const struct kr_query *q = qry; q; q = q->parent) + ind += 2; + const uint32_t qry_uid = qry ? qry->uid : 0; + const struct kr_request *req = qry ? qry->request : NULL; + + va_list args; + va_start(args, fmt); + kr_vlog_req(req, qry_uid, ind, group, tag, fmt, args); + va_end(args); +} + diff --git a/lib/log.h b/lib/log.h index 18481272b..eaa88ffff 100644 --- a/lib/log.h +++ b/lib/log.h @@ -27,7 +27,7 @@ typedef struct { log_groups_t g_val; } log_group_names_t; -/* Don't forget add name to log_group_names[] (log.c) */ +/* Don't forget add *_TAG below and log_group_names[] item (log.c) */ #define LOG_GRP_SYSTEM (1 << 1) #define LOG_GRP_CACHE (1 << 2) #define LOG_GRP_IO (1 << 3) @@ -42,6 +42,44 @@ typedef struct { #define LOG_GRP_DOH (1 << 12) #define LOG_GRP_DNSSEC (1 << 13) #define LOG_GRP_HINT (1 << 14) +#define LOG_GRP_PLAN (1 << 15) +#define LOG_GRP_ITERATOR (1 << 16) +#define LOG_GRP_VALIDATOR (1 << 17) +#define LOG_GRP_RESOLVER (1 << 18) +#define LOG_GRP_SELECTION (1 << 19) +#define LOG_GRP_ZCUT (1 << 20) +#define LOG_GRP_COOKIES (1 << 21) +#define LOG_GRP_STATISTICS (1 << 22) +#define LOG_GRP_REBIND (1 << 23) +#define LOG_GRP_WORKER (1 << 24) +#define LOG_GRP_POLICY (1 << 25) + +#define LOG_GRP_SYSTEM_TAG "system" +#define LOG_GRP_CACHE_TAG "cache " +#define LOG_GRP_IO_TAG "io " +#define LOG_GRP_NETWORK_TAG "net " +#define LOG_GRP_TA_TAG "ta " +#define LOG_GRP_TLS_TAG "tls " +#define LOG_GRP_GNUTLS_TAG "gnutls" +#define LOG_GRP_TLSCLIENT_TAG "tls_cl" +#define LOG_GRP_XDP_TAG "xdp " +#define LOG_GRP_ZIMPORT_TAG "zimprt" +#define LOG_GRP_ZSCANNER_TAG "zscann" +#define LOG_GRP_DOH_TAG "doh " +#define LOG_GRP_DNSSEC_TAG "dnssec" +#define LOG_GRP_HINT_TAG "hint " +#define LOG_GRP_PLAN_TAG "plan " +#define LOG_GRP_ITERATOR_TAG "iterat" +#define LOG_GRP_VALIDATOR_TAG "valdtr" +#define LOG_GRP_RESOLVER_TAG "resolv" +#define LOG_GRP_SELECTION_TAG "select" +#define LOG_GRP_ZCUT_TAG "zoncut" +#define LOG_GRP_COOKIES_TAG "cookie" +#define LOG_GRP_STATISTICS_TAG "statis" +#define LOG_GRP_REBIND_TAG "rebind" +#define LOG_GRP_WORKER_TAG "worker" +#define LOG_GRP_POLICY_TAG "policy" + KR_EXPORT extern log_groups_t kr_log_groups; @@ -79,20 +117,20 @@ void kr_log_init(log_level_t level, log_target_t target); #define SD_JOURNAL_METADATA "CODE_FILE=" __FILE__, "CODE_LINE=" TO_STR(__LINE__), "" #define kr_log_debug(grp, fmt, ...) \ - kr_log_fmt(grp, LOG_DEBUG, SD_JOURNAL_METADATA, fmt, ## __VA_ARGS__) + kr_log_fmt(grp, LOG_DEBUG, SD_JOURNAL_METADATA, "[" grp ## _TAG "] " fmt, ## __VA_ARGS__) #define kr_log_info(grp, fmt, ...) \ - kr_log_fmt(grp, LOG_INFO, SD_JOURNAL_METADATA, fmt, ## __VA_ARGS__) + kr_log_fmt(grp, LOG_INFO, SD_JOURNAL_METADATA, "[" grp ## _TAG "] " fmt, ## __VA_ARGS__) #define kr_log_notice(grp, fmt, ...) \ - kr_log_fmt(grp, LOG_NOTICE, SD_JOURNAL_METADATA, fmt, ## __VA_ARGS__) + kr_log_fmt(grp, LOG_NOTICE, SD_JOURNAL_METADATA, "[" grp ## _TAG "] " fmt, ## __VA_ARGS__) #define kr_log_warning(grp, fmt, ...) \ - kr_log_fmt(grp, LOG_WARNING, SD_JOURNAL_METADATA, fmt, ## __VA_ARGS__) + kr_log_fmt(grp, LOG_WARNING, SD_JOURNAL_METADATA, "[" grp ## _TAG "] " fmt, ## __VA_ARGS__) #define kr_log_error(grp, fmt, ...) \ - kr_log_fmt(grp, LOG_ERR, SD_JOURNAL_METADATA, fmt, ## __VA_ARGS__) + kr_log_fmt(grp, LOG_ERR, SD_JOURNAL_METADATA, "[" grp ## _TAG "] " fmt, ## __VA_ARGS__) #define kr_log_fatal(grp, fmt, ...) \ - kr_log_fmt(grp, LOG_CRIT, SD_JOURNAL_METADATA, fmt, ## __VA_ARGS__) + kr_log_fmt(grp, LOG_CRIT, SD_JOURNAL_METADATA, "[" grp ## _TAG "] " fmt, ## __VA_ARGS__) #define kr_log_deprecate(grp, fmt, ...) \ - kr_log_fmt(grp, LOG_WARNING,SD_JOURNAL_METADATA, "deprecation WARNING: " fmt, ## __VA_ARGS__) + kr_log_fmt(grp, LOG_WARNING,SD_JOURNAL_METADATA, "[" grp ## _TAG "] deprecation WARNING: " fmt, ## __VA_ARGS__) #define KR_LOG_LEVEL_IS(exp) ((kr_log_level >= (exp)) ? true : false) @@ -113,3 +151,39 @@ typedef struct _code { KR_EXPORT extern syslog_code_t prioritynames[]; #endif + + +/* Misc. */ + +struct kr_request; +struct kr_query; + +/** + * Log a message through the request log handler or stdout. + * Caller is responsible for detecting verbose mode, use QRVERBOSE() macro. + * @param qry_uid query ID to append to request ID, 0 means "no query" + * @param indent level of indentation between [req.qry][source] and message + * @param source message source + * @param fmt message format + */ +#define kr_log_req(req, qry_id, indent, grp, fmt, ...) \ + kr_log_req1(req, qry_id, indent, grp, grp ## _TAG, fmt, ## __VA_ARGS__) +KR_EXPORT KR_PRINTF(6) +void kr_log_req1(const struct kr_request * const req, uint32_t qry_uid, + const unsigned int indent, log_groups_t group, const char *tag, const char *fmt, ...); + +/** + * Log a message through the request log handler or stdout. + * Caller is responsible for detecting verbose mode, use QRVERBOSE() macro. + * @param qry current query + * @param source message source + * @param fmt message format + */ +#define kr_log_q(qry, grp, fmt, ...) kr_log_q1(qry, grp, grp ## _TAG, fmt, ## __VA_ARGS__) +KR_EXPORT KR_PRINTF(4) +void kr_log_q1(const struct kr_query *qry, log_groups_t 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)) +#define kr_log_verbose if(VERBOSE_STATUS) printf diff --git a/lib/resolve.c b/lib/resolve.c index dfb6d6b6f..3c3b61542 100644 --- a/lib/resolve.c +++ b/lib/resolve.c @@ -26,7 +26,7 @@ #define KNOT_EDNS_OPTION_COOKIE 10 #endif /* ENABLE_COOKIES */ -#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), "resl", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), LOG_GRP_RESOLVER, __VA_ARGS__) bool kr_rank_check(uint8_t rank) { @@ -458,7 +458,7 @@ 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)) - kr_log_req(request, 0, 0, "resl", + kr_log_req(request, 0, 0, LOG_GRP_RESOLVER, "request failed, answering with empty SERVFAIL\n"); knot_pkt_t *answer = request->answer; knot_rrset_t *opt_rr = answer->opt_rr; /* it gets NULLed below */ @@ -834,7 +834,7 @@ int kr_resolve_consume(struct kr_request *request, struct kr_transport **transpo if (request->state & KR_STATE_FAIL) { if (++request->count_fail_row > KR_CONSUME_FAIL_ROW_LIMIT) { if (VERBOSE_STATUS || kr_log_rtrace_enabled(request)) { - kr_log_req(request, 0, 2, "resl", + kr_log_req(request, 0, 2, LOG_GRP_RESOLVER, "=> too many failures in a row, " "bail out (mitigation for NXNSAttack " "CVE-2020-12667)\n"); diff --git a/lib/rplan.c b/lib/rplan.c index e88b982b6..7eac9fa0b 100644 --- a/lib/rplan.c +++ b/lib/rplan.c @@ -11,7 +11,7 @@ #include "lib/defines.h" #include "lib/layer.h" -#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, "plan", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_PLAN, __VA_ARGS__) inline static unsigned char chars_or(const unsigned char a, const unsigned char b) { diff --git a/lib/selection.c b/lib/selection.c index 535af1691..dc2382d1a 100644 --- a/lib/selection.c +++ b/lib/selection.c @@ -14,7 +14,7 @@ #include "lib/utils.h" -#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), "slct", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), LOG_GRP_SELECTION, __VA_ARGS__) #define DEFAULT_TIMEOUT 400 #define MAX_TIMEOUT 10000 diff --git a/lib/selection_forward.c b/lib/selection_forward.c index cde634d56..f2f233d1a 100644 --- a/lib/selection_forward.c +++ b/lib/selection_forward.c @@ -5,7 +5,7 @@ #include "lib/selection_forward.h" #include "lib/resolve.h" -#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), "slct", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), LOG_GRP_SELECTION, __VA_ARGS__) #define FORWARDING_TIMEOUT 2000 diff --git a/lib/selection_iter.c b/lib/selection_iter.c index 87206cc01..0a5bbda17 100644 --- a/lib/selection_iter.c +++ b/lib/selection_iter.c @@ -10,7 +10,7 @@ #include "lib/zonecut.h" #include "lib/resolve.h" -#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), "slct", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE((qry), LOG_GRP_SELECTION, __VA_ARGS__) /// To be held per query and locally. Allocations are in the kr_request's mempool. struct iter_local_state { diff --git a/lib/utils.c b/lib/utils.c index db5988bdb..016247c56 100644 --- a/lib/utils.c +++ b/lib/utils.c @@ -85,55 +85,6 @@ static inline int u16tostr(uint8_t *dst, uint16_t num) return 5; } -/* - * Cleanup callbacks. - */ -static void kr_vlog_req( - const struct kr_request * const req, uint32_t qry_uid, - const unsigned int indent, const char *source, const char *fmt, - va_list args) -{ - struct mempool *mp = mp_new(512); - - const uint32_t req_uid = req ? req->uid : 0; - char *msg = mp_printf(mp, "[%05u.%02u][%-4s] %*s", - req_uid, qry_uid, source, indent, ""); - - msg = mp_vprintf_append(mp, msg, fmt, args); - - if (kr_log_rtrace_enabled(req)) - req->trace_log(req, msg); - else - /* caller is responsible for detecting verbose mode, use QRVERBOSE() macro */ - printf("%s", msg); - - mp_delete(mp); -} - -void kr_log_req(const struct kr_request * const req, uint32_t qry_uid, - const unsigned int indent, const char *source, const char *fmt, ...) -{ - va_list args; - va_start(args, fmt); - kr_vlog_req(req, qry_uid, indent, source, fmt, args); - va_end(args); -} - -void kr_log_q(const struct kr_query * const qry, - const char *source, const char *fmt, ...) -{ - unsigned ind = 0; - for (const struct kr_query *q = qry; q; q = q->parent) - ind += 2; - const uint32_t qry_uid = qry ? qry->uid : 0; - const struct kr_request *req = qry ? qry->request : NULL; - - va_list args; - va_start(args, fmt); - kr_vlog_req(req, qry_uid, ind, source, fmt, args); - va_end(args); -} - char* kr_strcatdup(unsigned n, ...) { if (n < 1) { @@ -817,7 +768,7 @@ int kr_ranked_rrarray_finalize(ranked_rr_array_t *array, uint32_t qry_uid, knot_ if (knot_rdata_cmp(ra->at[i], ra->at[i + 1]) == 0) { ra->at[i] = NULL; ++dup_count; - QRVERBOSE(NULL, "iter", "deleted duplicate RR\n"); + QRVERBOSE(NULL, LOG_GRP_ITERATOR, "deleted duplicate RR\n"); } } /* Prepare rdataset, except rdata contents. */ diff --git a/lib/utils.h b/lib/utils.h index 4e9c7699d..ba628b417 100644 --- a/lib/utils.h +++ b/lib/utils.h @@ -28,8 +28,6 @@ #include "lib/generic/array.h" #include "lib/log.h" -struct kr_query; -struct kr_request; /* * Logging and debugging. @@ -107,33 +105,6 @@ static inline bool kr_assert_func(bool result, const char *expr, const char *fun (qry) && kr_log_rtrace_enabled(qry->request), \ false)) -/** - * Log a message through the request log handler or stdout. - * Caller is responsible for detecting verbose mode, use QRVERBOSE() macro. - * @param qry_uid query ID to append to request ID, 0 means "no query" - * @param indent level of indentation between [req.qry][source] and message - * @param source message source - * @param fmt message format - */ -KR_EXPORT KR_PRINTF(5) -void kr_log_req(const struct kr_request * const req, uint32_t qry_uid, - const unsigned int indent, const char *source, const char *fmt, ...); - -/** - * Log a message through the request log handler or stdout. - * Caller is responsible for detecting verbose mode, use QRVERBOSE() macro. - * @param qry current query - * @param source message source - * @param fmt message format - */ -KR_EXPORT KR_PRINTF(3) -void kr_log_q(const struct kr_query *qry, const char *source, const char *fmt, ...); - -/** Block run in --verbose mode; optimized when not run. */ -#define VERBOSE_STATUS __builtin_expect(KR_LOG_LEVEL_IS(LOG_DEBUG), false) -#define WITH_VERBOSE(query) if(__builtin_expect(KR_LOG_LEVEL_IS(LOG_DEBUG) || kr_log_qtrace_enabled(query), false)) -#define kr_log_verbose if(VERBOSE_STATUS) printf - #define KR_DNAME_GET_STR(dname_str, dname) \ char dname_str[KR_DNAME_STR_MAXLEN]; \ knot_dname_to_str(dname_str, (dname), sizeof(dname_str)); \ diff --git a/lib/zonecut.c b/lib/zonecut.c index 4577c634b..b0d5aeb5b 100644 --- a/lib/zonecut.c +++ b/lib/zonecut.c @@ -15,7 +15,7 @@ #include #include -#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, "zcut", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_ZCUT, __VA_ARGS__) /** Information for one NS name + address type. */ typedef enum { diff --git a/modules/cookies/cookiemonster.c b/modules/cookies/cookiemonster.c index 3cb06cb5b..eca6df8fb 100644 --- a/modules/cookies/cookiemonster.c +++ b/modules/cookies/cookiemonster.c @@ -20,7 +20,7 @@ #include "lib/rplan.h" #include "modules/cookies/cookiemonster.h" -#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, "cookies", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_COOKIES, __VA_ARGS__) /** * Obtain address from query/response context if if can be obtained. diff --git a/modules/hints/hints.c b/modules/hints/hints.c index 740999000..35cdaf44f 100644 --- a/modules/hints/hints.c +++ b/modules/hints/hints.c @@ -25,8 +25,8 @@ #include /* Defaults */ -#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, "hint", __VA_ARGS__) -#define ERR_MSG(...) kr_log_error(LOG_GRP_HINT, "[ ][hint]" __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_HINT, __VA_ARGS__) +#define ERR_MSG(...) kr_log_error(LOG_GRP_HINT, "[ ]" __VA_ARGS__) struct hints_data { struct kr_zonecut hints; diff --git a/modules/policy/policy.lua b/modules/policy/policy.lua index 1b450d84f..a3cd30417 100644 --- a/modules/policy/policy.lua +++ b/modules/policy/policy.lua @@ -652,15 +652,17 @@ ffi.gc(debug_logline_cb, free_cb) local debug_logfinish_cb = ffi.cast('trace_callback_f', function (req) jit.off(true, true) -- JIT for (C -> lua)^2 nesting isn't allowed - ffi.C.kr_log_req(req, 0, 0, 'dbg', + local LOG_GRP_POLICY= bit.lshift(1, 25) + local LOG_GRP_POLICY_TAG="policy" + ffi.C.kr_log_req1(req, 0, 0, LOG_GRP_POLICY, LOG_GRP_POLICY_TAG, 'following rrsets were marked as interesting:\n' .. req:selected_tostring()) if req.answer ~= nil then - ffi.C.kr_log_req(req, 0, 0, 'dbg', + ffi.C.kr_log_req1(req, 0, 0, LOG_GRP_POLICY, LOG_GRP_POLICY_TAG, 'answer packet:\n' .. tostring(req.answer)) else - ffi.C.kr_log_req(req, 0, 0, 'dbg', + ffi.C.kr_log_req1(req, 0, 0, LOG_GRP_POLICY, LOG_GRP_POLICY_TAG, 'answer packet DROPPED\n') end end) @@ -668,7 +670,10 @@ ffi.gc(debug_logfinish_cb, free_cb) -- log request packet function policy.REQTRACE(_, req) - ffi.C.kr_log_req(req, 0, 0, 'dbg', 'request packet:\n%s', + local LOG_GRP_POLICY= bit.lshift(1, 25) + local LOG_GRP_POLICY_TAG="policy" + ffi.C.kr_log_req1(req, 0, 0, LOG_GRP_POLICY, LOG_GRP_POLICY_TAG, + 'request packet:\n%s', tostring(req.qsource.packet)) end diff --git a/modules/rebinding/rebinding.lua b/modules/rebinding/rebinding.lua index f75656ca8..68c6fd89e 100644 --- a/modules/rebinding/rebinding.lua +++ b/modules/rebinding/rebinding.lua @@ -108,7 +108,9 @@ function M.layer.consume(state, req, pkt) state = refuse(req) end if verbose() then - ffi.C.kr_log_q(qry, 'rebinding', + local LOG_GRP_REBIND= bit.lshift(1, 23) + local LOG_GRP_REBIND_TAG="rebind" + ffi.C.kr_log_q1(qry, LOG_GRP_REBIND, LOG_GRP_REBIND_TAG, 'blocking blacklisted IP in RR \'%s\'\n', kres.rr2str(bad_rr)) end return state diff --git a/modules/stats/stats.c b/modules/stats/stats.c index 5deb09323..75b6a9127 100644 --- a/modules/stats/stats.c +++ b/modules/stats/stats.c @@ -25,7 +25,7 @@ #include "lib/resolve.h" /* Defaults */ -#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, "stat", __VA_ARGS__) +#define VERBOSE_MSG(qry, ...) QRVERBOSE(qry, LOG_GRP_STATISTICS, __VA_ARGS__) #define FREQUENT_PSAMPLE 10 /* Sampling rate, 1 in N */ #ifdef LRU_REP_SIZE #define FREQUENT_COUNT LRU_REP_SIZE /* Size of frequent tables */