From: Matthijs Mekking <matthijs@isc.org>
Date: Mon, 1 Sep 2025 15:11:51 +0000 (+0200)
Subject: Wait for rekey_done log in rollover system tests
X-Git-Tag: v9.21.12~8^2
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=4141ae1275cb95c2cb617f193f2a772e3145eb33;p=thirdparty%2Fbind9.git

Wait for rekey_done log in rollover system tests

Waiting for "keymgr: done" logs caused some manual-mode tests to fail
intermittently. Waiting for "rekey done" logs should be more reliable.
---

diff --git a/bin/tests/system/kasp/tests_kasp.py b/bin/tests/system/kasp/tests_kasp.py
index 4e91565a78f..ad9b67f82c6 100644
--- a/bin/tests/system/kasp/tests_kasp.py
+++ b/bin/tests/system/kasp/tests_kasp.py
@@ -1753,7 +1753,9 @@ def test_kasp_manual_mode(ns3):
     # Force step.
     with ns3.watch_log_from_here() as watcher:
         ns3.rndc(f"dnssec -step {zone}", log=False)
-        watcher.wait_for_line(f"keymgr: {zone} done")
+        watcher.wait_for_line(
+            f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+        )
 
     # Check keys again, make sure the rollover has started.
     keyprops = [
diff --git a/bin/tests/system/rollover-algo-csk/tests_rollover_algo_csk_reconfig.py b/bin/tests/system/rollover-algo-csk/tests_rollover_algo_csk_reconfig.py
index 38527ad5e0d..eecf1ba855b 100644
--- a/bin/tests/system/rollover-algo-csk/tests_rollover_algo_csk_reconfig.py
+++ b/bin/tests/system/rollover-algo-csk/tests_rollover_algo_csk_reconfig.py
@@ -88,7 +88,9 @@ def test_algoroll_csk_reconfig_step1(tld, ns6, alg, size):
         # Force step.
         with ns6.watch_log_from_here() as watcher:
             ns6.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/RSASHA256"
+            )
 
     # Check state after step.
     step = {
@@ -178,7 +180,9 @@ def test_algoroll_csk_reconfig_step3(tld, ns6, alg, size):
         # Force step.
         with ns6.watch_log_from_here() as watcher:
             ns6.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
         # Check logs.
         tag = keys[0].key.tag
@@ -188,9 +192,12 @@ def test_algoroll_csk_reconfig_step3(tld, ns6, alg, size):
             isctest.log.debug(
                 f"keymgr-manual-mode blocking transition CSK {zone}/RSASHA256/{tag} type DS state OMNIPRESENT to state UNRETENTIVE, step again"
             )
+            tag = keys[1].key.tag
             with ns6.watch_log_from_here() as watcher:
                 ns6.rndc(f"dnssec -step {zone}")
-                watcher.wait_for_line(f"keymgr: {zone} done")
+                watcher.wait_for_line(
+                    f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+                )
 
     step = {
         "zone": zone,
@@ -240,9 +247,12 @@ def test_algoroll_csk_reconfig_step4(tld, ns6, alg, size):
         ns6.log.expect(msg)
 
         # Force step.
+        tag = keys[1].key.tag
         with ns6.watch_log_from_here() as watcher:
             ns6.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         "zone": zone,
diff --git a/bin/tests/system/rollover-algo-ksk-zsk/tests_rollover_algo_ksk_zsk_reconfig.py b/bin/tests/system/rollover-algo-ksk-zsk/tests_rollover_algo_ksk_zsk_reconfig.py
index 9646dce7afc..ba77d799d5d 100644
--- a/bin/tests/system/rollover-algo-ksk-zsk/tests_rollover_algo_ksk_zsk_reconfig.py
+++ b/bin/tests/system/rollover-algo-ksk-zsk/tests_rollover_algo_ksk_zsk_reconfig.py
@@ -92,7 +92,9 @@ def test_algoroll_ksk_zsk_reconfig_step1(tld, ns6, alg, size):
         # Force step.
         with ns6.watch_log_from_here() as watcher:
             ns6.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {ktag}/RSASHA256"
+            )
 
     step = {
         "zone": zone,
@@ -187,7 +189,9 @@ def test_algoroll_ksk_zsk_reconfig_step3(tld, ns6, alg, size):
         # Force step.
         with ns6.watch_log_from_here() as watcher:
             ns6.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
         # Check logs.
         tag = keys[0].key.tag
@@ -197,9 +201,12 @@ def test_algoroll_ksk_zsk_reconfig_step3(tld, ns6, alg, size):
             isctest.log.debug(
                 f"keymgr-manual-mode blocking transition CSK {zone}/RSASHA256/{tag} type DS state OMNIPRESENT to state UNRETENTIVE, step again"
             )
+            tag = keys[2].key.tag
             with ns6.watch_log_from_here() as watcher:
                 ns6.rndc(f"dnssec -step {zone}")
-                watcher.wait_for_line(f"keymgr: {zone} done")
+                watcher.wait_for_line(
+                    f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+                )
 
     step = {
         "zone": zone,
@@ -256,9 +263,12 @@ def test_algoroll_ksk_zsk_reconfig_step4(tld, ns6, alg, size):
         ns6.log.expect(msg2)
 
         # Force step.
+        ktag = keys[3].key.tag
         with ns6.watch_log_from_here() as watcher:
             ns6.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {ktag}/ECDSAP256SHA256"
+            )
 
     step = {
         "zone": zone,
diff --git a/bin/tests/system/rollover-csk-roll1/tests_rollover_csk_roll1.py b/bin/tests/system/rollover-csk-roll1/tests_rollover_csk_roll1.py
index 5f60cb048c4..b9c5861d86e 100644
--- a/bin/tests/system/rollover-csk-roll1/tests_rollover_csk_roll1.py
+++ b/bin/tests/system/rollover-csk-roll1/tests_rollover_csk_roll1.py
@@ -130,7 +130,9 @@ def test_csk_roll1_step2(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         # Successor CSK is prepublished (signs DNSKEY RRset, but not yet
@@ -188,7 +190,9 @@ def test_csk_roll1_step3(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
         # Check logs.
         tag = keys[0].key.tag
@@ -200,7 +204,9 @@ def test_csk_roll1_step3(tld, alg, size, ns3):
             )
             with ns3.watch_log_from_here() as watcher:
                 ns3.rndc(f"dnssec -step {zone}")
-                watcher.wait_for_line(f"keymgr: {zone} done")
+                watcher.wait_for_line(
+                    f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+                )
 
     step = {
         # Successor CSK becomes omnipresent, meaning we can start signing
@@ -272,9 +278,12 @@ def test_csk_roll1_step4(tld, alg, size, ns3):
         ns3.log.expect(msg)
 
         # Force step.
+        tag = keys[1].key.tag
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         "zone": zone,
diff --git a/bin/tests/system/rollover-csk-roll2/tests_rollover_csk_roll2.py b/bin/tests/system/rollover-csk-roll2/tests_rollover_csk_roll2.py
index c8039453f61..f63c565fc0b 100644
--- a/bin/tests/system/rollover-csk-roll2/tests_rollover_csk_roll2.py
+++ b/bin/tests/system/rollover-csk-roll2/tests_rollover_csk_roll2.py
@@ -133,7 +133,9 @@ def test_csk_roll2_step2(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         # Successor CSK is prepublished (signs DNSKEY RRset, but not yet
@@ -191,7 +193,9 @@ def test_csk_roll2_step3(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
         # Check logs.
         tag = keys[0].key.tag
@@ -203,7 +207,9 @@ def test_csk_roll2_step3(tld, alg, size, ns3):
             )
             with ns3.watch_log_from_here() as watcher:
                 ns3.rndc(f"dnssec -step {zone}")
-                watcher.wait_for_line(f"keymgr: {zone} done")
+                watcher.wait_for_line(
+                    f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+                )
 
     step = {
         # Successor CSK becomes omnipresent, meaning we can start signing
@@ -313,9 +319,12 @@ def test_csk_roll2_step5(tld, alg, size, ns3):
         ns3.log.expect(msg2)
 
         # Force step.
+        tag = keys[1].key.tag
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         "zone": zone,
diff --git a/bin/tests/system/rollover-enable-dnssec/tests_rollover_enable_dnssec.py b/bin/tests/system/rollover-enable-dnssec/tests_rollover_enable_dnssec.py
index 2cb805a6741..e4d83be42f2 100644
--- a/bin/tests/system/rollover-enable-dnssec/tests_rollover_enable_dnssec.py
+++ b/bin/tests/system/rollover-enable-dnssec/tests_rollover_enable_dnssec.py
@@ -160,7 +160,9 @@ def test_rollover_enable_dnssec_step3(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         "zone": zone,
diff --git a/bin/tests/system/rollover-ksk-doubleksk/tests_rollover_ksk_doubleksk.py b/bin/tests/system/rollover-ksk-doubleksk/tests_rollover_ksk_doubleksk.py
index 90ebce96a64..9f01fdaca94 100644
--- a/bin/tests/system/rollover-ksk-doubleksk/tests_rollover_ksk_doubleksk.py
+++ b/bin/tests/system/rollover-ksk-doubleksk/tests_rollover_ksk_doubleksk.py
@@ -115,7 +115,9 @@ def test_ksk_doubleksk_step2(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         # Successor KSK is prepublished (and signs DNSKEY RRset).
@@ -174,7 +176,9 @@ def test_ksk_doubleksk_step3(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
         # Check logs.
         tag = keys[1].key.tag
@@ -186,7 +190,9 @@ def test_ksk_doubleksk_step3(tld, alg, size, ns3):
             )
             with ns3.watch_log_from_here() as watcher:
                 ns3.rndc(f"dnssec -step {zone}")
-                watcher.wait_for_line(f"keymgr: {zone} done")
+                watcher.wait_for_line(
+                    f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+                )
 
     step = {
         # The successor DNSKEY RRset has become omnipresent.  The
@@ -250,9 +256,12 @@ def test_ksk_doubleksk_step4(tld, alg, size, ns3):
         ns3.log.expect(msg2)
 
         # Force step.
+        tag = keys[2].key.tag
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         # The predecessor DNSKEY may be removed, the successor DS is
diff --git a/bin/tests/system/rollover-zsk-prepub/tests_rollover_zsk_prepublication.py b/bin/tests/system/rollover-zsk-prepub/tests_rollover_zsk_prepublication.py
index 232be8f7f91..c8643022e6e 100644
--- a/bin/tests/system/rollover-zsk-prepub/tests_rollover_zsk_prepublication.py
+++ b/bin/tests/system/rollover-zsk-prepub/tests_rollover_zsk_prepublication.py
@@ -122,7 +122,9 @@ def test_zsk_prepub_step2(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         # it is time to pre-publish the successor zsk.
@@ -179,7 +181,9 @@ def test_zsk_prepub_step3(tld, alg, size, ns3):
         # Force step.
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
         # Check logs.
         tag = keys[1].key.tag
@@ -191,7 +195,9 @@ def test_zsk_prepub_step3(tld, alg, size, ns3):
             )
             with ns3.watch_log_from_here() as watcher:
                 ns3.rndc(f"dnssec -step {zone}")
-                watcher.wait_for_line(f"keymgr: {zone} done")
+                watcher.wait_for_line(
+                    f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+                )
 
     step = {
         # predecessor zsk is no longer actively signing. successor zsk is
@@ -251,9 +257,12 @@ def test_zsk_prepub_step4(tld, alg, size, ns3):
         ns3.log.expect(msg)
 
         # Force step.
+        tag = keys[2].key.tag
         with ns3.watch_log_from_here() as watcher:
             ns3.rndc(f"dnssec -step {zone}")
-            watcher.wait_for_line(f"keymgr: {zone} done")
+            watcher.wait_for_line(
+                f"zone {zone}/IN (signed): zone_rekey done: key {tag}/ECDSAP256SHA256"
+            )
 
     step = {
         # predecessor zsk is no longer needed. all rrsets are signed with