From: Ondřej Surý Date: Wed, 7 Dec 2022 08:45:34 +0000 (+0100) Subject: Add internal logging functions to the netmgr X-Git-Tag: v9.19.9~79^2 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=52307f8116879774989ae524fa2545e99c71853f;p=thirdparty%2Fbind9.git 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 7b1d6f7ece6..cf04ac3d466 100644 --- 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 4271990bffd..d467b81d041 100644 --- 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 d7dc2334095..9563f27ef7c 100644 --- 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 bd3da5235cb..52e5abac16b 100644 --- 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 f672c51532b..9024d9422cf 100644 --- 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 0da0dfe7f1a..c857eb15ada 100644 --- 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 61fc304a8af..a1e59b54add 100644 --- 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); }