Merge branch '3275-notify-test-fix' into 'main'

Avoid timeouts in the notify system test

Closes #3275

See merge request isc-projects/bind9!6121
This commit is contained in:
Tony Finch
2022-04-19 17:10:59 +00:00
3 changed files with 27 additions and 14 deletions

View File

@@ -1263,7 +1263,7 @@ $SETTIME -K ns3 -A now+3s $ksk > settime.out.test$n.ksk || ret=1
($RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i) || ret=1
echo_i "waiting for changes to take effect"
sleep 3
wait_for_log 10 "add delay\.example\..*NSEC.a\.delay\.example\. NS SOA RRSIG NSEC DNSKEY" ns3/named.run
wait_for_log_re 10 "add delay\.example\..*NSEC.a\.delay\.example\. NS SOA RRSIG NSEC DNSKEY" ns3/named.run
check_is_signed() {
$DIG $DIGOPTS +noall +answer dnskey delay.example. @10.53.0.3 > dig.out.ns3.1.test$n || return 1
# DNSKEY expected:

View File

@@ -489,6 +489,13 @@ _search_log() (
nextpart "$file" | grep -F -e "$msg" > /dev/null
)
# _search_log_re: same as _search_log but the message is an egrep regex
_search_log_re() (
msg="$1"
file="$2"
nextpart "$file" | grep -E -e "$msg" > /dev/null
)
# _search_log_peek: look for message $1 in file $2 with nextpartpeek().
_search_log_peek() (
msg="$1"
@@ -506,7 +513,17 @@ wait_for_log() (
msg="$2"
file="$3"
retry_quiet "$timeout" _search_log "$msg" "$file" && return 0
echo_i "exceeded time limit waiting for '$msg' in $file"
echo_i "exceeded time limit waiting for literal '$msg' in $file"
return 1
)
# wait_for_log_re: same as wait_for_log, but the message is an egrep regex
wait_for_log_re() (
timeout="$1"
msg="$2"
file="$3"
retry_quiet "$timeout" _search_log_re "$msg" "$file" && return 0
echo_i "exceeded time limit waiting for regex '$msg' in $file"
return 1
)
@@ -517,7 +534,7 @@ wait_for_log_peek() (
msg="$2"
file="$3"
retry_quiet "$timeout" _search_log_peek "$msg" "$file" && return 0
echo_i "exceeded time limit waiting for '$msg' in $file"
echo_i "exceeded time limit waiting for literal '$msg' in $file"
return 1
)

View File

@@ -105,15 +105,7 @@ rm -f ns2/example.db
cp -f ns2/example2.db ns2/example.db
echo_i "reloading with example2 using HUP and waiting up to 45 seconds"
kill -HUP "$(cat ns2/named.pid)"
try=0
while [ $try -lt 45 ]
do
nextpart ns3/named.run > tmp
grep "transfer of 'example/IN' from 10.53.0.2#.*success" tmp > /dev/null && break
sleep 1
try=$((try + 1))
done
wait_for_log_re 45 "transfer of 'example/IN' from 10.53.0.2#.*success" ns3/named.run
test_start "checking notify message was logged"
grep 'notify from 10.53.0.2#[0-9][0-9]*: serial 2$' ns3/named.run > /dev/null || ret=1
@@ -143,7 +135,7 @@ rm -f ns2/example.db
cp -f ns2/example4.db ns2/example.db
start_server --noclean --restart --port "${PORT}" notify ns2
wait_for_log 45 "transfer of 'example/IN' from 10.53.0.2#.*success" ns3/named.run
wait_for_log_re 45 "transfer of 'example/IN' from 10.53.0.2#.*success" ns3/named.run
test_start "checking notify message was logged"
grep 'notify from 10.53.0.2#[0-9][0-9]*: serial 4$' ns3/named.run > /dev/null || ret=1
@@ -208,10 +200,14 @@ grep "test string" "$fnb" > /dev/null || ret=1
grep "test string" "$fnc" > /dev/null || ret=1
grep "sending notify to 10.53.0.5#[0-9]* : TSIG (b)" ns5/named.run > /dev/null || ret=1
grep "sending notify to 10.53.0.5#[0-9]* : TSIG (c)" ns5/named.run > /dev/null || ret=1
test_end
# notify messages were sent to unresponsive 10.53.10.53 during the tests
# 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 ($n)"
nextpartreset ns3/named.run
wait_for_log 45 'retries exceeded' ns3/named.run || ret=1
test_end