log: use kr_log_debug instead kr_log_verbose

diff --git a/daemon/bindings/net.c b/daemon/bindings/net.c
index 1c66358c7b3c79ddbf8c47ddbbb6139e9af460f0..79993b0184130e83db6e8567f0c71fa9e93258d5 100644 (file)
--- a/daemon/bindings/net.c
+++ b/daemon/bindings/net.c
@@ -653,8 +653,7 @@ static int net_tls_client(lua_State *L)
                                        ca_file, gnutls_strerror_name(ret),
                                        gnutls_strerror(ret));
                        } else {
-                               kr_log_verbose(
-                                       "[tls_client] imported %d certs from file '%s'\n",
+                               kr_log_debug(TLSCLIENT, "imported %d certs from file '%s'\n",
                                        ret, ca_file);
                        }
 
@@ -731,8 +730,7 @@ static int net_tls_client(lua_State *L)
                        ERROR("failed to use system CA certificate store: %s",
                                ret ? gnutls_strerror(ret) : kr_strerror(ENOENT));
                } else {
-                       kr_log_verbose(
-                               "[tls_client] imported %d certs from system store\n",
+                       kr_log_debug(TLSCLIENT, "imported %d certs from system store\n",
                                ret);
                }
        }

diff --git a/daemon/engine.c b/daemon/engine.c
index 5119ed1c51068cd4a2549020b0b90e4bb32eb737..cc684c66fd569cfc65021d6b566624586a2fc739 100644 (file)
--- a/daemon/engine.c
+++ b/daemon/engine.c
@@ -724,7 +724,7 @@ int engine_loadconf(struct engine *engine, const char *config_path)
 
        char cwd[PATH_MAX];
        get_workdir(cwd, sizeof(cwd));
-       kr_log_verbose("[system] loading config '%s' (workdir '%s')\n", config_path, cwd);
+       kr_log_debug(SYSTEM, "loading config '%s' (workdir '%s')\n", config_path, cwd);
 
        int ret = luaL_dofile(engine->L, config_path);
        if (ret != 0) {

diff --git a/daemon/http.c b/daemon/http.c
index b1563a9d0c6f67c01e16a03538d352413c32cfdd..7472956fe4ea9b79b773b6b25b5c963563bf4ee0 100644 (file)
--- a/daemon/http.c
+++ b/daemon/http.c
@@ -230,8 +230,7 @@ static int process_uri_path(struct http_ctx *ctx, const char* path, int32_t stre
        ret = kr_base64url_decode((uint8_t*)beg, end - beg, dest, remaining);
        if (ret < 0) {
                ctx->buf_pos = 0;
-               kr_log_verbose("[http] base64url decode failed %s\n",
-                              strerror(ret));
+               kr_log_debug(DOH, "base64url decode failed %s\n", strerror(ret));
                return ret;
        }
 
@@ -288,8 +287,8 @@ static int begin_headers_callback(nghttp2_session *h2, const nghttp2_frame *fram
        }
 
        if (ctx->incomplete_stream != -1) {
-               kr_log_verbose(
-                       "[http] stream %d incomplete, refusing\n", ctx->incomplete_stream);
+               kr_log_debug(DOH, "stream %d incomplete, refusing\n",
+                               ctx->incomplete_stream);
                refuse_stream(h2, stream_id);
        } else {
                http_cleanup_stream(ctx);  // Free any leftover data and ensure pristine state
@@ -317,8 +316,8 @@ static int header_callback(nghttp2_session *h2, const nghttp2_frame *frame,
                return 0;
 
        if (ctx->incomplete_stream != stream_id) {
-               kr_log_verbose(
-                       "[http] stream %d incomplete, refusing\n", ctx->incomplete_stream);
+               kr_log_debug(DOH, "stream %d incomplete, refusing\n",
+                               ctx->incomplete_stream);
                refuse_stream(h2, stream_id);
                return 0;
        }
@@ -330,8 +329,8 @@ static int header_callback(nghttp2_session *h2, const nghttp2_frame *frame,
 
                        /* Limit maximum value size to reduce attack surface. */
                        if (valuelen > HTTP_MAX_HEADER_IN_SIZE) {
-                               kr_log_verbose(
-                                       "[http] stream %d: header too large (%zu B), refused\n",
+                               kr_log_debug(DOH,
+                                       "stream %d: header too large (%zu B), refused\n",
                                        stream_id, valuelen);
                                refuse_stream(h2, stream_id);
                                return 0;
@@ -394,8 +393,7 @@ static int data_chunk_recv_callback(nghttp2_session *h2, uint8_t flags, int32_t
        bool is_first = queue_len(ctx->streams) == 0 || queue_tail(ctx->streams).id != ctx->incomplete_stream;
 
        if (ctx->incomplete_stream != stream_id) {
-               kr_log_verbose(
-                       "[http] stream %d incomplete, refusing\n",
+               kr_log_debug(DOH, "stream %d incomplete, refusing\n",
                        ctx->incomplete_stream);
                refuse_stream(h2, stream_id);
                ctx->incomplete_stream = -1;
@@ -455,7 +453,7 @@ static int on_frame_recv_callback(nghttp2_session *h2, const nghttp2_frame *fram
 
                len = ctx->buf_pos - sizeof(uint16_t);
                if (len <= 0 || len > KNOT_WIRE_MAX_PKTSIZE) {
-                       kr_log_verbose("[http] invalid dnsmsg size: %zd B\n", len);
+                       kr_log_debug(DOH, "invalid dnsmsg size: %zd B\n", len);
                        return NGHTTP2_ERR_CALLBACK_FAILURE;
                }
 
@@ -573,14 +571,14 @@ ssize_t http_process_input_data(struct session *session, const uint8_t *buf,
 
        ret = nghttp2_session_mem_recv(ctx->h2, buf, nread);
        if (ret < 0) {
-               kr_log_verbose("[http] nghttp2_session_mem_recv failed: %s (%zd)\n",
+               kr_log_debug(DOH, "nghttp2_session_mem_recv failed: %s (%zd)\n",
                               nghttp2_strerror(ret), ret);
                return kr_error(EIO);
        }
 
        ret = nghttp2_session_send(ctx->h2);
        if (ret < 0) {
-               kr_log_verbose("[http] nghttp2_session_send failed: %s (%zd)\n",
+               kr_log_debug(DOH, "nghttp2_session_send failed: %s (%zd)\n",
                             nghttp2_strerror(ret), ret);
                return kr_error(EIO);
        }
@@ -644,14 +642,14 @@ static int http_send_response(nghttp2_session *h2, int32_t stream_id,
 
        ret = nghttp2_session_set_stream_user_data(h2, stream_id, (void*)data);
        if (ret != 0) {
-               kr_log_verbose("[http] failed to set stream user data: %s\n", nghttp2_strerror(ret));
+               kr_log_debug(DOH, "failed to set stream user data: %s\n", nghttp2_strerror(ret));
                free(data);
                return kr_error(EIO);
        }
 
        ret = nghttp2_submit_response(h2, stream_id, hdrs, sizeof(hdrs)/sizeof(*hdrs), prov);
        if (ret != 0) {
-               kr_log_verbose("[http] nghttp2_submit_response failed: %s\n", nghttp2_strerror(ret));
+               kr_log_debug(DOH, "nghttp2_submit_response failed: %s\n", nghttp2_strerror(ret));
                nghttp2_session_set_stream_user_data(h2, stream_id, NULL);  // just in case
                free(data);
                return kr_error(EIO);
@@ -659,7 +657,7 @@ static int http_send_response(nghttp2_session *h2, int32_t stream_id,
 
        ret = nghttp2_session_send(h2);
        if(ret < 0) {
-               kr_log_verbose("[http] nghttp2_session_send failed: %s\n", nghttp2_strerror(ret));
+               kr_log_debug(DOH, "nghttp2_session_send failed: %s\n", nghttp2_strerror(ret));
 
                /* At this point, there was an error in some nghttp2 callback. The on_pkt_write()
                 * callback which also calls free(data) may or may not have been called. Therefore,

diff --git a/daemon/io.c b/daemon/io.c
index 39b6b4ec9568b3de4782eebae347e8ffb7945c2c..84910a425356a339adb4bc2c9bd4f577980b569e 100644 (file)
--- a/daemon/io.c
+++ b/daemon/io.c
@@ -79,7 +79,7 @@ void udp_recv(uv_udp_t *handle, ssize_t nread, const uv_buf_t *buf,
                if (kr_fails_assert(peer->sa_family != AF_UNSPEC))
                        return;
                if (kr_sockaddr_cmp(peer, addr) != 0) {
-                       kr_log_verbose("[io] <= ignoring UDP from unexpected address '%s'\n",
+                       kr_log_debug(IO, "<= ignoring UDP from unexpected address '%s'\n",
                                        kr_straddr(addr));
                        return;
                }
@@ -253,7 +253,7 @@ void tcp_timeout_trigger(uv_timer_t *timer)
                } else {
                        struct sockaddr *peer = session_get_peer(s);
                        char *peer_str = kr_straddr(peer);
-                       kr_log_verbose("[io] => closing connection to '%s'\n",
+                       kr_log_debug(IO, "=> closing connection to '%s'\n",
                                       peer_str ? peer_str : "");
                        if (session_flags(s)->outgoing) {
                                worker_del_tcp_waiting(the_worker, peer);
@@ -284,7 +284,7 @@ static void tcp_recv(uv_stream_t *handle, ssize_t nread, const uv_buf_t *buf)
                if (KR_LOG_LEVEL_IS(LOG_DEBUG)) {
                        struct sockaddr *peer = session_get_peer(s);
                        char *peer_str = kr_straddr(peer);
-                       kr_log_verbose("[io] => connection to '%s' closed by peer (%s)\n",
+                       kr_log_debug(IO, "=> connection to '%s' closed by peer (%s)\n",
                                       peer_str ? peer_str : "",
                                       uv_strerror(nread));
                }
@@ -303,7 +303,7 @@ static void tcp_recv(uv_stream_t *handle, ssize_t nread, const uv_buf_t *buf)
                        if (KR_LOG_LEVEL_IS(LOG_DEBUG)) {
                                struct sockaddr *peer = session_get_peer(s);
                                char *peer_str = kr_straddr(peer);
-                               kr_log_verbose("[io] => connection to '%s': "
+                               kr_log_debug(IO, "=> connection to '%s': "
                                               "error processing TLS data, close\n",
                                               peer_str ? peer_str : "");
                        }
@@ -322,7 +322,7 @@ static void tcp_recv(uv_stream_t *handle, ssize_t nread, const uv_buf_t *buf)
                        if (KR_LOG_LEVEL_IS(LOG_DEBUG)) {
                                struct sockaddr *peer = session_get_peer(s);
                                char *peer_str = kr_straddr(peer);
-                               kr_log_verbose("[io] => connection to '%s': "
+                               kr_log_debug(IO, "=> connection to '%s': "
                                       "error processing HTTP data, close\n",
                                       peer_str ? peer_str : "");
                        }
@@ -359,7 +359,7 @@ static ssize_t tls_send(const uint8_t *buf, const size_t len, struct session *se
 
        sent = gnutls_record_send(ctx->c.tls_session, buf, len);
        if (sent < 0) {
-               kr_log_verbose("[http] gnutls_record_send failed: %s (%zd)\n",
+               kr_log_debug(DOH, "gnutls_record_send failed: %s (%zd)\n",
                               gnutls_strerror_name(sent), sent);
                return kr_error(EIO);
        }
@@ -821,7 +821,7 @@ static void xdp_rx(uv_poll_t* handle, int status, int events)
                kr_log_error(XDP, "knot_xdp_recv(): %d, %s\n", ret, knot_strerror(ret));
                return;
        }
-       kr_log_verbose("poll triggered, processing a batch of %d packets\n", (int)rcvd);
+       kr_log_debug(XDP, "poll triggered, processing a batch of %d packets\n", (int)rcvd);
        kr_require(rcvd <= XDP_RX_BATCH_SIZE);
        for (int i = 0; i < rcvd; ++i) {
                const knot_xdp_msg_t *msg = &msgs[i];
@@ -837,7 +837,7 @@ static void xdp_rx(uv_poll_t* handle, int status, int events)
                                        msg->eth_from, msg->eth_to, kpkt);
                }
                if (ret)
-                       kr_log_verbose("[xdp] worker_submit() == %d: %s\n", ret, kr_strerror(ret));
+                       kr_log_debug(XDP, "worker_submit() == %d: %s\n", ret, kr_strerror(ret));
                mp_flush(the_worker->pkt_pool.ctx);
        }
        knot_xdp_recv_finish(xhd->socket, msgs, rcvd);

diff --git a/daemon/lua/kres-gen-29.lua b/daemon/lua/kres-gen-29.lua
index 668c773c5d9a127801cd160a64aa49e523930ed8..bcc824f136f148c87d9def50c03d6e53629db60b 100644 (file)
--- a/daemon/lua/kres-gen-29.lua
+++ b/daemon/lua/kres-gen-29.lua
@@ -308,7 +308,7 @@ struct kr_server_selection {
 };
 typedef unsigned long log_groups_t;
 typedef int log_level_t;
-enum kr_log_groups_type {LOG_GRP_SYSTEM = 1, LOG_GRP_CACHE, LOG_GRP_IO, LOG_GRP_NETWORK, LOG_GRP_TA, LOG_GRP_TLS, LOG_GRP_GNUTLS, LOG_GRP_TLSCLIENT, LOG_GRP_XDP, LOG_GRP_ZIMPORT, LOG_GRP_ZSCANNER, LOG_GRP_DOH, LOG_GRP_DNSSEC, LOG_GRP_HINT, LOG_GRP_PLAN, LOG_GRP_ITERATOR, LOG_GRP_VALIDATOR, LOG_GRP_RESOLVER, LOG_GRP_SELECTION, LOG_GRP_ZCUT, LOG_GRP_COOKIES, LOG_GRP_STATISTICS, LOG_GRP_REBIND, LOG_GRP_WORKER, LOG_GRP_POLICY, LOG_GRP_TASENTINEL, LOG_GRP_TASIGNALING, LOG_GRP_TAUPDATE, LOG_GRP_DAF, LOG_GRP_DETECTTIMEJUMP, LOG_GRP_DETECTTIMESKEW, LOG_GRP_GRAPHITE, LOG_GRP_PREFILL, LOG_GRP_PRIMING, LOG_GRP_SRVSTALE, LOG_GRP_WATCHDOG, LOG_GRP_TESTS};
+enum kr_log_groups_type {LOG_GRP_SYSTEM = 1, LOG_GRP_CACHE, LOG_GRP_IO, LOG_GRP_NETWORK, LOG_GRP_TA, LOG_GRP_TLS, LOG_GRP_GNUTLS, LOG_GRP_TLSCLIENT, LOG_GRP_XDP, LOG_GRP_ZIMPORT, LOG_GRP_ZSCANNER, LOG_GRP_DOH, LOG_GRP_DNSSEC, LOG_GRP_HINT, LOG_GRP_PLAN, LOG_GRP_ITERATOR, LOG_GRP_VALIDATOR, LOG_GRP_RESOLVER, LOG_GRP_SELECTION, LOG_GRP_ZCUT, LOG_GRP_COOKIES, LOG_GRP_STATISTICS, LOG_GRP_REBIND, LOG_GRP_WORKER, LOG_GRP_POLICY, LOG_GRP_TASENTINEL, LOG_GRP_TASIGNALING, LOG_GRP_TAUPDATE, LOG_GRP_DAF, LOG_GRP_DETECTTIMEJUMP, LOG_GRP_DETECTTIMESKEW, LOG_GRP_GRAPHITE, LOG_GRP_PREFILL, LOG_GRP_PRIMING, LOG_GRP_SRVSTALE, LOG_GRP_WATCHDOG, LOG_GRP_NSID, LOG_GRP_DNSTAP, LOG_GRP_TESTS};
 
 kr_layer_t kr_layer_t_static;
 _Bool kr_dbg_assertion_abort;

diff --git a/daemon/lua/sandbox.lua.in b/daemon/lua/sandbox.lua.in
index eff54eb821dc48adcf691c3bf70601d2c045695c..5c4fcc5139d271264c8691e4aecc4c805fafaa2b 100644 (file)
--- a/daemon/lua/sandbox.lua.in
+++ b/daemon/lua/sandbox.lua.in
@@ -31,8 +31,8 @@ local function curr_file() return debug.getinfo(4,'S').source end
 local function curr_line() return debug.getinfo(4,'l').currentline end
 
 local function log_fmt(grp, level, fmt, ...)
-       ffi.C.kr_log_fmt(grp, level, "CODE_FILE="..curr_file(), "CODE_LINE="..curr_line(), "",
-                       "[%s]" .. fmt, ffi.C.kr_log_grp2name(grp), ...)
+       ffi.C.kr_log_fmt(grp, level, 'CODE_FILE='..curr_file(), 'CODE_LINE='..curr_line(), '',
+                       '[%s] ' .. fmt .. '\n', ffi.C.kr_log_grp2name(grp), ...)
 end
 
 function log_req(req, qry_uid, indent, grp, fmt, ...)

diff --git a/daemon/main.c b/daemon/main.c
index 084cd102490ba35c9b05809ff5452888790f9635..08e662c3fe00ddb4e94a47b82d946fbc437c1d05 100644 (file)
--- a/daemon/main.c
+++ b/daemon/main.c
@@ -384,7 +384,7 @@ static void drop_capabilities(void)
 #if ENABLE_CAP_NG
        /* Drop all capabilities when running under non-root user. */
        if (geteuid() == 0) {
-               kr_log_verbose("[system] running as root, no capabilities dropped\n");
+               kr_log_debug(SYSTEM, "running as root, no capabilities dropped\n");
                return;
        }
        if (capng_have_capability(CAPNG_EFFECTIVE, CAP_SETPCAP)) {
@@ -395,11 +395,11 @@ static void drop_capabilities(void)
                        kr_log_error(SYSTEM, "failed to set process capabilities: %s\n",
                                  strerror(errno));
                } else {
-                       kr_log_verbose("[system] all capabilities dropped\n");
+                       kr_log_debug(SYSTEM, "all capabilities dropped\n");
                }
        } else {
                /* If user() was called, the capabilities were already dropped along with SETPCAP. */
-               kr_log_verbose("[system] process not allowed to set capabilities, skipping\n");
+               kr_log_debug(SYSTEM, "process not allowed to set capabilities, skipping\n");
        }
 #endif /* ENABLE_CAP_NG */
 }
@@ -465,7 +465,7 @@ int main(int argc, char **argv)
        struct rlimit rlim;
        ret = getrlimit(RLIMIT_NOFILE, &rlim);
        if (ret == 0 && rlim.rlim_cur != rlim.rlim_max) {
-               kr_log_verbose("[system] increasing file-descriptor limit: %ld -> %ld\n",
+               kr_log_debug(SYSTEM, "increasing file-descriptor limit: %ld -> %ld\n",
                                (long)rlim.rlim_cur, (long)rlim.rlim_max);
                rlim.rlim_cur = rlim.rlim_max;
                ret = setrlimit(RLIMIT_NOFILE, &rlim);

diff --git a/daemon/tls.c b/daemon/tls.c
index e402be7f48043c732b706c9cf8afe0710e5fb92c..98168218a1d425f5892608ed5250053bd53a6d38 100644 (file)
--- a/daemon/tls.c
+++ b/daemon/tls.c
@@ -27,9 +27,15 @@
 #define EPHEMERAL_CERT_EXPIRATION_SECONDS_RENEW_BEFORE (60*60*24*7)
 #define GNUTLS_PIN_MIN_VERSION  0x030400
 
+#define VERBOSE_MSG(cl_side, ...)\
+       if (cl_side) \
+               kr_log_debug(TLSCLIENT, __VA_ARGS__); \
+       else \
+               kr_log_debug(TLS, __VA_ARGS__);
+
 /** @internal Debugging facility. */
 #ifdef DEBUG
-#define DEBUG_MSG(...) kr_log_verbose("[tls] " __VA_ARGS__)
+#define DEBUG_MSG(...) kr_log_debug(TLS, __VA_ARGS__)
 #else
 #define DEBUG_MSG(...)
 #endif
@@ -40,9 +46,6 @@ struct async_write_ctx {
        char buf[];
 };
 
-static char const server_logstring[] = "tls";
-static char const client_logstring[] = "tls_client";
-
 static int client_verify_certificate(gnutls_session_t tls_session);
 
 /**
@@ -165,8 +168,8 @@ static ssize_t kres_gnutls_vec_push(gnutls_transport_ptr_t h, const giovec_t * i
                if (ret < 0 && ret != UV_EAGAIN) {
                        /* uv_try_write() has returned error code other then UV_EAGAIN.
                         * Return. */
-                       kr_log_verbose("[%s] uv_try_write error: %s\n",
-                                      t->client_side ? "tls_client" : "tls", uv_strerror(ret));
+                       VERBOSE_MSG(t->client_side, "uv_try_write error: %s\n",
+                                       uv_strerror(ret));
                        ret = -1;
                        errno = EIO;
                        return ret;
@@ -224,8 +227,8 @@ static ssize_t kres_gnutls_vec_push(gnutls_transport_ptr_t h, const giovec_t * i
                        t->write_queue_size += 1;
                } else {
                        free(p);
-                       kr_log_verbose("[%s] uv_write error: %s\n",
-                                      t->client_side ? "tls_client" : "tls", uv_strerror(ret));
+                       VERBOSE_MSG(t->client_side, "uv_write error: %s\n",
+                                       uv_strerror(ret));
                        errno = EIO;
                        ret = -1;
                }
@@ -246,15 +249,14 @@ static ssize_t kres_gnutls_vec_push(gnutls_transport_ptr_t h, const giovec_t * i
   */
 static int tls_handshake(struct tls_common_ctx *ctx, tls_handshake_cb handshake_cb) {
        struct session *session = ctx->session;
-       const char *logstring = ctx->client_side ? client_logstring : server_logstring;
 
        int err = gnutls_handshake(ctx->tls_session);
        if (err == GNUTLS_E_SUCCESS) {
                /* Handshake finished, return success */
                ctx->handshake_state = TLS_HS_DONE;
                struct sockaddr *peer = session_get_peer(session);
-               kr_log_verbose("[%s] TLS handshake with %s has completed\n",
-                              logstring,  kr_straddr(peer));
+               VERBOSE_MSG(ctx->client_side, "TLS handshake with %s has completed\n",
+                               kr_straddr(peer));
                if (handshake_cb) {
                        if (handshake_cb(session, 0) != kr_ok()) {
                                return kr_error(EIO);
@@ -264,9 +266,8 @@ static int tls_handshake(struct tls_common_ctx *ctx, tls_handshake_cb handshake_
                return kr_error(EAGAIN);
        } else if (gnutls_error_is_fatal(err)) {
                /* Fatal errors, return error as it's not recoverable */
-               kr_log_verbose("[%s] gnutls_handshake failed: %s (%d)\n",
-                            logstring,
-                            gnutls_strerror_name(err), err);
+               VERBOSE_MSG(ctx->client_side, "gnutls_handshake failed: %s (%d)\n",
+                               gnutls_strerror_name(err), err);
                /* Notify the peer about handshake failure via an alert. */
                gnutls_alert_send_appropriate(ctx->tls_session, err);
                if (handshake_cb) {
@@ -278,8 +279,8 @@ static int tls_handshake(struct tls_common_ctx *ctx, tls_handshake_cb handshake_
                const char *alert_name = gnutls_alert_get_name(gnutls_alert_get(ctx->tls_session));
                if (alert_name != NULL) {
                        struct sockaddr *peer = session_get_peer(session);
-                       kr_log_verbose("[%s] TLS alert from %s received: %s\n",
-                                      logstring, kr_straddr(peer), alert_name);
+                       VERBOSE_MSG(ctx->client_side, "TLS alert from %s received: %s\n",
+                                       kr_straddr(peer), alert_name);
                }
        }
        return kr_ok();
@@ -372,8 +373,7 @@ void tls_close(struct tls_common_ctx *ctx)
 
        if (ctx->handshake_state == TLS_HS_DONE) {
                const struct sockaddr *peer = session_get_peer(ctx->session);
-               kr_log_verbose("[%s] closing tls connection to `%s`\n",
-                              ctx->client_side ? "tls_client" : "tls",
+               VERBOSE_MSG(ctx->client_side, "closing tls connection to `%s`\n",
                               kr_straddr(peer));
                ctx->handshake_state = TLS_HS_CLOSING;
                gnutls_bye(ctx->tls_session, GNUTLS_SHUT_RDWR);
@@ -409,15 +409,14 @@ int tls_write(uv_write_t *req, uv_handle_t *handle, knot_pkt_t *pkt, uv_write_cb
                return kr_error(EINVAL);
 
        const uint16_t pkt_size = htons(pkt->size);
-       const char *logstring = tls_ctx->client_side ? client_logstring : server_logstring;
        gnutls_session_t tls_session = tls_ctx->tls_session;
 
        gnutls_record_cork(tls_session);
        ssize_t count = 0;
        if ((count = gnutls_record_send(tls_session, &pkt_size, sizeof(pkt_size)) < 0) ||
            (count = gnutls_record_send(tls_session, pkt->wire, pkt->size) < 0)) {
-               kr_log_verbose("[%s] gnutls_record_send failed: %s (%zd)\n",
-                              logstring, gnutls_strerror_name(count), count);
+               VERBOSE_MSG(tls_ctx->client_side, "gnutls_record_send failed: %s (%zd)\n",
+                               gnutls_strerror_name(count), count);
                return kr_error(EIO);
        }
 
@@ -428,15 +427,14 @@ int tls_write(uv_write_t *req, uv_handle_t *handle, knot_pkt_t *pkt, uv_write_cb
                if (!gnutls_error_is_fatal(ret)) {
                        return kr_error(EAGAIN);
                } else {
-                       kr_log_verbose("[%s] gnutls_record_uncork failed: %s (%d)\n",
-                                      logstring, gnutls_strerror_name(ret), ret);
+                       VERBOSE_MSG(tls_ctx->client_side, "gnutls_record_uncork failed: %s (%d)\n",
+                                       gnutls_strerror_name(ret), ret);
                        return kr_error(EIO);
                }
        }
 
        if (ret != submitted) {
-               kr_log_error(TLS, "[%s] gnutls_record_uncork didn't send all data (%d of %zd)\n",
-                            logstring, ret, submitted);
+               kr_log_error(TLS, "gnutls_record_uncork didn't send all data (%d of %zd)\n", ret, submitted);
                return kr_error(EIO);
        }
 
@@ -460,8 +458,6 @@ ssize_t tls_process_input_data(struct session *s, const uint8_t *buf, ssize_t nr
        if (kr_fails_assert(ok)) /* don't risk overflowing the buffer if we have a mistake somewhere */
                return kr_error(EINVAL);
 
-       const char *logstring = tls_p->client_side ? client_logstring : server_logstring;
-
        tls_p->buf = buf;
        tls_p->nread = nread >= 0 ? nread : 0;
        tls_p->consumed = 0;
@@ -494,8 +490,8 @@ ssize_t tls_process_input_data(struct session *s, const uint8_t *buf, ssize_t nr
                } else if (count == GNUTLS_E_REHANDSHAKE) {
                        /* See https://www.gnutls.org/manual/html_node/Re_002dauthentication.html */
                        struct sockaddr *peer = session_get_peer(s);
-                       kr_log_verbose("[%s] TLS rehandshake with %s has started\n",
-                                      logstring,  kr_straddr(peer));
+                       VERBOSE_MSG(tls_p->client_side, "TLS rehandshake with %s has started\n",
+                                       kr_straddr(peer));
                        tls_set_hs_state(tls_p, TLS_HS_IN_PROGRESS);
                        int err = kr_ok();
                        while (tls_p->handshake_state <= TLS_HS_IN_PROGRESS) {
@@ -513,13 +509,13 @@ ssize_t tls_process_input_data(struct session *s, const uint8_t *buf, ssize_t nr
                        /* There are can be data available, check it. */
                        continue;
                } else if (count < 0) {
-                       kr_log_verbose("[%s] gnutls_record_recv failed: %s (%zd)\n",
-                                    logstring, gnutls_strerror_name(count), count);
+                       VERBOSE_MSG(tls_p->client_side, "gnutls_record_recv failed: %s (%zd)\n",
+                                       gnutls_strerror_name(count), count);
                        return kr_error(EIO);
                } else if (count == 0) {
                        break;
                }
-               DEBUG_MSG("[%s] received %zd data\n", logstring, count);
+               DEBUG_MSG("[%s] received %zd data\n", tls_p->client_side ? "tls_client" : "tls", count);
                wire_buf += count;
                wire_buf_size -= count;
                submitted += count;
@@ -629,7 +625,7 @@ void tls_credentials_log_pins(struct tls_credentials *tls_credentials)
 #else
 void tls_credentials_log_pins(struct tls_credentials *tls_credentials)
 {
-       kr_log_verbose("[tls] could not calculate RFC 7858 OOB key-pin; GnuTLS 3.4.0+ required\n");
+       kr_log_debug(TLS, "could not calculate RFC 7858 OOB key-pin; GnuTLS 3.4.0+ required\n");
 }
 #endif
 
@@ -1082,9 +1078,9 @@ struct tls_client_ctx *tls_client_ctx_new(tls_client_param_t *entry,
        if (ret == GNUTLS_E_SUCCESS && entry->hostname) {
                ret = gnutls_server_name_set(ctx->c.tls_session, GNUTLS_NAME_DNS,
                                        entry->hostname, strlen(entry->hostname));
-               kr_log_verbose("[tls_client] set hostname, ret = %d\n", ret);
+               kr_log_debug(TLSCLIENT, "set hostname, ret = %d\n", ret);
        } else if (!entry->hostname) {
-               kr_log_verbose("[tls_client] no hostname\n");
+               kr_log_debug(TLSCLIENT, "no hostname\n");
        }
        if (ret != GNUTLS_E_SUCCESS) {
                tls_client_ctx_free(ctx);
@@ -1194,3 +1190,4 @@ int tls_client_ctx_set_session(struct tls_client_ctx *ctx, struct session *sessi
 }
 
 #undef DEBUG_MSG
+#undef VERBOSE_MSG

diff --git a/daemon/tls_session_ticket-srv.c b/daemon/tls_session_ticket-srv.c
index 49b36f67f52e30bae62ffe0cd0713498591ca360..b5aee95d762eaf38f55983884501b5d61ba464a0 100644 (file)
--- a/daemon/tls_session_ticket-srv.c
+++ b/daemon/tls_session_ticket-srv.c
@@ -190,7 +190,7 @@ static void tst_key_check(uv_timer_t *timer, bool force_update)
        /* ^ +1 because we don't want to wake up half a millisecond before the epoch! */
        if (kr_fails_assert(remain_ms < (TST_KEY_LIFETIME + 1 /*rounding tolerance*/) * 1000))
                return;
-       kr_log_verbose("[tls] session ticket: epoch %"PRIu64
+       kr_log_debug(TLS, "session ticket: epoch %"PRIu64
                        ", scheduling rotation check in %"PRIu64" ms\n",
                        (uint64_t)epoch, remain_ms);
        err = uv_timer_start(timer, &tst_timer_callback, remain_ms, 0);

diff --git a/daemon/worker.c b/daemon/worker.c
index 4647a8b7926610c167b1f1f8b36e94eed3dfde4c..a96e3a668bd6e479ac3e9284a65ce352f4c8708a 100644 (file)
--- a/daemon/worker.c
+++ b/daemon/worker.c
@@ -142,7 +142,7 @@ static uv_handle_t *ioreq_spawn(struct worker_ctx *worker,
        bool precond = (socktype == SOCK_DGRAM || socktype == SOCK_STREAM)
                        && (family == AF_INET  || family == AF_INET6);
        if (kr_fails_assert(precond)) {
-               kr_log_verbose("[work] ioreq_spawn: pre-condition failed\n");
+               kr_log_debug(WORKER, "ioreq_spawn: pre-condition failed\n");
                return NULL;
        }
 
@@ -316,7 +316,7 @@ static void free_wire(const struct request_ctx *ctx)
        uint32_t sent;
        int ret = knot_xdp_send(xhd->socket, &out, 1, &sent);
        kr_assert(ret == KNOT_EOK && sent == 0);
-       kr_log_verbose("[xdp] freed unsent buffer, ret = %d\n", ret);
+       kr_log_debug(XDP, "freed unsent buffer, ret = %d\n", ret);
 }
 #endif
 /* Helper functions for transport selection */
@@ -643,7 +643,7 @@ 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_verbose( "[wrkr]=> disconnected from '%s': %s\n",
+                               kr_log_debug(WORKER, "=> disconnected from '%s': %s\n",
                                                peer_str, uv_strerror(status));
                        }
                        worker_end_tcp(s);
@@ -868,9 +868,9 @@ static int session_tls_hs_cb(struct session *session, int status)
        tls_client_param_t *tls_params = tls_client_ctx->params;
        gnutls_session_t tls_session = tls_client_ctx->c.tls_session;
        if (gnutls_session_is_resumed(tls_session) != 0) {
-               kr_log_verbose("[tls_client] TLS session has resumed\n");
+               kr_log_debug(TLSCLIENT, "TLS session has resumed\n");
        } else {
-               kr_log_verbose("[tls_client] TLS session has not resumed\n");
+               kr_log_debug(TLSCLIENT, "TLS session has not resumed\n");
                /* session wasn't resumed, delete old session data ... */
                if (tls_params->session_data.data != NULL) {
                        gnutls_free(tls_params->session_data.data);
@@ -986,7 +986,7 @@ static void on_connect(uv_connect_t *req, int status)
                 * it's timeouted session. */
                if (VERBOSE_STATUS) {
                        const char *peer_str = kr_straddr(peer);
-                       kr_log_verbose( "[wrkr]=> connected to '%s', but session "
+                       kr_log_debug(WORKER, "=> connected to '%s', but session "
                                        "is already timeouted, close\n",
                                        peer_str ? peer_str : "");
                }
@@ -1003,7 +1003,7 @@ static void on_connect(uv_connect_t *req, int status)
                 * to reconnect to upstream after unsuccessful attempt. */
                if (VERBOSE_STATUS) {
                        const char *peer_str = kr_straddr(peer);
-                       kr_log_verbose( "[wrkr]=> connected to '%s', but peer "
+                       kr_log_debug(WORKER, "=> connected to '%s', but peer "
                                        "is already connected, close\n",
                                        peer_str ? peer_str : "");
                }
@@ -1016,7 +1016,7 @@ static void on_connect(uv_connect_t *req, int status)
        if (status != 0) {
                if (VERBOSE_STATUS) {
                        const char *peer_str = kr_straddr(peer);
-                       kr_log_verbose( "[wrkr]=> connection to '%s' failed (%s), flagged as 'bad'\n",
+                       kr_log_debug(WORKER, "=> connection to '%s' failed (%s), flagged as 'bad'\n",
                                        peer_str ? peer_str : "", uv_strerror(status));
                }
                worker_del_tcp_waiting(worker, peer);
@@ -1049,7 +1049,7 @@ static void on_connect(uv_connect_t *req, int status)
 
        if (VERBOSE_STATUS) {
                const char *peer_str = kr_straddr(peer);
-               kr_log_verbose( "[wrkr]=> connected to '%s'\n", peer_str ? peer_str : "");
+               kr_log_debug(WORKER, "=> connected to '%s'\n", peer_str ? peer_str : "");
        }
 
        session_flags(session)->connected = true;
@@ -1308,7 +1308,7 @@ static int xdp_push(struct qr_task *task, const uv_handle_t *src_handle)
        ctx->req.answer->wire = NULL; /* it's been freed */
 
        uv_idle_start(&xhd->tx_waker, xdp_tx_waker);
-       kr_log_verbose("[xdp] pushed a packet, ret = %d\n", ret);
+       kr_log_debug(XDP, "pushed a packet, ret = %d\n", ret);
 
        return qr_task_on_send(task, src_handle, ret);
 #else

diff --git a/lib/cache/api.c b/lib/cache/api.c
index 34c99f57ed269dde869f4e09fbe85bea941e48c9..1c64094e63688eeca04d8fc899076d1bbabbfb34 100644 (file)
--- a/lib/cache/api.c
+++ b/lib/cache/api.c
@@ -83,13 +83,13 @@ static int assert_right_version(struct kr_cache *cache)
                if (ret != 0) { /* Log for non-empty cache to limit noise on fresh start. */
                        kr_log_info(CACHE, "incompatible cache database detected, purging\n");
                        if (oldret) {
-                               kr_log_verbose("[cache] reading version returned: %d\n", oldret);
+                               kr_log_debug(CACHE, "reading version returned: %d\n", oldret);
                        } else if (val.len != sizeof(CACHE_VERSION)) {
-                               kr_log_verbose("[cache] version has bad length: %d\n", (int)val.len);
+                               kr_log_debug(CACHE, "version has bad length: %d\n", (int)val.len);
                        } else {
                                uint16_t ver;
                                memcpy(&ver, val.data, sizeof(ver));
-                               kr_log_verbose("[cache] version has bad value: %d instead of %d\n",
+                               kr_log_debug(CACHE, "version has bad value: %d instead of %d\n",
                                        (int)ver, (int)CACHE_VERSION);
                        }
                }

diff --git a/lib/cache/cdb_lmdb.c b/lib/cache/cdb_lmdb.c
index ab36dbe68ad145d22f111ed192528aa0956f68a6..5bf226a89987a045641d4f1a5b24d5adb9d2773e 100644 (file)
--- a/lib/cache/cdb_lmdb.c
+++ b/lib/cache/cdb_lmdb.c
@@ -486,7 +486,7 @@ static int cdb_check_health(kr_cdb_pt db, struct kr_cdb_stats *stats)
        }
 
        if (st.st_dev != env->st_dev || st.st_ino != env->st_ino) {
-               kr_log_verbose("[cache] cache file has been replaced, reopening\n");
+               kr_log_debug(CACHE, "cache file has been replaced, reopening\n");
                int ret = reopen_env(env, stats, 0); // we accept mapsize from the new file
                return ret == 0 ? 1 : ret;
        }
@@ -598,7 +598,7 @@ static int cdb_clear(kr_cdb_pt db, struct kr_cdb_stats *stats)
                        ret = kr_ok();
                // else pass some other error
        } else {
-               kr_log_verbose("[cache] clear: identical files, unlinking\n");
+               kr_log_debug(CACHE, "clear: identical files, unlinking\n");
                // coverity[toctou]
                unlink(env->mdb_data_path);
                unlink(mdb_lockfile);

diff --git a/lib/cache/nsec1.c b/lib/cache/nsec1.c
index f6bf7275804c4e5cc01db102a1743f504dbace15..ccf282c55844c000e7de601d166befd4ff0c77b7 100644 (file)
--- a/lib/cache/nsec1.c
+++ b/lib/cache/nsec1.c
@@ -66,7 +66,7 @@ knot_db_val_t key_NSEC1(struct key *k, const knot_dname_t *name, bool add_wildca
        /*
        VERBOSE_MSG(NULL, "<> key_NSEC1; name: ");
        kr_dname_print(name, add_wildcard ? "*." : "" , " ");
-       kr_log_verbose("(zone name LF length: %d; total key length: %d)\n",
+       kr_log_debug(CACHE, "(zone name LF length: %d; total key length: %d)\n",
                        k->zlf_len, key_len);
        */
 

diff --git a/lib/log.c b/lib/log.c
index 702dfd34e119e1012b64f3bdd7fcd9ba0c664690..3d8482d551f36d27d0bdf063f1a713740c23b242 100644 (file)
--- a/lib/log.c
+++ b/lib/log.c
@@ -60,6 +60,8 @@ log_group_names_t log_group_names[] = {
        GRP_NAME_ITEM(LOG_GRP_PRIMING),
        GRP_NAME_ITEM(LOG_GRP_SRVSTALE),
        GRP_NAME_ITEM(LOG_GRP_WATCHDOG),
+       GRP_NAME_ITEM(LOG_GRP_NSID),
+       GRP_NAME_ITEM(LOG_GRP_DNSTAP),
        GRP_NAME_ITEM(LOG_GRP_TESTS),
        { NULL,         -1 },
 };

diff --git a/lib/log.h b/lib/log.h
index c43f53f304199cc5e92e6dfc1a6e7f0894e9778c..cbbd585a512eaedee7f3e9825201f9803789d737 100644 (file)
--- a/lib/log.h
+++ b/lib/log.h
@@ -66,6 +66,8 @@ enum kr_log_groups_type {
        LOG_GRP_PRIMING,
        LOG_GRP_SRVSTALE,
        LOG_GRP_WATCHDOG,
+       LOG_GRP_NSID,
+       LOG_GRP_DNSTAP,
        LOG_GRP_TESTS,
 };
 
@@ -106,6 +108,8 @@ enum kr_log_groups_type {
 #define LOG_GRP_PRIMING_TAG            "primin"
 #define LOG_GRP_SRVSTALE_TAG           "srvstl"
 #define LOG_GRP_WATCHDOG_TAG           "wtchdg"
+#define LOG_GRP_NSID_TAG               "nsid  "
+#define LOG_GRP_DNSTAP_TAG             "dnstap"
 #define LOG_GRP_TESTS_TAG              "tests "
 
 KR_EXPORT
@@ -220,4 +224,4 @@ void kr_log_q1(const struct kr_query *qry, log_groups_t group, const char *tag,
 /** 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/modules/dnstap/dnstap.c b/modules/dnstap/dnstap.c
index f813653b0d3843059b1f54f3e33360f7beedd039..1182a3ce2358e7bef48463e9fe8f972509bf0c7d 100644 (file)
--- a/modules/dnstap/dnstap.c
+++ b/modules/dnstap/dnstap.c
@@ -21,7 +21,7 @@
 #include <sys/socket.h>
 #include <uv.h>
 
-#define DEBUG_MSG(fmt, ...) kr_log_verbose("[dnstap] " fmt, ##__VA_ARGS__);
+#define DEBUG_MSG(fmt, ...) kr_log_debug(DNSTAP, fmt, ##__VA_ARGS__);
 #define CFG_SOCK_PATH "socket_path"
 #define CFG_IDENTITY_STRING "identity"
 #define CFG_VERSION_STRING "version"

diff --git a/modules/nsid/nsid.c b/modules/nsid/nsid.c
index c0eabfdc487f4c9f2bba89915784423c9a55674f..09f6d39ef7c6536edd7421b98e6c887fca1924f2 100644 (file)
--- a/modules/nsid/nsid.c
+++ b/modules/nsid/nsid.c
@@ -38,7 +38,7 @@ static int nsid_finalize(kr_layer_t *ctx) {
        /* Check violation of https://tools.ietf.org/html/rfc5001#section-2.1:
         * The resolver MUST NOT include any NSID payload data in the query */
        if (knot_edns_opt_get_length(req_nsid) != 0)
-               kr_log_verbose("[%05u.  ][nsid] FORMERR: NSID option in query "
+               kr_log_debug(NSID, "[%05u.  ] FORMERR: NSID option in query "
                               "must not contain payload, continuing\n", req->uid);
                /* FIXME: actually change RCODE in answer to FORMERR? */
 
@@ -50,7 +50,7 @@ static int nsid_finalize(kr_layer_t *ctx) {
                                 config->local_nsid_len, config->local_nsid,
                                 &req->pool) != KNOT_EOK) {
                /* something went wrong and there is no way to salvage content of OPT RRset */
-               kr_log_verbose("[%05u.  ][nsid] unable to add NSID option\n", req->uid);
+               kr_log_debug(NSID, "[%05u.  ] unable to add NSID option\n", req->uid);
                knot_rrset_clear(req->answer->opt_rr, &req->pool);
        }
 

diff --git a/utils/cache_gc/db.c b/utils/cache_gc/db.c
index 3b4a75be5e52399f779947691a41a18a6cdf7cab..923da87a58f0f7599ed278ad05be265cc5c30c36 100644 (file)
--- a/utils/cache_gc/db.c
+++ b/utils/cache_gc/db.c
@@ -274,7 +274,7 @@ int kr_gc_cache_iter(knot_db_t * knot_db, const  kr_cache_gc_cfg_t *cfg,
 
        api->txn_abort(&txn);
 
-       kr_log_verbose("DEBUG: iterated %u items, gc consistent %u, kr consistent %u\n",
+       kr_log_debug(CACHE, "iterated %u items, gc consistent %u, kr consistent %u\n",
                counter_iter, counter_gc_consistent, counter_kr_consistent);
        return KNOT_EOK;
 }

diff --git a/utils/cache_gc/kr_cache_gc.c b/utils/cache_gc/kr_cache_gc.c
index 758a6e9a4f537828e7f21522d27d8b04a26f76d4..d89352e877f0dafaaa50fc6fcba3b954c2616de3 100644 (file)
--- a/utils/cache_gc/kr_cache_gc.c
+++ b/utils/cache_gc/kr_cache_gc.c
@@ -229,7 +229,7 @@ int kr_cache_gc(kr_cache_gc_cfg_t *cfg, kr_cache_gc_state_t **state)
        /* use less precise variant to avoid 32-bit overflow */
        ssize_t amount_tofree = cats_sumsize / 100 * cfg->cache_to_be_freed;
 
-       kr_log_verbose("tofree: %zd / %zd\n", amount_tofree, cats_sumsize);
+       kr_log_debug(CACHE, "tofree: %zd / %zd\n", amount_tofree, cats_sumsize);
        if (VERBOSE_STATUS) {
                for (int i = 0; i < CATEGORIES; i++) {
                        if (cats.categories_sizes[i] > 0) {