timing issue in statschannel system test
In job #3207137 the statschannel
failed on check fetch zone 'dnssec' stats data after updating DNSKEY RRset (7)
.
The test expects 1 zsk sign operation and 1 ksk sign operation. These happen:
02-Mar-2023 09:10:06.228 add re-sign dnssec. 300 IN RRSIG DNSKEY 13 1 300 20230401091005 20230302081006 7913 dnssec. MT/JQRYMGsWYBwyRkdnj+tB7h2oSbpVfZ9n+DMr1oyDdXtRSoxGwydIO a2GRjUgP5kQ/N5JWUQMK2LkvThFvsA==
02-Mar-2023 09:10:06.228 add re-sign dnssec. 300 IN RRSIG SOA 13 1 300 20230401091006 20230302081006 35685 dnssec. unerVqERet0Xr8KV19/D174G3moa5NVkDoXIbvpc3cPQuzCd/z+eYC2h zuLlEZawAFe2NTI3jw+TDkIgKfpnCw==
Then the test waits for next key event
:
02-Mar-2023 09:10:06.228 zone dnssec/IN: next key event: 02-Mar-2023 10:10:06.220
However, 100 milliseconds later, before the test retrieves the zone statistics from the statschannel, additional signing operations take place:
02-Mar-2023 09:10:06.328 zone_maintenance: zone dnssec/IN: enter
02-Mar-2023 09:10:06.328 zone_resigninc: zone dnssec/IN: enter
02-Mar-2023 09:10:06.328 zone_journal: zone dnssec/IN: enter
02-Mar-2023 09:10:06.328 writing to journal
02-Mar-2023 09:10:06.328 del dnssec. 300 IN SOA mname1. . 4 20 20 1814400 3600
02-Mar-2023 09:10:06.328 del re-sign dnssec. 300 IN RRSIG NS 13 1 300 20230309211006 20230302080959 35685 dnssec. kaS58YnGbS/p3V8088p+yREiSINte5ETOr/3QvFU9XsHyuxDqRLkux6i XqY5/PSkQFm094MO/wNLdbTp8LaB2g==
02-Mar-2023 09:10:06.328 del re-sign a.dnssec. 300 IN RRSIG NSEC 13 2 300 20230309211006 20230302080959 35685 dnssec. 12MDX1o0qgh0T3SoM0aKsu6AjJYcueqHpOT//xD0l/EjFJgBOVu3VJpA 0OO3R/VdQzFeBq1tgY88dpLnTwvKUw==
02-Mar-2023 09:10:06.328 del re-sign a.dnssec. 300 IN RRSIG MX 13 2 300 20230309211006 20230302080959 35685 dnssec. vGNl05h/fsvnnHvU1RX3yUuCRS5Egqd9Mr5HxZ8J3uZAleQNVxUa+gG9 f9ZJ+q6+Zp8Kz8AFHqCxN1vMq0+5zw==
02-Mar-2023 09:10:06.332 del re-sign mail.dnssec. 300 IN RRSIG A 13 2 300 20230309211006 20230302080959 35685 dnssec. RRafXWoDHpbErUBXOVzI3rbREe8ezmj8QEHpHampjKVNJrfzFWbP1cku meg3TPsTCQdy/1v6v4cvfB03SusQoQ==
02-Mar-2023 09:10:06.332 del re-sign a.dnssec. 300 IN RRSIG A 13 2 300 20230309211006 20230302080959 35685 dnssec. ofun5lwcYTsK0OawryLIViK/sdJHPSHT7RxoQR5ErmkAPpjZvTIoE4EO ua95xdHE1X5h/hnJCBYPpl5kHS+Lfg==
02-Mar-2023 09:10:06.332 del re-sign mail.dnssec. 300 IN RRSIG NSEC 13 2 300 20230309211006 20230302080959 35685 dnssec. GspggAHIxa6RQMbauI4On2esTEWifodSorcCjxqlwtZ71XOF7LdtWTbw HLf5o1xYP76o2RRN3CAZRPmAOs1Lkw==
02-Mar-2023 09:10:06.332 del re-sign ns2.dnssec. 300 IN RRSIG NSEC 13 2 300 20230309211006 20230302080959 35685 dnssec. FJXd9+ncwyBxhrMpmAO3xs1sEGlP3g0EhmOk9IHa4/Ljgv6qIJYIL7hW dz2JbfYjI3oI+QqbCEM/5mIM9AO5Jw==
02-Mar-2023 09:10:06.332 del re-sign ns2.dnssec. 300 IN RRSIG A 13 2 300 20230309211006 20230302080959 35685 dnssec. gzliUistEykm6hpMGY8ForYJewFzaUB4rPOJxHROOupf8jaX+GhbelWU tfcnLKmjypuWEIdyFkGugFpzE/slCA==
02-Mar-2023 09:10:06.332 del re-sign dnssec. 300 IN RRSIG SOA 13 1 300 20230401091006 20230302081006 35685 dnssec. unerVqERet0Xr8KV19/D174G3moa5NVkDoXIbvpc3cPQuzCd/z+eYC2h zuLlEZawAFe2NTI3jw+TDkIgKfpnCw==
02-Mar-2023 09:10:06.332 add dnssec. 300 IN SOA mname1. . 5 20 20 1814400 3600
02-Mar-2023 09:10:06.332 add re-sign dnssec. 300 IN RRSIG NS 13 1 300 20230401084359 20230302081006 35685 dnssec. C+vYMDHLb6wperZxXwTAAK3vM9XJ+7/WAGddPyQcdI+fp6hRXL6UM4hz C5qj8+hnKY0E2bHq1jYLoQaw62M/mw==
02-Mar-2023 09:10:06.332 add re-sign a.dnssec. 300 IN RRSIG NSEC 13 2 300 20230401084359 20230302081006 35685 dnssec. h1X7d4NBfaVyRJnkzcsiyjAZPXufVBgKPw08wxAm8Zx1W8N5Tg0WS2/m Xx6MyytvPoCSFFvFOQLkCXurucZUww==
02-Mar-2023 09:10:06.332 add re-sign a.dnssec. 300 IN RRSIG MX 13 2 300 20230401084359 20230302081006 35685 dnssec. J5uy5bjeXLdt73gV8nv4/dbj+cjOIcyFHuh6Qp/sdqFE/sswo8izCdRU 3/iYmjwLS9EeNs6dEb2xx0l9heRmDg==
02-Mar-2023 09:10:06.332 add re-sign mail.dnssec. 300 IN RRSIG A 13 2 300 20230401084359 20230302081006 35685 dnssec. wCLJPDVyC8ja84GHqaA/OnUrOocpAKNOZiTQJdHJkwkkd0BbVxLazYiP fE2rKG54VIFvGxC/EcXavXcqiFeQEg==
02-Mar-2023 09:10:06.332 add re-sign a.dnssec. 300 IN RRSIG A 13 2 300 20230401084359 20230302081006 35685 dnssec. /BXz8YtxNfEo3tJYFGRHVjMQQDAtzZ8ne2nJOm6CQm3d803qzs5JaHLy /4hmNB5oTEz1l9kXw3LQnB94iuH/yA==
02-Mar-2023 09:10:06.332 add re-sign mail.dnssec. 300 IN RRSIG NSEC 13 2 300 20230401084359 20230302081006 35685 dnssec. QWpfnMgaVTitdgvpdIBTimLxJY+YUPcCvcQcVlnVta8FkmhSxgRhLkRs NGM9H1J5o+4K9uFwso3bSmLTADq1YA==
02-Mar-2023 09:10:06.332 add re-sign ns2.dnssec. 300 IN RRSIG NSEC 13 2 300 20230401084359 20230302081006 35685 dnssec. o/RJ6s2Jcccttnk2PxugOcjnyQ9kX9BfxEu5nKLZglAcaFAl7pnPjhNm 9455gOUH62iNPlxHS3KXrac8HuruIQ==
02-Mar-2023 09:10:06.332 add re-sign ns2.dnssec. 300 IN RRSIG A 13 2 300 20230401084359 20230302081006 35685 dnssec. E59RXGdRykOWp+Oad6UJ6DjIJDJT0vtX326pRcoW54obolq/sc2ZjCha GZk634z/MvcNFHWaQnF2rmtOj0SuGg==
02-Mar-2023 09:10:06.332 add re-sign dnssec. 300 IN RRSIG SOA 13 1 300 20230401091006 20230302081006 35685 dnssec. aSQQxKw8rg8Pbn6bacb22o993cEwzPXchCB9wQM4nLjMWq5VgW5JIQeG Tkz2VIWj9dPCQVRv4xKInZmBjHSwfg==
This results in the test detecting extra 9 signature operations which it doesn't expect and thus fails.