Merge branch '4001-4002-retry-over-TCP-when-notify-sending-fails' into 'main'

Handle the failure to send notify more gracefully and with log Closes #4001 and #4002 See merge request isc-projects/bind9!7805
2023-04-20 08:41:02 +00:00
parent 6892e463bf f4fcb63152
commit 25962dd188
4 changed files with 84 additions and 21 deletions
@@ -1,3 +1,11 @@
+6151.	[bug]		When the same ``notify-source`` address and port number
+			was configured for multiple destinations and zones, an
+			unresponsive server could tie up the socket until it
+			timed out; in the meantime, NOTIFY messages for other
+			servers silently failed.``named`` will now retry these
+			failing messages over TCP.  NOTIFY failures are now
+			logged at level INFO. [GL #4001] [GL #4002]
+
 6150.	[bug]		If the zones have active upstream forwards, the
 			shutting down the server might cause assertion
 			failures as the forward were all canceled from
@@ -210,9 +210,15 @@ test_end
 # above, which should time out at some point; we need to wait for them to
 # appear in the logs in case the tests run faster than the notify timeouts

-test_start "checking notify retries expire within 45 seconds"
+test_start "checking notify to retry over TCP within 45 seconds"
 nextpartreset ns3/named.run
-wait_for_log 45 'retries exceeded' ns3/named.run || ret=1
+wait_for_log 45 'retrying over TCP' ns3/named.run || ret=1
+test_end
+
+# the TCP timeout is set to 15 seconds, double that for some leeway
+test_start "checking notify retries expire within 30 seconds"
+nextpartreset ns3/named.run
+wait_for_log 30 'retries exceeded' ns3/named.run || ret=1
 test_end

 echo_i "exit status: $status"
@@ -37,6 +37,12 @@ Bug Fixes

 - None.

+- When the same ``notify-source`` address and port number was configured for
+  multiple destinations and zones, an unresponsive server could tie up the
+  socket until it timed out; in the meantime, NOTIFY messages for other servers
+  silently failed.``named`` will now retry these failing messages over TCP.
+  NOTIFY failures are now logged at level INFO. :gl:`#4001` :gl:`#4002`
+
 Known Issues
 ~~~~~~~~~~~~

@@ -639,15 +639,18 @@ struct dns_notify {
 	isc_rlevent_t *rlevent;
 };

-#define DNS_NOTIFY_NOSOA   0x0001U
-#define DNS_NOTIFY_STARTUP 0x0002U
+typedef enum dns_notify_flags {
+	DNS_NOTIFY_NOSOA = 1 << 0,
+	DNS_NOTIFY_STARTUP = 1 << 1,
+	DNS_NOTIFY_TCP = 1 << 2,
+} dns_notify_flags_t;

 /*%
 * Hold checkds state.
 */
 struct dns_checkds {
 	unsigned int magic;
-	unsigned int flags;
+	dns_notify_flags_t flags;
 	isc_mem_t *mctx;
 	dns_zone_t *zone;
 	dns_adbfind_t *find;
@@ -12200,13 +12203,15 @@ notify_send_toaddr(void *arg) {
 	dns_tsigkey_t *key = NULL;
 	char addrbuf[ISC_SOCKADDR_FORMATSIZE];
 	isc_sockaddr_t src;
-	unsigned int options, timeout;
+	unsigned int options, timeout, udptimeout;
 	bool have_notifysource = false;

 	REQUIRE(DNS_NOTIFY_VALID(notify));

 	LOCK_ZONE(notify->zone);

+	isc_sockaddr_format(&notify->dst, addrbuf, sizeof(addrbuf));
+
 	if (DNS_ZONE_FLAG(notify->zone, DNS_ZONEFLG_LOADED) == 0 ||
 	    notify->rlevent->canceled ||
 	    DNS_ZONE_FLAG(notify->zone, DNS_ZONEFLG_EXITING) ||
@@ -12223,7 +12228,6 @@ notify_send_toaddr(void *arg) {
 	if (isc_sockaddr_pf(&notify->dst) == PF_INET6 &&
 	    IN6_IS_ADDR_V4MAPPED(&notify->dst.type.sin6.sin6_addr))
 	{
-		isc_sockaddr_format(&notify->dst, addrbuf, sizeof(addrbuf));
 		notify_log(notify->zone, ISC_LOG_DEBUG(3),
 			   "notify: ignoring IPv6 mapped IPV4 address: %s",
 			   addrbuf);
@@ -12236,7 +12240,6 @@ notify_send_toaddr(void *arg) {
 		goto cleanup;
 	}

-	isc_sockaddr_format(&notify->dst, addrbuf, sizeof(addrbuf));
 	if (notify->key != NULL) {
 		/* Transfer ownership of key */
 		key = notify->key;
@@ -12257,12 +12260,12 @@ notify_send_toaddr(void *arg) {
 		char namebuf[DNS_NAME_FORMATSIZE];

 		dns_name_format(&key->name, namebuf, sizeof(namebuf));
-		notify_log(notify->zone, ISC_LOG_DEBUG(3),
+		notify_log(notify->zone, ISC_LOG_INFO,
 			   "sending notify to %s : TSIG (%s)", addrbuf,
 			   namebuf);
 	} else {
-		notify_log(notify->zone, ISC_LOG_DEBUG(3),
-			   "sending notify to %s", addrbuf);
+		notify_log(notify->zone, ISC_LOG_INFO, "sending notify to %s",
+			   addrbuf);
 	}
 	options = 0;
 	if (notify->zone->view->peers != NULL) {
@@ -12308,13 +12311,20 @@ notify_send_toaddr(void *arg) {
 		result = ISC_R_NOTIMPLEMENTED;
 		goto cleanup_key;
 	}
-	timeout = 15;
+	udptimeout = 15;
 	if (DNS_ZONE_FLAG(notify->zone, DNS_ZONEFLG_DIALNOTIFY)) {
-		timeout = 30;
+		udptimeout = 30;
+	}
+	timeout = 3 * udptimeout;
+again:
+	if ((notify->flags & DNS_NOTIFY_TCP) != 0) {
+		options |= DNS_REQUESTOPT_TCP;
+		udptimeout = 0;
+		timeout = 15;
 	}
 	result = dns_request_create(
 		notify->zone->view->requestmgr, message, &src, &notify->dst,
-		NULL, NULL, options, key, timeout * 3, timeout, 2,
+		NULL, NULL, options, key, timeout, udptimeout, 2,
 		notify->zone->loop, notify_done, notify, &notify->request);
 	if (result == ISC_R_SUCCESS) {
 		if (isc_sockaddr_pf(&notify->dst) == AF_INET) {
@@ -12324,6 +12334,14 @@ notify_send_toaddr(void *arg) {
 			inc_stats(notify->zone,
 				  dns_zonestatscounter_notifyoutv6);
 		}
+	} else if (result == ISC_R_SHUTTINGDOWN || result == ISC_R_CANCELED) {
+		goto cleanup_key;
+	} else if ((notify->flags & DNS_NOTIFY_TCP) == 0) {
+		notify_log(notify->zone, ISC_LOG_NOTICE,
+			   "notify to %s failed: %s: retrying over TCP",
+			   addrbuf, isc_result_totext(result));
+		notify->flags |= DNS_NOTIFY_TCP;
+		goto again;
 	}

 cleanup_key:
@@ -12334,8 +12352,15 @@ cleanup_message:
 	dns_message_detach(&message);
 cleanup:
 	UNLOCK_ZONE(notify->zone);
-	isc_rlevent_free(&notify->rlevent);
+	if (notify->rlevent != NULL) {
+		isc_rlevent_free(&notify->rlevent);
+	}
+
 	if (result != ISC_R_SUCCESS) {
+		isc_sockaddr_format(&notify->dst, addrbuf, sizeof(addrbuf));
+		notify_log(notify->zone, ISC_LOG_WARNING,
+			   "notify to %s failed: %s", addrbuf,
+			   isc_result_totext(result));
 		notify_destroy(notify, false);
 	}
 }
@@ -15777,18 +15802,36 @@ notify_done(void *arg) {
 			   (int)buf.used, rcode);
 	}

+	dns_message_detach(&message);
 	goto done;

 fail:
-	notify_log(notify->zone, ISC_LOG_DEBUG(2), "notify to %s failed: %s",
-		   addrbuf, isc_result_totext(result));
-	if (result == ISC_R_TIMEDOUT) {
-		notify_log(notify->zone, ISC_LOG_DEBUG(1),
-			   "notify to %s: retries exceeded", addrbuf);
+	dns_message_detach(&message);
+
+	if (result == ISC_R_SUCCESS) {
+		notify_log(notify->zone, ISC_LOG_INFO,
+			   "notify to %s successful", addrbuf);
+	} else if (result == ISC_R_SHUTTINGDOWN || result == ISC_R_CANCELED) {
+		goto done;
+	} else if ((notify->flags & DNS_NOTIFY_TCP) == 0) {
+		notify_log(notify->zone, ISC_LOG_NOTICE,
+			   "notify to %s failed: %s: retrying over TCP",
+			   addrbuf, isc_result_totext(result));
+		notify->flags |= DNS_NOTIFY_TCP;
+		dns_request_destroy(&notify->request);
+		notify_send_queue(notify, (notify->flags & DNS_NOTIFY_STARTUP));
+		return;
+	} else if (result == ISC_R_TIMEDOUT) {
+		notify_log(notify->zone, ISC_LOG_WARNING,
+			   "notify to %s failed: %s: retries exceeded", addrbuf,
+			   isc_result_totext(result));
+	} else {
+		notify_log(notify->zone, ISC_LOG_WARNING,
+			   "notify to %s failed: %s", addrbuf,
+			   isc_result_totext(result));
 	}
 done:
 	notify_destroy(notify, false);
-	dns_message_detach(&message);
 }

 struct rss {