slow zone transfer takes longer than expected in statschannel test
statschannel
system test recently became more unstable, failing on the following check:
2024-02-08 00:32:57 INFO:statschannel I:statschannel_tmp_0gqlueys:Wait for slow zone transfer to complete (29)
2024-02-08 00:33:16 INFO:statschannel I:statschannel_tmp_0gqlueys:exceeded time limit waiting for literal 'zone example/IN: zone transfer finished: success' in ns3/named.run
2024-02-08 00:33:16 INFO:statschannel I:statschannel_tmp_0gqlueys:failed
The check in question uses -T transferslowly
option which makes the code use select()
with a one second timeout to delay the individual packets. ns1
uses the transfer-format one-answer;
for the transfer to ns3
. The example.db
zone has 8 records and the check allows 20 second timeout, which should be more than sufficient. However, the records are delayed more than expected on the sending side:
08-Feb-2024 00:32:57.116 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': AXFR question section OK
08-Feb-2024 00:32:57.116 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': AXFR authority section OK
08-Feb-2024 00:32:57.116 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': AXFR started (serial 1)
08-Feb-2024 00:32:57.116 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': starting maxtime timer 7200000 ms
08-Feb-2024 00:32:57.116 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 77 bytes
08-Feb-2024 00:32:58.120 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 48 bytes
08-Feb-2024 00:32:59.124 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 48 bytes
08-Feb-2024 00:33:02.140 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 53 bytes
08-Feb-2024 00:33:05.152 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 785 bytes
08-Feb-2024 00:33:08.165 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 51 bytes
08-Feb-2024 00:33:11.177 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 50 bytes
08-Feb-2024 00:33:14.189 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 59 bytes
08-Feb-2024 00:33:17.201 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': sending TCP message of 71 bytes
08-Feb-2024 00:33:19.209 client @0x7b780001f800 10.53.0.3#41203 (example): transfer of 'example/IN': send: operation canceled
After the first three record are transmitted, each following record is delayed by just over 3 seconds (rather than 1 second). It could be caused by the load in the CI due to parallelization, but the fact this pattern (first 3 records have 1s delay, remaining record have 3s delay) repeats in another job makes this a bit suspicious:
08-Feb-2024 09:55:12.719 client @0x7f559a027000 10.53.0.3#46059 (example): transfer of 'example/IN': sending TCP message of 77 bytes
08-Feb-2024 09:55:13.719 client @0x7f559a027000 10.53.0.3#46059 (example): transfer of 'example/IN': sending TCP message of 48 bytes
08-Feb-2024 09:55:14.724 client @0x7f559a027000 10.53.0.3#46059 (example): transfer of 'example/IN': sending TCP message of 48 bytes
08-Feb-2024 09:55:17.728 client @0x7f559a027000 10.53.0.3#46059 (example): transfer of 'example/IN': sending TCP message of 53 bytes
08-Feb-2024 09:55:21.740 client @0x7f559a027000 10.53.0.3#46059 (example): transfer of 'example/IN': sending TCP message of 785 bytes
08-Feb-2024 09:55:24.748 client @0x7f559a027000 10.53.0.3#46059 (example): transfer of 'example/IN': sending TCP message of 51 bytes
08-Feb-2024 09:55:28.756 client @0x7f559a027000 10.53.0.3#46059 (example): transfer of 'example/IN': sending TCP message of 50 bytes
08-Feb-2024 09:55:31.765 client @0x7f559a027000 10.53.0.3#46059 (example): transfer of 'example/IN': sending TCP message of 59 bytes