From 0d48ac5a936ce01d1187b430b21f2d430abe6ed0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Sur=C3=BD?= Date: Wed, 5 Apr 2023 15:24:21 +0200 Subject: [PATCH 1/2] 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 --- bin/tests/system/notify/tests.sh | 10 +++- lib/dns/zone.c | 81 ++++++++++++++++++++++++-------- 2 files changed, 70 insertions(+), 21 deletions(-) diff --git a/bin/tests/system/notify/tests.sh b/bin/tests/system/notify/tests.sh index a96d59cb57..1d62c035dc 100644 --- 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 0a7d1d9d5d..05d7d6c1fd 100644 --- 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(¬ify->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(¬ify->dst) == PF_INET6 && IN6_IS_ADDR_V4MAPPED(¬ify->dst.type.sin6.sin6_addr)) { - isc_sockaddr_format(¬ify->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(¬ify->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, ¬ify->dst, - NULL, NULL, options, key, timeout * 3, timeout, 2, + NULL, NULL, options, key, timeout, udptimeout, 2, notify->zone->loop, notify_done, notify, ¬ify->request); if (result == ISC_R_SUCCESS) { if (isc_sockaddr_pf(¬ify->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(¬ify->rlevent); + if (notify->rlevent != NULL) { + isc_rlevent_free(¬ify->rlevent); + } + if (result != ISC_R_SUCCESS) { + isc_sockaddr_format(¬ify->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(¬ify->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 { From f4fcb63152aefa453d5d82ed611c644cfa21e3ff Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Sur=C3=BD?= Date: Wed, 5 Apr 2023 15:37:07 +0200 Subject: [PATCH 2/2] Add CHANGES and release note for [GL #4001] [GL #4002] --- CHANGES | 8 ++++++++ doc/notes/notes-current.rst | 6 ++++++ 2 files changed, 14 insertions(+) diff --git a/CHANGES b/CHANGES index 2aa2225de3..aa518f8a15 100644 --- a/CHANGES +++ b/CHANGES @@ -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 diff --git a/doc/notes/notes-current.rst b/doc/notes/notes-current.rst index 5653301c0c..51c5e2d9e6 100644 --- a/doc/notes/notes-current.rst +++ b/doc/notes/notes-current.rst @@ -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 ~~~~~~~~~~~~