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.

diff --git a/lib/isc/netmgr/netmgr-int.h b/lib/isc/netmgr/netmgr-int.h
index da892b8415aca34c8e8da7ecc9d6d67d2591e455..db5c247118391f39616c2da7e18d799f2958a99f 100644 (file)
--- 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 3404d19ba0ebc1dc6088fb592daaa054615567ac..13168683e11b20d97d4ad977a1c340f09c0e850d 100644 (file)
--- 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 382018944e2138fc1a36c3be837258975ca20efc..eb6437d8d4a862374818edc09f94854b80aa347b 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
@@ -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 5fed46018f1f8d37287af72d98a84c36e1ba3698..9167e52bb5f7360b2d9d76bcba105bdbacd9dffc 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
@@ -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 700874d28e9e9d45cebf6e5ae01b255190351389..137a1709cd276f7952abf20a973200717156f37d 100644 (file)
--- 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