RNDC system test failed to run to completion
Job #3628321 failed for 6a1a7375:
check if query for the zone returns SERVFAIL
test failed as the dig
command timed out. It is attempting to elicit a SERVFAIL
response while the zone is loading but failed to get any response. At a minimum || ret=
needs to be added to the dig command to allow the test to complete and report failure. We also need to try to determine why named failed to respond while the server was loading huge.zone
.
2023-09-01 02:25:00 INFO:rndc I:rndc_tmp_sza8xpb1:test 'rndc reconfig' with loading of a large zone (53)
2023-09-01 02:25:00 INFO:rndc I:rndc_tmp_sza8xpb1:reloading config
2023-09-01 02:25:01 INFO:rndc I:rndc_tmp_sza8xpb1:check if zone load was scheduled (54)
2023-09-01 02:25:01 INFO:rndc I:rndc_tmp_sza8xpb1:check if query for the zone returns SERVFAIL (55)
---------------------------- Captured log teardown -----------------------------
2023-09-01 02:25:19 INFO:rndc test artifacts in: rndc_rndc
$ awk '/^=+ ERRORS =+/{flag=1;next}/^=+.*=+$/{flag=0}flag' bin/tests/system/pytest.out.txt || true
$ find bin/tests/system -name "*dig.*" | xargs grep "error" || true
bin/tests/system/rndc_tmp_sza8xpb1/dig.out.4.test31:;; communications error to 10.53.0.4#19999: timed out
bin/tests/system/rndc_tmp_sza8xpb1/dig.out.1.test55:;; communications error to 10.53.0.6#19999: timed out
bin/tests/system/rndc_tmp_sza8xpb1/dig.out.1.test55:;; communications error to 10.53.0.6#19999: timed out
bin/tests/system/rndc_tmp_sza8xpb1/dig.out.1.test55:;; communications error to 10.53.0.6#19999: timed out
$ PYTHON="$(source bin/tests/system/conf.sh; echo $PYTHON)"
n=$((n+1))
echo_i "test 'rndc reconfig' with loading of a large zone ($n)"
ret=0
nextpart ns6/named.run > /dev/null
cp ns6/named.conf ns6/named.conf.save
echo "zone \"huge.zone\" { type primary; file \"huge.zone.db\"; };" >> ns6/named.conf
echo_i "reloading config"
$RNDCCMD 10.53.0.6 reconfig > rndc.out.1.test$n 2>&1 || ret=1
if [ $ret != 0 ]; then echo_i "failed"; fi
status=$((status+ret))
sleep 1
n=$((n+1))
echo_i "check if zone load was scheduled ($n)"
wait_for_log_peek 20 "scheduled loading new zones" ns6/named.run || ret=1
if [ $ret != 0 ]; then echo_i "failed"; fi
status=$((status+ret))
n=$((n+1))
echo_i "check if query for the zone returns SERVFAIL ($n)"
$DIG @10.53.0.6 -p ${PORT} -t soa huge.zone > dig.out.1.test$n
grep "SERVFAIL" dig.out.1.test$n > /dev/null || ret=1
if [ $ret != 0 ]; then echo_i "failed (ignored)"; ret=0; fi
status=$((status+ret))
n=$((n+1))
echo_i "wait for the zones to be loaded ($n)"
wait_for_log_peek 60 "huge.zone/IN: loaded serial" ns6/named.run || ret=1
if [ $ret != 0 ]; then echo_i "failed"; fi
status=$((status+ret))
n=$((n+1))
echo_i "check if query for the zone returns NOERROR ($n)"
$DIG @10.53.0.6 -p ${PORT} -t soa huge.zone > dig.out.1.test$n
grep "NOERROR" dig.out.1.test$n > /dev/null || ret=1
if [ $ret != 0 ]; then echo_i "failed"; fi
status=$((status+ret))
01-Sep-2023 02:25:00.172 received control channel command 'reconfig'
...
01-Sep-2023 02:25:00.184 load_configuration: success
01-Sep-2023 02:25:00.184 reloading configuration succeeded
01-Sep-2023 02:25:00.184 loop exclusive mode: starting
01-Sep-2023 02:25:00.184 loop exclusive mode: started
01-Sep-2023 02:25:00.188 loop exclusive mode: ending
01-Sep-2023 02:25:00.188 loop exclusive mode: ended
01-Sep-2023 02:25:00.188 scheduled loading new zones
01-Sep-2023 02:25:00.188 zone huge.zone/IN: starting load
01-Sep-2023 02:25:00.188 zone_startload: zone huge.zone/IN: enter
01-Sep-2023 02:25:00.192 huge.zone.db:234: signature has expired
01-Sep-2023 02:25:11.184 zone huge.zone/IN: number of nodes in database: 250163
01-Sep-2023 02:25:11.184 zone huge.zone/IN: no journal file, but that's OK
01-Sep-2023 02:25:11.184 zone huge.zone/IN: loaded; checking validity
01-Sep-2023 02:25:11.184 zone huge.zone/IN: ds01.huge.zone/NS 'ns42.huge.zone' has no address records (A or AAAA)
01-Sep-2023 02:25:11.184 zone huge.zone/IN: ds02.huge.zone/NS 'ns43.huge.zone' has no address records (A or AAAA)
01-Sep-2023 02:25:14.972 zone huge.zone/IN: mx01.huge.zone/MX 'mail.huge.zone' has no address records (A or AAAA)
01-Sep-2023 02:25:14.972 zone huge.zone/IN: 'spf01.huge.zone' found type SPF record but no SPF TXT record found, add matching type TXT record
01-Sep-2023 02:25:14.972 zone huge.zone/IN: 'spf02.huge.zone' found type SPF record but no SPF TXT record found, add matching type TXT record
01-Sep-2023 02:25:14.972 zone huge.zone/IN: srv02.huge.zone/SRV 'old-slow-box.huge.zone' has no address records (A or AAAA)
01-Sep-2023 02:25:18.652 dns_zone_verifydb: zone huge.zone/IN: enter
01-Sep-2023 02:25:18.652 zone huge.zone/IN: loaded serial 1397051952
01-Sep-2023 02:25:18.652 zone_postload: zone huge.zone/IN: done
01-Sep-2023 02:25:18.652 any newly configured zones are now loaded
01-Sep-2023 02:25:18.652 FIPS mode is disabled
01-Sep-2023 02:25:18.652 zone__settimer: zone version.bind/CH: enter
01-Sep-2023 02:25:18.652 zone_timer_stop: zone version.bind/CH: stop zone timer
01-Sep-2023 02:25:18.652 zone__settimer: zone hostname.bind/CH: enter
01-Sep-2023 02:25:18.652 zone_timer_stop: zone hostname.bind/CH: stop zone timer
01-Sep-2023 02:25:18.652 zone__settimer: zone id.server/CH: enter
01-Sep-2023 02:25:18.652 running
Edited by Mark Andrews