From: Matthijs Mekking Date: Mon, 9 Dec 2019 07:26:46 +0000 (+0100) Subject: Fix race in autosign test X-Git-Tag: v9.11.14~7^2~1 X-Git-Url: http://git.ipfire.org/gitweb/?a=commitdiff_plain;h=677ea3aa05e54934b2462253baf5c78c23140164;p=thirdparty%2Fbind9.git Fix race in autosign test The autosign test has a test case where a DNSSEC maintaiend zone has a set of DNSSEC keys without any timing metadata set. It tests if named picks up the key for publication and signing if a delayed dnssec-settime/loadkeys event has occured. The test failed intermittently despite the fact it sleeps for 5 seconds but the triggered key reconfigure action should happen after 3 seconds. However, the test output showed that the test query came in before the key reconfigure action was complete (see excerpts below). The loadkeys command is received: 15:38:36 received control channel command 'loadkeys delay.example.' The reconfiguring zone keys action is triggered after 3 seconds: 15:38:39 zone delay.example/IN: reconfiguring zone keys 15:38:39 DNSKEY delay.example/NSEC3RSASHA1/7484 (ZSK) is now published 15:38:39 DNSKEY delay.example/NSEC3RSASHA1/7455 (KSK) is now published 15:38:39 writing to journal Two seconds later the test query comes in: 15:38:41 client @0x7f1b8c0562b0 10.53.0.1#44177: query 15:38:41 client @0x7f1b8c0562b0 10.53.0.1#44177: endrequest And 6 more seconds later the reconfigure keys action is complete: 15:38:47 zone delay.example/IN: next key event: 05-Dec-2019 15:48:39 This commit fixes the test by checking the "next key event" log has been seen before executing the test query, making sure that the reconfigure keys action has been complete. This commit however does not fix, nor explain why it took such a long time (8 seconds) to reconfigure the keys. (cherry picked from commit 2e4273b55a27dcefa775161b1387fa25f95b678d) (cherry picked from commit fb0ddd5bfe9fa504da0ca46573dfe0d85e56c7d9) --- diff --git a/bin/tests/system/autosign/clean.sh b/bin/tests/system/autosign/clean.sh index 533bcc2e914..371040f5c48 100644 --- a/bin/tests/system/autosign/clean.sh +++ b/bin/tests/system/autosign/clean.sh @@ -14,8 +14,8 @@ rm -f */core rm -f */example.bk rm -f */named.conf rm -f */named.memstats -rm -f */named.run -rm -f */named.conf +rm -f */named.run* +rm -f */trusted.conf */private.conf rm -f activate-now-publish-1day.key rm -f active.key inact.key del.key delzsk.key unpub.key standby.key rev.key rm -f delayksk.key delayzsk.key autoksk.key autozsk.key diff --git a/bin/tests/system/autosign/tests.sh b/bin/tests/system/autosign/tests.sh index 7e2b8efbe45..03f458bba44 100755 --- a/bin/tests/system/autosign/tests.sh +++ b/bin/tests/system/autosign/tests.sh @@ -61,6 +61,12 @@ checkprivate () { return 1 } +# wait until the next key event for zone $1 on server $2. +wait_for_next_key_event () { + wait_for_log 10 "zone ${1}/IN: next key event:" "${2}/named.run" || return 1 + return 0 +} + # Check the signatures expiration times. First check how many signatures # there are in total ($rrsigs). Then see what the distribution of signature # expiration times is ($expiretimes). Ignore the time part for a better @@ -156,6 +162,9 @@ do $DIG $DIGOPTS $z @10.53.0.3 axfr | awk '$4 == "RRSIG" {print $9}' | sort | uniq -c | cat_i done +# Set logfile offset for wait_for_log usage. +nextpartreset ns3/named.run + # # Check that DNSKEY is initially signed with a KSK and not a ZSK. # @@ -1172,12 +1181,14 @@ status=`expr $status + $ret` echo_i "checking scheduled key publication, not activation ($n)" ret=0 +# Ensure initial reconfiguring zone keys event has passed. +wait_for_next_key_event "delay.example" "ns3" || ret=1 $SETTIME -K ns3 -P now+3s -A none $zsk > settime.out.test$n.zsk $SETTIME -K ns3 -P now+3s -A none $ksk > settime.out.test$n.ksk $RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i - echo_i "waiting for changes to take effect" -sleep 5 +sleep 3 +wait_for_next_key_event "delay.example" "ns3" || ret=1 $DIG $DIGOPTS +noall +answer dnskey delay.example. @10.53.0.3 > dig.out.ns3.test$n || ret=1 # DNSKEY expected: @@ -1193,9 +1204,9 @@ ret=0 $SETTIME -K ns3 -A now+3s $zsk > settime.out.test$n.zsk $SETTIME -K ns3 -A now+3s $ksk > settime.out.test$n.ksk $RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i - echo_i "waiting for changes to take effect" -sleep 5 +sleep 3 +wait_for_next_key_event "delay.example" "ns3" || ret=1 $DIG $DIGOPTS +noall +answer dnskey delay.example. @10.53.0.3 > dig.out.ns3.1.test$n || ret=1 # DNSKEY expected: