From 1c97ace7dc9608c5b4e92c4f3eca5eae5305e831 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Wed, 16 Jan 2019 15:31:48 +0100 Subject: [PATCH 1/4] Log a message when a transferred mirror zone comes into effect Log a message when a mirror zone is successfully transferred and verified, but only if no database for that zone was yet loaded at the time the transfer was initiated. This could have been implemented in a simpler manner, e.g. by modifying zone_replacedb(), but (due to the calling order of the functions involved in finalizing a zone transfer) that would cause the resulting logs to suggest that a mirror zone comes into effect before its transfer is finished, which would be confusing given the nature of mirror zones and the fact that no message is logged upon successful mirror zone verification. Once the dns_zone_replacedb() call in axfr_finalize() is made, it becomes impossible to determine whether the transferred zone had a database attached before the transfer was started. Thus, that check is instead performed when the transfer context is first created and the result of this check is passed around in a field of the transfer context structure. If it turns out to be desired, the relevant log message is then emitted just before the transfer context is freed. Taking this approach means that the log message added by this commit is not timed precisely, i.e. mirror zone data may be used before this message is logged. However, that can only be fixed by logging the message inside zone_replacedb(), which causes arguably more dire issues discussed above. dns_zone_isloaded() is not used to double-check that transferred zone data was correctly loaded since the 'shutdown_result' field of the zone transfer context will not be set to ISC_R_SUCCESS unless axfr_finalize() succeeds (and that in turn will not happen unless dns_zone_replacedb() succeeds). --- bin/tests/system/mirror/ns2/named.conf.in | 1 + bin/tests/system/mirror/tests.sh | 29 +++++++++++++++++++---- lib/dns/xfrin.c | 23 +++++++++++++++++- 3 files changed, 47 insertions(+), 6 deletions(-) diff --git a/bin/tests/system/mirror/ns2/named.conf.in b/bin/tests/system/mirror/ns2/named.conf.in index 2979ea9980..1b616e52a8 100644 --- a/bin/tests/system/mirror/ns2/named.conf.in +++ b/bin/tests/system/mirror/ns2/named.conf.in @@ -59,6 +59,7 @@ zone "verify-ixfr" { type master; file "verify-ixfr.db.signed"; ixfr-from-differences yes; + allow-transfer { 10.53.0.3; }; }; zone "verify-reconfig" { diff --git a/bin/tests/system/mirror/tests.sh b/bin/tests/system/mirror/tests.sh index 074e82a451..e6702de1df 100644 --- a/bin/tests/system/mirror/tests.sh +++ b/bin/tests/system/mirror/tests.sh @@ -62,7 +62,8 @@ ret=0 wait_for_transfer verify-unsigned $DIG $DIGOPTS @10.53.0.3 +norec verify-unsigned SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_BAD}.*; serial" dig.out.ns3.test$n > /dev/null && ret=1 -nextpart ns3/named.run | grep "verify-unsigned.*Zone contains no DNSSEC keys" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-unsigned.*Zone contains no DNSSEC keys" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-unsigned.*mirror zone is now in use" > /dev/null && ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -73,7 +74,8 @@ nextpartreset ns3/named.run wait_for_transfer verify-untrusted $DIG $DIGOPTS @10.53.0.3 +norec verify-untrusted SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_BAD}.*; serial" dig.out.ns3.test$n > /dev/null && ret=1 -nextpart ns3/named.run | grep "verify-untrusted.*No trusted KSK DNSKEY found" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-untrusted.*No trusted KSK DNSKEY found" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-untrusted.*mirror zone is now in use" > /dev/null && ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -84,7 +86,8 @@ nextpartreset ns3/named.run wait_for_transfer verify-axfr $DIG $DIGOPTS @10.53.0.3 +norec verify-axfr SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_BAD}.*; serial" dig.out.ns3.test$n > /dev/null && ret=1 -nextpart ns3/named.run | grep "No correct RSASHA256 signature for verify-axfr SOA" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "No correct RSASHA256 signature for verify-axfr SOA" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-axfr.*mirror zone is now in use" > /dev/null && ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -98,6 +101,7 @@ $RNDCCMD 10.53.0.3 retransfer verify-axfr > /dev/null 2>&1 wait_for_transfer verify-axfr $DIG $DIGOPTS @10.53.0.3 +norec verify-axfr SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_GOOD}.*; serial" dig.out.ns3.test$n > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-axfr.*mirror zone is now in use" > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -106,12 +110,23 @@ echo_i "checking that an IXFR of an incorrectly signed mirror zone is rejected ( nextpartreset ns3/named.run ret=0 wait_for_transfer verify-ixfr -nextpart ns3/named.run > /dev/null # Make a copy of the original zone file for reuse in journal tests below. cp ns2/verify-ixfr.db.signed ns3/verify-journal.db.mirror # Wait 1 second so that the zone file timestamp changes and the subsequent -# invocation of "rndc reload" triggers a zone reload. +# invocation of "rndc reload" triggers a zone reload. This should also be way +# more than enough for the log message announcing the mirror zone coming into +# effect to appear in the log (see below). sleep 1 +# Sanity check: the initial, properly signed version of the zone should have +# been announced as coming into effect. Note that we cannot check that +# immediately after wait_for_transfer() as the latter might return before the +# log message we are looking for here appears; we also cannot call nextpart() +# after we update the zone on ns2 since there is a possibility of periodic +# refreshes triggering an IXFR of the "verify-ixfr" zone before the "rndc +# refresh" call below and that possibility needs to be handled as proper +# behavior. Thus, we need to look for the log message now. +nextpart ns3/named.run | grep "verify-ixfr.*mirror zone is now in use" > /dev/null || ret=1 +# Update the "verify-ixfr" zone on ns2. cat ns2/verify-ixfr.db.bad.signed > ns2/verify-ixfr.db.signed reload_zone verify-ixfr ${UPDATED_SERIAL_BAD} # Make a copy of the bad zone journal for reuse in journal tests below. @@ -148,6 +163,10 @@ wait_for_transfer verify-ixfr # Ensure the new, good version of the zone was accepted. $DIG $DIGOPTS @10.53.0.3 +norec verify-ixfr SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_GOOD}.*; serial" dig.out.ns3.test$n > /dev/null || ret=1 +# The log message announcing the mirror zone coming into effect should not have +# been logged this time since the mirror zone in question is expected to +# already be in effect before this test case is checked. +nextpartpeek ns3/named.run | grep "verify-ixfr.*mirror zone is now in use" > /dev/null && ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` diff --git a/lib/dns/xfrin.c b/lib/dns/xfrin.c index f7e5cb3ab5..2ae5f94149 100644 --- a/lib/dns/xfrin.c +++ b/lib/dns/xfrin.c @@ -133,6 +133,13 @@ struct dns_xfrin_ctx { dns_tcpmsg_t tcpmsg; bool tcpmsg_valid; + /*% + * Whether the zone originally had a database attached at the time this + * transfer context was created. Used by maybe_free() when making + * logging decisions. + */ + bool zone_had_db; + dns_db_t *db; dns_dbversion_t *ver; dns_diff_t diff; /*%< Pending database changes */ @@ -657,6 +664,10 @@ dns_xfrin_create(dns_zone_t *zone, dns_rdatatype_t xfrtype, dns_zone_getclass(zone), xfrtype, masteraddr, sourceaddr, dscp, tsigkey, &xfr)); + if (db != NULL) { + xfr->zone_had_db = true; + } + CHECK(xfrin_start(xfr)); xfr->done = done; @@ -821,6 +832,7 @@ xfrin_create(isc_mem_t *mctx, /* tcpmsg */ xfr->tcpmsg_valid = false; + xfr->zone_had_db = false; xfr->db = NULL; if (db != NULL) dns_db_attach(db, &xfr->db); @@ -1513,8 +1525,17 @@ maybe_free(dns_xfrin_ctx_t *xfr) { if (xfr->db != NULL) dns_db_detach(&xfr->db); - if (xfr->zone != NULL) + if (xfr->zone != NULL) { + if (!xfr->zone_had_db && + xfr->shuttingdown && + xfr->shutdown_result == ISC_R_SUCCESS && + dns_zone_gettype(xfr->zone) == dns_zone_mirror) + { + dns_zone_log(xfr->zone, ISC_LOG_INFO, + "mirror zone is now in use"); + } dns_zone_idetach(&xfr->zone); + } isc_mem_putanddetach(&xfr->mctx, xfr, sizeof(*xfr)); } From 7665e132066e8c8fd59581f425842501f7776539 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Wed, 16 Jan 2019 15:31:48 +0100 Subject: [PATCH 2/4] Log a message when a mirror zone loaded from disk comes into effect Log a message when a mirror zone is successfully loaded from disk and subsequently verified. This could have been implemented in a simpler manner, e.g. by modifying an earlier code branch inside zone_postload() which checks whether the zone already has a database attached and calls attachdb() if it does not, but that would cause the resulting logs to indicate that a mirror zone comes into effect before the "loaded serial ..." message is logged, which would be confusing. Tweak some existing sed commands used in the "mirror" system test to ensure that separate test cases comprising it do not break each other. --- bin/tests/system/mirror/tests.sh | 34 ++++++++++++++++++++++++++++---- lib/dns/zone.c | 7 +++++++ 2 files changed, 37 insertions(+), 4 deletions(-) diff --git a/bin/tests/system/mirror/tests.sh b/bin/tests/system/mirror/tests.sh index e6702de1df..970cb6a7d9 100644 --- a/bin/tests/system/mirror/tests.sh +++ b/bin/tests/system/mirror/tests.sh @@ -177,7 +177,8 @@ nextpartreset ns3/named.run wait_for_load verify-load ${UPDATED_SERIAL_BAD} ns3/named.run $DIG $DIGOPTS @10.53.0.3 +norec verify-load SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_BAD}.*; serial" dig.out.ns3.test$n > /dev/null && ret=1 -nextpart ns3/named.run | grep "No correct RSASHA256 signature for verify-load SOA" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "No correct RSASHA256 signature for verify-load SOA" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-load.*mirror zone is now in use" > /dev/null && ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -191,6 +192,7 @@ $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port ${PORT} mirror ns3 wait_for_load verify-load ${UPDATED_SERIAL_GOOD} ns3/named.run $DIG $DIGOPTS @10.53.0.3 +norec verify-load SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_GOOD}.*; serial" dig.out.ns3.test$n > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-load.*mirror zone is now in use" > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -200,12 +202,31 @@ ret=0 $PERL $SYSTEMTESTTOP/stop.pl --use-rndc --port ${CONTROLPORT} mirror ns3 cp ns3/verify-journal.db.mirror ns3/verify-ixfr.db.mirror cp ns3/verify-journal.db.bad.mirror.jnl ns3/verify-ixfr.db.mirror.jnl +# Temporarily disable transfers of the "verify-ixfr" zone on ns2. This is +# required to reliably test whether the message announcing the mirror zone +# coming into effect is not logged after a failed journal verification since +# otherwise a corrected version of the zone may be transferred after +# verification fails but before we look for the aforementioned log message. +# (NOTE: Keep the embedded newline in the sed function list below.) +sed '/^zone "verify-ixfr" {$/,/^};$/ { + s/10.53.0.3/10.53.0.254/ +}' ns2/named.conf > ns2/named.conf.modified +mv ns2/named.conf.modified ns2/named.conf +rndc_reconfig ns2 10.53.0.2 nextpart ns3/named.run > /dev/null $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port ${PORT} mirror ns3 wait_for_load verify-ixfr ${UPDATED_SERIAL_BAD} ns3/named.run $DIG $DIGOPTS @10.53.0.3 +norec verify-ixfr SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_BAD}.*; serial" dig.out.ns3.test$n > /dev/null && ret=1 -nextpart ns3/named.run | grep "No correct RSASHA256 signature for verify-ixfr SOA" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "No correct RSASHA256 signature for verify-ixfr SOA" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-ixfr.*mirror zone is now in use" > /dev/null && ret=1 +# Restore transfers for the "verify-ixfr" zone on ns2. +# (NOTE: Keep the embedded newline in the sed function list below.) +sed '/^zone "verify-ixfr" {$/,/^};$/ { + s/10.53.0.254/10.53.0.3/ +}' ns2/named.conf > ns2/named.conf.modified +mv ns2/named.conf.modified ns2/named.conf +rndc_reconfig ns2 10.53.0.2 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -220,6 +241,7 @@ $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port ${PORT} mirror ns3 wait_for_load verify-ixfr ${UPDATED_SERIAL_GOOD} ns3/named.run $DIG $DIGOPTS @10.53.0.3 +norec verify-ixfr SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_GOOD}.*; serial" dig.out.ns3.test$n > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "verify-ixfr.*mirror zone is now in use" > /dev/null || ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -320,7 +342,9 @@ grep "flags:.* ad" dig.out.ns3.test$n.1 > /dev/null || ret=1 # Sanity check: the authoritative server should have been queried. nextpart ns2/named.run | grep "query 'foo.initially-unavailable/A/IN'" > /dev/null || ret=1 # Reconfigure ns2 so that the zone can be mirrored on ns3. -sed "s/10.53.0.254/10.53.0.3/;" ns2/named.conf > ns2/named.conf.modified +sed '/^zone "initially-unavailable" {$/,/^};$/ { + s/10.53.0.254/10.53.0.3/ +}' ns2/named.conf > ns2/named.conf.modified mv ns2/named.conf.modified ns2/named.conf rndc_reconfig ns2 10.53.0.2 # Flush the cache on ns3 and retransfer the mirror zone. @@ -343,7 +367,9 @@ echo_i "checking that resolution succeeds with expired mirror zone data ($n)" ret=0 # Reconfigure ns2 so that the zone from the previous test can no longer be # mirrored on ns3. -sed "s/10.53.0.3/10.53.0.254/;" ns2/named.conf > ns2/named.conf.modified +sed '/^zone "initially-unavailable" {$/,/^};$/ { + s/10.53.0.3/10.53.0.254/ +}' ns2/named.conf > ns2/named.conf.modified mv ns2/named.conf.modified ns2/named.conf rndc_reconfig ns2 10.53.0.2 # Stop ns3, update the timestamp of the zone file to one far in the past, then diff --git a/lib/dns/zone.c b/lib/dns/zone.c index 5a22e77998..77497fd919 100644 --- a/lib/dns/zone.c +++ b/lib/dns/zone.c @@ -4440,6 +4440,7 @@ zone_postload(dns_zone_t *zone, dns_db_t *db, isc_time_t loadtime, bool needdump = false; bool hasinclude = DNS_ZONE_FLAG(zone, DNS_ZONEFLG_HASINCLUDE); bool nomaster = false; + bool had_db = false; unsigned int options; dns_include_t *inc; @@ -4804,6 +4805,7 @@ zone_postload(dns_zone_t *zone, dns_db_t *db, isc_time_t loadtime, ZONEDB_LOCK(&zone->dblock, isc_rwlocktype_write); if (zone->db != NULL) { + had_db = true; result = zone_replacedb(zone, db, false); ZONEDB_UNLOCK(&zone->dblock, isc_rwlocktype_write); if (result != ISC_R_SUCCESS) @@ -4915,6 +4917,11 @@ zone_postload(dns_zone_t *zone, dns_db_t *db, isc_time_t loadtime, dns_db_issecure(db) ? " (DNSSEC signed)" : ""); } + if (!had_db && zone->type == dns_zone_mirror) { + dns_zone_logc(zone, DNS_LOGCATEGORY_ZONELOAD, ISC_LOG_INFO, + "mirror zone is now in use"); + } + zone->loadtime = loadtime; goto done; From 7d6b8f7c128009fb167a605bc324ca3020a12cae Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Wed, 16 Jan 2019 15:31:48 +0100 Subject: [PATCH 3/4] Log a message when a mirror zone becomes unusable Log a message if a mirror zone becomes unusable for the resolver (most usually due to the zone's expiration timer firing). Ensure that verification failures do not cause a mirror zone to be unloaded (instead, its last successfully verified version should be served if it is available). --- bin/tests/system/mirror/tests.sh | 11 ++++++++--- lib/dns/zone.c | 6 ++++++ 2 files changed, 14 insertions(+), 3 deletions(-) diff --git a/bin/tests/system/mirror/tests.sh b/bin/tests/system/mirror/tests.sh index 970cb6a7d9..ce35f67dc0 100644 --- a/bin/tests/system/mirror/tests.sh +++ b/bin/tests/system/mirror/tests.sh @@ -142,7 +142,10 @@ fi # Ensure the new, bad version of the zone was not accepted. $DIG $DIGOPTS @10.53.0.3 +norec verify-ixfr SOA > dig.out.ns3.test$n 2>&1 || ret=1 grep "${UPDATED_SERIAL_BAD}.*; serial" dig.out.ns3.test$n > /dev/null && ret=1 -nextpart ns3/named.run | grep "No correct RSASHA256 signature for verify-ixfr SOA" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "No correct RSASHA256 signature for verify-ixfr SOA" > /dev/null || ret=1 +# Despite the verification failure for this IXFR, this mirror zone should still +# be in use as its previous version should have been verified successfully. +nextpartpeek ns3/named.run | grep "verify-ixfr.*mirror zone is no longer in use" > /dev/null && ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -165,7 +168,7 @@ $DIG $DIGOPTS @10.53.0.3 +norec verify-ixfr SOA > dig.out.ns3.test$n 2>&1 || ret grep "${UPDATED_SERIAL_GOOD}.*; serial" dig.out.ns3.test$n > /dev/null || ret=1 # The log message announcing the mirror zone coming into effect should not have # been logged this time since the mirror zone in question is expected to -# already be in effect before this test case is checked. +# already be in use before this test case is checked. nextpartpeek ns3/named.run | grep "verify-ixfr.*mirror zone is now in use" > /dev/null && ret=1 if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -380,7 +383,9 @@ nextpart ns3/named.run > /dev/null $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port ${PORT} mirror ns3 # Ensure named attempts to retransfer the zone due to its expiry. wait_for_transfer initially-unavailable -nextpart ns3/named.run | grep "initially-unavailable.*expired" > /dev/null || ret=1 +# Ensure the expected messages were logged. +nextpartpeek ns3/named.run | grep "initially-unavailable.*expired" > /dev/null || ret=1 +nextpartpeek ns3/named.run | grep "initially-unavailable.*mirror zone is no longer in use" > /dev/null || ret=1 # Query for a record in the expired zone. Resolution should still succeed. $DIG $DIGOPTS @10.53.0.3 foo.initially-unavailable. A > dig.out.ns3.test$n 2>&1 || ret=1 # Check response code and flags in the answer. diff --git a/lib/dns/zone.c b/lib/dns/zone.c index 77497fd919..954245c999 100644 --- a/lib/dns/zone.c +++ b/lib/dns/zone.c @@ -10845,6 +10845,12 @@ zone_unload(dns_zone_t *zone) { ZONEDB_UNLOCK(&zone->dblock, isc_rwlocktype_write); DNS_ZONE_CLRFLAG(zone, DNS_ZONEFLG_LOADED); DNS_ZONE_CLRFLAG(zone, DNS_ZONEFLG_NEEDDUMP); + + if (zone->type == dns_zone_mirror) { + dns_zone_log(zone, ISC_LOG_INFO, + "mirror zone is no longer in use; " + "reverting to normal recursion"); + } } void From 5d37c910c80269940ebd5ce9a89ec7db05073680 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Wed, 16 Jan 2019 15:31:48 +0100 Subject: [PATCH 4/4] Add CHANGES entry 5137. [func] named now logs messages whenever a mirror zone becomes usable or unusable for resolution purposes. [GL #818] --- CHANGES | 3 +++ 1 file changed, 3 insertions(+) diff --git a/CHANGES b/CHANGES index a46594cb4f..c3be4bc5b1 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,6 @@ +5137. [func] named now logs messages whenever a mirror zone becomes + usable or unusable for resolution purposes. [GL #818] + 5136. [cleanup] Check in named-checkconf that allow-update and allow-update-forwarding are not set at the view/options level; fix documentation. [GL #512]