From 20ac73eb222e60395399b467b0a72015a4dd8845 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Sur=C3=BD?= Date: Wed, 1 Dec 2021 17:41:20 +0100 Subject: [PATCH 1/2] Improve the logging on failed TCP accept Previously, when TCP accept failed, we have logged a message with ISC_LOG_ERROR level. One common case, how this could happen is that the client hits TCP client quota and is put on hold and when resumed, the client has already given up and closed the TCP connection. In such case, the named would log: TCP connection failed: socket is not connected This message was quite confusing because it actually doesn't say that it's related to the accepting the TCP connection and also it logs everything on the ISC_LOG_ERROR level. Change the log message to "Accepting TCP connection failed" and for specific error states lower the severity of the log message to ISC_LOG_INFO. --- lib/isc/netmgr/netmgr-int.h | 3 +++ lib/isc/netmgr/netmgr.c | 27 +++++++++++++++++++++++++++ lib/isc/netmgr/tcp.c | 20 ++------------------ lib/isc/netmgr/tcpdns.c | 22 ++-------------------- lib/isc/netmgr/tlsdns.c | 22 ++-------------------- 5 files changed, 36 insertions(+), 58 deletions(-) diff --git a/lib/isc/netmgr/netmgr-int.h b/lib/isc/netmgr/netmgr-int.h index da892b8415..db5c247118 100644 --- a/lib/isc/netmgr/netmgr-int.h +++ b/lib/isc/netmgr/netmgr-int.h @@ -2034,4 +2034,7 @@ isc__nm_failed_read_cb(isc_nmsocket_t *sock, isc_result_t result, bool async); void isc__nmsocket_connecttimeout_cb(uv_timer_t *timer); +void +isc__nm_accept_connection_log(isc_result_t result, bool can_log_quota); + #define STREAM_CLIENTS_PER_CONN 23 diff --git a/lib/isc/netmgr/netmgr.c b/lib/isc/netmgr/netmgr.c index 3404d19ba0..13168683e1 100644 --- a/lib/isc/netmgr/netmgr.c +++ b/lib/isc/netmgr/netmgr.c @@ -2048,6 +2048,33 @@ isc__nmsocket_connecttimeout_cb(uv_timer_t *timer) { } } +void +isc__nm_accept_connection_log(isc_result_t result, bool can_log_quota) { + int level; + + switch (result) { + case ISC_R_SUCCESS: + case ISC_R_NOCONN: + return; + case ISC_R_QUOTA: + case ISC_R_SOFTQUOTA: + if (!can_log_quota) { + return; + } + level = ISC_LOG_INFO; + break; + case ISC_R_NOTCONNECTED: + level = ISC_LOG_INFO; + break; + default: + 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)); +} + static void isc__nmsocket_readtimeout_cb(uv_timer_t *timer) { isc_nmsocket_t *sock = uv_handle_get_data((uv_handle_t *)timer); diff --git a/lib/isc/netmgr/tcp.c b/lib/isc/netmgr/tcp.c index 382018944e..eb6437d8d4 100644 --- a/lib/isc/netmgr/tcp.c +++ b/lib/isc/netmgr/tcp.c @@ -631,15 +631,7 @@ tcp_connection_cb(uv_stream_t *server, int status) { result = accept_connection(ssock, quota); done: - if (result != ISC_R_SUCCESS && result != ISC_R_NOCONN) { - if ((result != ISC_R_QUOTA && result != ISC_R_SOFTQUOTA) || - can_log_tcp_quota()) { - isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, - ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR, - "TCP connection failed: %s", - isc_result_totext(result)); - } - } + isc__nm_accept_connection_log(result, can_log_tcp_quota()); } void @@ -931,15 +923,7 @@ isc__nm_async_tcpaccept(isc__networker_t *worker, isc__netievent_t *ev0) { REQUIRE(sock->tid == isc_nm_tid()); result = accept_connection(sock, ievent->quota); - if (result != ISC_R_SUCCESS && result != ISC_R_NOCONN) { - if ((result != ISC_R_QUOTA && result != ISC_R_SOFTQUOTA) || - can_log_tcp_quota()) { - isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, - ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR, - "TCP connection failed: %s", - isc_result_totext(result)); - } - } + isc__nm_accept_connection_log(result, can_log_tcp_quota()); } static isc_result_t diff --git a/lib/isc/netmgr/tcpdns.c b/lib/isc/netmgr/tcpdns.c index 5fed46018f..9167e52bb5 100644 --- a/lib/isc/netmgr/tcpdns.c +++ b/lib/isc/netmgr/tcpdns.c @@ -600,16 +600,7 @@ tcpdns_connection_cb(uv_stream_t *server, int status) { result = accept_connection(ssock, quota); done: - if (result != ISC_R_SUCCESS && result != ISC_R_NOCONN) { - if ((result != ISC_R_QUOTA && result != ISC_R_SOFTQUOTA) || - can_log_tcpdns_quota()) - { - isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, - ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR, - "TCP connection failed: %s", - isc_result_totext(result)); - } - } + isc__nm_accept_connection_log(result, can_log_tcpdns_quota()); } void @@ -920,16 +911,7 @@ isc__nm_async_tcpdnsaccept(isc__networker_t *worker, isc__netievent_t *ev0) { REQUIRE(ievent->sock->tid == isc_nm_tid()); result = accept_connection(ievent->sock, ievent->quota); - if (result != ISC_R_SUCCESS && result != ISC_R_NOCONN) { - if ((result != ISC_R_QUOTA && result != ISC_R_SOFTQUOTA) || - can_log_tcpdns_quota()) - { - isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, - ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR, - "TCP connection failed: %s", - isc_result_totext(result)); - } - } + isc__nm_accept_connection_log(result, can_log_tcpdns_quota()); } static isc_result_t diff --git a/lib/isc/netmgr/tlsdns.c b/lib/isc/netmgr/tlsdns.c index 700874d28e..137a1709cd 100644 --- a/lib/isc/netmgr/tlsdns.c +++ b/lib/isc/netmgr/tlsdns.c @@ -675,16 +675,7 @@ tlsdns_connection_cb(uv_stream_t *server, int status) { result = accept_connection(ssock, quota); done: - if (result != ISC_R_SUCCESS && result != ISC_R_NOCONN) { - if ((result != ISC_R_QUOTA && result != ISC_R_SOFTQUOTA) || - can_log_tlsdns_quota()) - { - isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, - ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR, - "TCP connection failed: %s", - isc_result_totext(result)); - } - } + isc__nm_accept_connection_log(result, can_log_tlsdns_quota()); } void @@ -1425,16 +1416,7 @@ isc__nm_async_tlsdnsaccept(isc__networker_t *worker, isc__netievent_t *ev0) { REQUIRE(ievent->sock->tid == isc_nm_tid()); result = accept_connection(ievent->sock, ievent->quota); - if (result != ISC_R_SUCCESS && result != ISC_R_NOCONN) { - if ((result != ISC_R_QUOTA && result != ISC_R_SOFTQUOTA) || - can_log_tlsdns_quota()) - { - isc_log_write(isc_lctx, ISC_LOGCATEGORY_GENERAL, - ISC_LOGMODULE_NETMGR, ISC_LOG_ERROR, - "TCP connection failed: %s", - isc_result_totext(result)); - } - } + isc__nm_accept_connection_log(result, can_log_tlsdns_quota()); } static isc_result_t From 9d53471890bedf2b602daa06362a95b60a675f44 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Sur=C3=BD?= Date: Wed, 1 Dec 2021 17:52:33 +0100 Subject: [PATCH 2/2] Add CHANGES and release note for [GL #2700] --- CHANGES | 6 ++++++ doc/notes/notes-current.rst | 9 +++++++++ 2 files changed, 15 insertions(+) diff --git a/CHANGES b/CHANGES index ef1eca035c..8fcdbc995c 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,9 @@ +5773. [func] Change the message when accepting TCP connection has + failed to say "Accepting TCP connection failed" and + change the log level for ISC_R_NOTCONNECTED, ISC_R_QUOTA + and ISC_R_SOFTQUOTA results codes from ERROR to INFO. + [GL #2700] + 5772. [bug] The resolver could hang on shutdown due to dispatch resources not being cleaned up when a TCP connection was reset. [GL #3026] diff --git a/doc/notes/notes-current.rst b/doc/notes/notes-current.rst index 01c49f9508..e539c51c9b 100644 --- a/doc/notes/notes-current.rst +++ b/doc/notes/notes-current.rst @@ -49,6 +49,15 @@ Feature Changes or wildcard (``*``) characters. This reverts change :gl:`!5738` from the previous release. :gl:`#1610` +- Previously, when an incoming TCP connection could not be accepted because the client + closed the connection early, an error message of ``TCP connection + failed: socket is not connected`` was logged. This message has been changed + to ``Accepting TCP connection failed: socket is not connected``. The + severity level at which this type of message is logged has also + been changed from ``error`` to ``info`` for the following triggering + events: ``socket is not connected``, ``quota reached``, and ``soft + quota reached``. :gl:`#2700` + Bug Fixes ~~~~~~~~~