"manykeys" zone gets resigned twice during a single "statschannel" system test run
https://gitlab.isc.org/isc-private/bind9/-/jobs/2819986
Click to expand/collapse test output
S:statschannel:2022-10-10T10:13:28+0000
T:statschannel:1:A
A:statschannel:System test statschannel
I:statschannel:PORTS:10363,10364,10365,10366,10367,10368,10369,10370,10371,10372,10373,10374,10375
I:statschannel:starting servers
I:statschannel:checking consistency between named.stats and xml/json (1)
I:statschannel:checking malloced memory statistics xml/json (2)
I:statschannel:checking consistency between regular and compressed output (3)
I:statschannel:checking if compressed output is really compressed (4)
I:statschannel:fetching zone 'dnssec' stats data after zone maintenance at startup (5)
I:statschannel:... using xml
I:statschannel:... using json
I:statschannel:fetching zone 'dnssec' stats data after dynamic update (6)
I:statschannel:... using xml
I:statschannel:... using json
I:statschannel:fetch zone 'dnssec' stats data after updating DNSKEY RRset (7)
I:statschannel:... using xml
I:statschannel:... using json
I:statschannel:fetching zone 'manykeys' stats data after zone maintenance at startup (8)
I:statschannel:... using xml
zones.out.x8 zones.expect.8 differ: char 37, line 1
I:statschannel:... using json
zones.out.j8 zones.expect.8 differ: char 37, line 1
I:statschannel:failed
I:statschannel:fetching zone 'manykeys' stats data after dynamic update (9)
I:statschannel:... using xml
zones.out.x9 zones.expect.9 differ: char 37, line 1
I:statschannel:... using json
zones.out.j9 zones.expect.9 differ: char 37, line 1
I:statschannel:failed
I:ns2 server reload successful
I:statschannel:fetching zone 'manykeys' stats data after dnssec-policy change (10)
I:statschannel:... using xml
zones.out.x10 zones.expect.10 differ: char 34, line 1
I:statschannel:... using json
zones.out.j10 zones.expect.10 differ: char 34, line 1
I:statschannel:failed
I:statschannel:Check HTTP/1.1 pipelined requests are handled (GET) (11)
I:statschannel:Check HTTP/1.1 pipelined requests are handled (POST) (12)
I:statschannel:Check HTTP/1.1 pipelined with truncated stream (13)
I:statschannel:exit status: 3
I:statschannel:stopping servers
R:statschannel:FAIL
E:statschannel:2022-10-10T10:13:48+0000
FAIL statschannel (exit status: 1)
$ diff -u zones.expect.8 zones.out.j8
--- zones.expect.8 2022-10-10 12:13:39.000000000 +0200
+++ zones.out.x8 2022-10-10 12:13:40.000000000 +0200
@@ -1,12 +1,12 @@
-dnssec-refresh operations 13+13146: 10
-dnssec-refresh operations 13+35376: 1
-dnssec-refresh operations 14+13156: 10
-dnssec-refresh operations 14+65001: 1
-dnssec-refresh operations 8+498: 10
-dnssec-refresh operations 8+5755: 1
-dnssec-sign operations 13+13146: 10
-dnssec-sign operations 13+35376: 1
-dnssec-sign operations 14+13156: 10
-dnssec-sign operations 14+65001: 1
-dnssec-sign operations 8+498: 10
-dnssec-sign operations 8+5755: 1
+dnssec-refresh operations 13+13146: 20
+dnssec-refresh operations 13+35376: 2
+dnssec-refresh operations 14+13156: 20
+dnssec-refresh operations 14+65001: 2
+dnssec-refresh operations 8+498: 20
+dnssec-refresh operations 8+5755: 2
+dnssec-sign operations 13+13146: 20
+dnssec-sign operations 13+35376: 2
+dnssec-sign operations 14+13156: 20
+dnssec-sign operations 14+65001: 2
+dnssec-sign operations 8+498: 20
+dnssec-sign operations 8+5755: 2
Looking at ns2/named.run
, it looks like the signatures were
unexpectedly refreshed twice: first at 10:13:30 and then again, ten
seconds later (at 10:13:40). Sample log excerpts for a single RRset:
$ grep -E '(add|del) re-sign mail\.manykeys\..*A 13.*13146' ns2/named.run
10-Oct-2022 10:13:30.523 del re-sign mail.manykeys. 300 IN RRSIG A 13 2 300 20221010101330 20221010091329 13146 manykeys. d3FRyKl8rOtAf/X760MtA34ekLMhPkK4kwXWu16bnHDXP+CFv3bHmIUo 3GlOU64YOY0sd1zdw1byjqD7uz84Gw==
10-Oct-2022 10:13:30.523 add re-sign mail.manykeys. 300 IN RRSIG A 13 2 300 20221015101340 20221010091330 13146 manykeys. 1nY6w6eOfvFvKQtkznuuB2sUPXy0Y8OCudY3bHl3+j4Atxbzwwp8hNRE bMOkm6b68Z9x9a82Xii3n5EE0vwDXA==
10-Oct-2022 10:13:40.079 del re-sign mail.manykeys. 300 IN RRSIG A 13 2 300 20221015101340 20221010091330 13146 manykeys. 1nY6w6eOfvFvKQtkznuuB2sUPXy0Y8OCudY3bHl3+j4Atxbzwwp8hNRE bMOkm6b68Z9x9a82Xii3n5EE0vwDXA==
10-Oct-2022 10:13:40.079 add re-sign mail.manykeys. 300 IN RRSIG A 13 2 300 20221024092343 20221010091340 13146 manykeys. 1oAQSc/D2yrMPekGrtLwFoMCGJj0UkF7XnWmPPV7o+snZij5dZCdrIjA cZlhzdOGA4VZvloE5a+p6EY1Mw/M3g==
10-Oct-2022 10:13:44.407 del re-sign mail.manykeys. 300 IN RRSIG A 13 2 300 20221024092343 20221010091340 13146 manykeys. 1oAQSc/D2yrMPekGrtLwFoMCGJj0UkF7XnWmPPV7o+snZij5dZCdrIjA cZlhzdOGA4VZvloE5a+p6EY1Mw/M3g==
This is what the same command outputs when the test passes:
$ grep -E '(add|del) re-sign mail\.manykeys\..*A 13.*15554' ns2/named.run
10-Oct-2022 15:41:21.833 del re-sign mail.manykeys. 300 IN RRSIG A 13 2 300 20221010134122 20221010124121 15554 manykeys. FQQc1UmPh0TVCJSBfb64Mw7btRfTpAr7CyFku52KUyJPmkCXBATY3tVg ksPoFHRs8YTp5dC6+jwmhEznH6JULg==
10-Oct-2022 15:41:21.833 add re-sign mail.manykeys. 300 IN RRSIG A 13 2 300 20221017201301 20221010124121 15554 manykeys. JIg+WRo5qf7a4A0J7bJ7Ug4BZIbUkDzG38ohjfNlG2JuDTYGlr92/gU+ uThPRYFN65ki7nChpV7TlwdojT1M4A==
10-Oct-2022 15:41:54.516 del re-sign mail.manykeys. 300 IN RRSIG A 13 2 300 20221017201301 20221010124121 15554 manykeys. JIg+WRo5qf7a4A0J7bJ7Ug4BZIbUkDzG38ohjfNlG2JuDTYGlr92/gU+ uThPRYFN65ki7nChpV7TlwdojT1M4A==
Seems to me like something made zone_resigninc()
believe that
signatures generated 10 seconds earlier are outdated and need to be
refreshed.