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.

(cherry picked from commit 20ac73eb222e60395399b467b0a72015a4dd8845)

diff --git a/lib/isc/netmgr/netmgr-int.h b/lib/isc/netmgr/netmgr-int.h
index f7b54f948435a31ed9e73ea211ea1f8c1c0e5944..b4299d512ea2565937a3774195a9c1794c2b38a1 100644 (file)
--- a/lib/isc/netmgr/netmgr-int.h
+++ b/lib/isc/netmgr/netmgr-int.h
@@ -1576,4 +1576,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 3283eb6e4f44326be9dc24cb2ad9ed5cb77983b6..54042a9123fa0936ca1b64a3a1c6d5a9c32721a3 100644 (file)
--- a/lib/isc/netmgr/netmgr.c
+++ b/lib/isc/netmgr/netmgr.c
@@ -1967,6 +1967,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 5cca9f52146915d4a11a6e5fad8d2afd3896555d..1b5e80d3a73fdbc7ac21b093c4dd149a51cc819d 100644 (file)
--- 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
@@ -934,15 +926,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 188790c8b4fa5e939379adef27708315b8103dc1..b76dcbc66cb801c48b1c36c23244df76c5cc281b 100644 (file)
--- 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
@@ -905,16 +896,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