Add internal logging functions to the netmgr

Add internal logging functions isc__netmgr_log, isc__nmsocket_log(), and
isc__nmhandle_log() that can be used to add logging messages to the
netmgr, and change all direct use of isc_log_write() to use those
logging functions to properly prefix them with netmgr, nmsocket and
nmsocket+nmhandle.

diff --git a/lib/isc/netmgr/http.c b/lib/isc/netmgr/http.c
index 7b1d6f7ece66abeed33b7ba177c98373c402da06..cf04ac3d46649e8d49d11d2fd07a04884a0986cc 100644 (file)
--- a/lib/isc/netmgr/http.c
+++ b/lib/isc/netmgr/http.c
@@ -2003,10 +2003,10 @@ log_server_error_response(const isc_nmsocket_t *socket,
        local_addr = isc_nmhandle_localaddr(socket->h2.session->handle);
        isc_sockaddr_format(&client_addr, client_sabuf, sizeof(client_sabuf));
        isc_sockaddr_format(&local_addr, local_sabuf, sizeof(local_sabuf));
-       isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, ISC_LOGMODULE_NETMGR,
-                     log_level, "HTTP/2 request from %s (on %s) failed: %s %s",
-                     client_sabuf, local_sabuf, response->header.value,
-                     response->desc);
+       isc__nmsocket_log(socket, log_level,
+                         "HTTP/2 request from %s (on %s) failed: %s %s",
+                         client_sabuf, local_sabuf, response->header.value,
+                         response->desc);
 }
 
 static isc_result_t

diff --git a/lib/isc/netmgr/netmgr-int.h b/lib/isc/netmgr/netmgr-int.h
index 4271990bffdc068fff276eb75a51b9f4f71890cf..d467b81d0417bf90b9fc44d7ba274536136b6a6e 100644 (file)
--- a/lib/isc/netmgr/netmgr-int.h
+++ b/lib/isc/netmgr/netmgr-int.h
@@ -1956,7 +1956,8 @@ void
 isc__nm_failed_read_cb(isc_nmsocket_t *sock, isc_result_t result, bool async);
 
 void
-isc__nm_accept_connection_log(isc_result_t result, bool can_log_quota);
+isc__nm_accept_connection_log(isc_nmsocket_t *sock, isc_result_t result,
+                             bool can_log_quota);
 
 /*
  * Timeout callbacks
@@ -1982,3 +1983,16 @@ isc__nm_tcp_freebind(uv_tcp_t *handle, const struct sockaddr *addr,
 
 void
 isc__nmsocket_log_tls_session_reuse(isc_nmsocket_t *sock, isc_tls_t *tls);
+
+/*
+ * Logging helpers
+ */
+void
+isc__netmgr_log(const isc_nm_t *netmgr, int level, const char *fmt, ...)
+       ISC_FORMAT_PRINTF(3, 4);
+void
+isc__nmsocket_log(const isc_nmsocket_t *sock, int level, const char *fmt, ...)
+       ISC_FORMAT_PRINTF(3, 4);
+void
+isc__nmhandle_log(const isc_nmhandle_t *handle, int level, const char *fmt, ...)
+       ISC_FORMAT_PRINTF(3, 4);

diff --git a/lib/isc/netmgr/netmgr.c b/lib/isc/netmgr/netmgr.c
index d7dc2334095e9788a5f60b0a4c3b4d0ac84dc7b2..9563f27ef7c9fac572cff3497ac79810864af65a 100644 (file)
--- a/lib/isc/netmgr/netmgr.c
+++ b/lib/isc/netmgr/netmgr.c
@@ -158,10 +158,9 @@ networker_teardown(void *arg) {
 
        worker->shuttingdown = true;
 
-       isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, ISC_LOGMODULE_NETMGR,
-                     ISC_LOG_DEBUG(1),
-                     "Shutting down network manager worker on loop %p(%d)",
-                     loop, isc_tid());
+       isc__netmgr_log(worker->netmgr, ISC_LOG_DEBUG(1),
+                       "Shutting down network manager worker on loop %p(%d)",
+                       loop, isc_tid());
 
        uv_walk(&loop->loop, shutdown_walk_cb, NULL);
 
@@ -175,9 +174,8 @@ netmgr_teardown(void *arg) {
        if (atomic_compare_exchange_strong(&netmgr->shuttingdown,
                                           &(bool){ false }, true))
        {
-               isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL,
-                             ISC_LOGMODULE_NETMGR, ISC_LOG_DEBUG(1),
-                             "Shutting down network manager");
+               isc__netmgr_log(netmgr, ISC_LOG_DEBUG(1),
+                               "Shutting down network manager");
        }
 }
 
@@ -1359,10 +1357,9 @@ isc__nm_failed_accept_cb(isc_nmsocket_t *sock, isc_result_t eresult) {
                /* IGNORE: The client disconnected before we could accept */
                break;
        default:
-               isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL,
-                             ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR,
-                             "Accepting TCP connection failed: %s",
-                             isc_result_totext(eresult));
+               isc__nmsocket_log(sock, ISC_LOG_ERROR,
+                                 "Accepting TCP connection failed: %s",
+                                 isc_result_totext(eresult));
        }
 }
 
@@ -1443,7 +1440,8 @@ isc__nmsocket_connecttimeout_cb(uv_timer_t *timer) {
 }
 
 void
-isc__nm_accept_connection_log(isc_result_t result, bool can_log_quota) {
+isc__nm_accept_connection_log(isc_nmsocket_t *sock, isc_result_t result,
+                             bool can_log_quota) {
        int level;
 
        switch (result) {
@@ -1464,9 +1462,8 @@ isc__nm_accept_connection_log(isc_result_t result, bool can_log_quota) {
                level = ISC_LOG_ERROR;
        }
 
-       isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, ISC_LOGMODULE_NETMGR,
-                     level, "Accepting TCP connection failed: %s",
-                     isc_result_totext(result));
+       isc__nmsocket_log(sock, level, "Accepting TCP connection failed: %s",
+                         isc_result_totext(result));
 }
 
 void
@@ -2791,11 +2788,10 @@ isc__nmsocket_log_tls_session_reuse(isc_nmsocket_t *sock, isc_tls_t *tls) {
 
        isc_sockaddr_format(&sock->peer, client_sabuf, sizeof(client_sabuf));
        isc_sockaddr_format(&sock->iface, local_sabuf, sizeof(local_sabuf));
-       isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, ISC_LOGMODULE_NETMGR,
-                     log_level, "TLS %s session %s for %s on %s",
-                     SSL_is_server(tls) ? "server" : "client",
-                     SSL_session_reused(tls) ? "resumed" : "created",
-                     client_sabuf, local_sabuf);
+       isc__nmsocket_log(sock, log_level, "TLS %s session %s for %s on %s",
+                         SSL_is_server(tls) ? "server" : "client",
+                         SSL_session_reused(tls) ? "resumed" : "created",
+                         client_sabuf, local_sabuf);
 }
 
 static void
@@ -2803,10 +2799,9 @@ isc__networker_destroy(isc__networker_t *worker) {
        isc_nm_t *netmgr = worker->netmgr;
        worker->netmgr = NULL;
 
-       isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, ISC_LOGMODULE_NETMGR,
-                     ISC_LOG_DEBUG(1),
-                     "Destroying down network manager worker on loop %p(%d)",
-                     worker->loop, isc_tid());
+       isc__netmgr_log(netmgr, ISC_LOG_DEBUG(1),
+                       "Destroying down network manager worker on loop %p(%d)",
+                       worker->loop, isc_tid());
 
        isc_loop_detach(&worker->loop);
 
@@ -2818,6 +2813,57 @@ isc__networker_destroy(isc__networker_t *worker) {
 
 ISC_REFCOUNT_IMPL(isc__networker, isc__networker_destroy);
 
+void
+isc__netmgr_log(const isc_nm_t *netmgr, int level, const char *fmt, ...) {
+       char msgbuf[2048];
+       va_list ap;
+
+       if (!isc_log_wouldlog(isc_lctx, level)) {
+               return;
+       }
+
+       va_start(ap, fmt);
+       vsnprintf(msgbuf, sizeof(msgbuf), fmt, ap);
+       va_end(ap);
+
+       isc_log_write(isc_lctx, ISC_LOGCATEGORY_DEFAULT, ISC_LOGMODULE_NETMGR,
+                     level, "netmgr %p: %s", netmgr, msgbuf);
+}
+
+void
+isc__nmsocket_log(const isc_nmsocket_t *sock, int level, const char *fmt, ...) {
+       char msgbuf[2048];
+       va_list ap;
+
+       if (!isc_log_wouldlog(isc_lctx, level)) {
+               return;
+       }
+
+       va_start(ap, fmt);
+       vsnprintf(msgbuf, sizeof(msgbuf), fmt, ap);
+       va_end(ap);
+
+       isc_log_write(isc_lctx, ISC_LOGCATEGORY_DEFAULT, ISC_LOGMODULE_NETMGR,
+                     level, "socket %p: %s", sock, msgbuf);
+}
+
+void
+isc__nmhandle_log(const isc_nmhandle_t *handle, int level, const char *fmt,
+                 ...) {
+       char msgbuf[2048];
+       va_list ap;
+
+       if (!isc_log_wouldlog(isc_lctx, level)) {
+               return;
+       }
+
+       va_start(ap, fmt);
+       vsnprintf(msgbuf, sizeof(msgbuf), fmt, ap);
+       va_end(ap);
+
+       isc__nmsocket_log(handle->sock, level, "handle %p: %s", handle, msgbuf);
+}
+
 #ifdef NETMGR_TRACE
 /*
  * Dump all active sockets in netmgr. We output to stderr

diff --git a/lib/isc/netmgr/tcp.c b/lib/isc/netmgr/tcp.c
index bd3da5235cb348e758cf1d6c3b492e36189c2e8f..52e5abac16b82501f5c6ccbb188305d8fed19413 100644 (file)
--- a/lib/isc/netmgr/tcp.c
+++ b/lib/isc/netmgr/tcp.c
@@ -100,10 +100,9 @@ failed_accept_cb(isc_nmsocket_t *sock, isc_result_t eresult) {
                /* IGNORE: The client disconnected before we could accept */
                break;
        default:
-               isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL,
-                             ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR,
-                             "Accepting TCP connection failed: %s",
-                             isc_result_totext(eresult));
+               isc__nmsocket_log(sock, ISC_LOG_ERROR,
+                                 "Accepting TCP connection failed: %s",
+                                 isc_result_totext(eresult));
        }
 }
 
@@ -532,10 +531,8 @@ isc__nm_async_tcplisten(isc__networker_t *worker, isc__netievent_t *ev0) {
        r = uv_listen((uv_stream_t *)&sock->uv_handle.tcp, sock->backlog,
                      tcp_connection_cb);
        if (r != 0) {
-               isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL,
-                             ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR,
-                             "uv_listen failed: %s",
-                             isc_result_totext(isc_uverr2result(r)));
+               isc__nmsocket_log(sock, ISC_LOG_ERROR, "uv_listen failed: %s",
+                                 isc_result_totext(isc_uverr2result(r)));
                isc__nm_incstats(sock, STATID_BINDFAIL);
                goto done;
        }
@@ -592,7 +589,7 @@ tcp_connection_cb(uv_stream_t *server, int status) {
 
        result = accept_connection(ssock, quota);
 done:
-       isc__nm_accept_connection_log(result, can_log_tcp_quota());
+       isc__nm_accept_connection_log(ssock, result, can_log_tcp_quota());
 }
 
 static void
@@ -883,7 +880,7 @@ isc__nm_async_tcpaccept(isc__networker_t *worker, isc__netievent_t *ev0) {
        REQUIRE(sock->tid == isc_tid());
 
        result = accept_connection(sock, ievent->quota);
-       isc__nm_accept_connection_log(result, can_log_tcp_quota());
+       isc__nm_accept_connection_log(sock, result, can_log_tcp_quota());
 }
 
 static isc_result_t

diff --git a/lib/isc/netmgr/tcpdns.c b/lib/isc/netmgr/tcpdns.c
index f672c51532b397f65b33a678ebe15bcd8cd60fee..9024d9422cf39538b35e7f0bc2654aa77cd80acf 100644 (file)
--- a/lib/isc/netmgr/tcpdns.c
+++ b/lib/isc/netmgr/tcpdns.c
@@ -527,10 +527,8 @@ isc__nm_async_tcpdnslisten(isc__networker_t *worker, isc__netievent_t *ev0) {
        r = uv_listen((uv_stream_t *)&sock->uv_handle.tcp, sock->backlog,
                      tcpdns_connection_cb);
        if (r != 0) {
-               isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL,
-                             ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR,
-                             "uv_listen failed: %s",
-                             isc_result_totext(isc_uverr2result(r)));
+               isc__nmsocket_log(sock, ISC_LOG_ERROR, "uv_listen failed: %s",
+                                 isc_result_totext(isc_uverr2result(r)));
                isc__nm_incstats(sock, STATID_BINDFAIL);
                goto done;
        }
@@ -587,7 +585,7 @@ tcpdns_connection_cb(uv_stream_t *server, int status) {
 
        result = accept_connection(ssock, quota);
 done:
-       isc__nm_accept_connection_log(result, can_log_tcpdns_quota());
+       isc__nm_accept_connection_log(ssock, result, can_log_tcpdns_quota());
 }
 
 static void
@@ -959,7 +957,8 @@ isc__nm_async_tcpdnsaccept(isc__networker_t *worker, isc__netievent_t *ev0) {
        REQUIRE(ievent->sock->tid == isc_tid());
 
        result = accept_connection(ievent->sock, ievent->quota);
-       isc__nm_accept_connection_log(result, can_log_tcpdns_quota());
+       isc__nm_accept_connection_log(ievent->sock, result,
+                                     can_log_tcpdns_quota());
 }
 
 static isc_result_t

diff --git a/lib/isc/netmgr/tlsdns.c b/lib/isc/netmgr/tlsdns.c
index 0da0dfe7f1a59eb1f7f19e95e2ba011a056eb810..c857eb15ada79e432d0ffb047ecef6de63aebd1f 100644 (file)
--- a/lib/isc/netmgr/tlsdns.c
+++ b/lib/isc/netmgr/tlsdns.c
@@ -641,10 +641,8 @@ isc__nm_async_tlsdnslisten(isc__networker_t *worker, isc__netievent_t *ev0) {
        r = uv_listen((uv_stream_t *)&sock->uv_handle.tcp, sock->backlog,
                      tlsdns_connection_cb);
        if (r != 0) {
-               isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL,
-                             ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR,
-                             "uv_listen failed: %s",
-                             isc_result_totext(isc_uverr2result(r)));
+               isc__nmsocket_log(sock, ISC_LOG_ERROR, "uv_listen failed: %s",
+                                 isc_result_totext(isc_uverr2result(r)));
                isc__nm_incstats(sock, STATID_BINDFAIL);
                goto done;
        }
@@ -701,7 +699,7 @@ tlsdns_connection_cb(uv_stream_t *server, int status) {
 
        result = accept_connection(ssock, quota);
 done:
-       isc__nm_accept_connection_log(result, can_log_tlsdns_quota());
+       isc__nm_accept_connection_log(ssock, result, can_log_tlsdns_quota());
 }
 
 static void
@@ -1583,7 +1581,8 @@ isc__nm_async_tlsdnsaccept(isc__networker_t *worker, isc__netievent_t *ev0) {
        REQUIRE(ievent->sock->tid == isc_tid());
 
        result = accept_connection(ievent->sock, ievent->quota);
-       isc__nm_accept_connection_log(result, can_log_tlsdns_quota());
+       isc__nm_accept_connection_log(ievent->sock, result,
+                                     can_log_tlsdns_quota());
 }
 
 static isc_result_t

diff --git a/lib/isc/netmgr/tlsstream.c b/lib/isc/netmgr/tlsstream.c
index 61fc304a8afbb468aae1887257dd4cc0cccd921e..a1e59b54add1186495bc485415a2c8f2f33ed8cc 100644 (file)
--- a/lib/isc/netmgr/tlsstream.c
+++ b/lib/isc/netmgr/tlsstream.c
@@ -642,13 +642,12 @@ tls_do_bio(isc_nmsocket_t *sock, isc_region_t *received_data,
 
 error:
 #if defined(NETMGR_TRACE) && defined(NETMGR_TRACE_VERBOSE)
-       isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, ISC_LOGMODULE_NETMGR,
-                     ISC_LOG_NOTICE,
-                     "SSL error in BIO: %d %s (errno: %d). Arguments: "
-                     "received_data: %p, "
-                     "send_data: %p, finish: %s",
-                     tls_status, isc_result_totext(result), saved_errno,
-                     received_data, send_data, finish ? "true" : "false");
+       isc__nmsocket_log(sock, ISC_LOG_NOTICE,
+                         "SSL error in BIO: %d %s (errno: %d). Arguments: "
+                         "received_data: %p, "
+                         "send_data: %p, finish: %s",
+                         tls_status, isc_result_totext(result), saved_errno,
+                         received_data, send_data, finish ? "true" : "false");
 #endif
        tls_failed_read_cb(sock, result);
 }