Handle the failure to send notify more gracefully and with log

When dns_request_create() failed in notify_send_toaddr(), sending the
notify would silently fail.  When notify_done() failed, the error would
be logged on the DEBUG(2) level.

This commit remedies the situation by:

 * Promoting several messages related to notifies to INFO level and add
   a "success" log message at the INFO level

 * Adding a TCP fallback - when sending the notify over UDP fails, named
   will retry sending notify over TCP and log the information on the
   NOTICE level

 * When sending the notify over TCP fails, it will be logged on the
   WARNING level

Closes: #4001, #4002

diff --git a/bin/tests/system/notify/tests.sh b/bin/tests/system/notify/tests.sh
index a96d59cb57f08f39084dc1f31f7ab743d37c4663..1d62c035dc130767058defd86e6a29a4112c5b45 100644 (file)
--- a/bin/tests/system/notify/tests.sh
+++ b/bin/tests/system/notify/tests.sh
@@ -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"

diff --git a/lib/dns/zone.c b/lib/dns/zone.c
index 0a7d1d9d5d62cbe603b91ac3400f5c92aef95970..05d7d6c1fd2d25e5675a58a8a3e7c6eef49e2385 100644 (file)
--- a/lib/dns/zone.c
+++ b/lib/dns/zone.c
@@ -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 {