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 4e91565a78fd1bf3fc11cf8e83224fef6d558973..ad9b67f82c65077ccba096137d0cef7cd4786011 100644 (file)
--- 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 38527ad5e0dc21c2f2952f2ad9c79fbe9fa7ba67..eecf1ba855b6f10523a79db88544231bf06bfff8 100644 (file)
--- 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 9646dce7afca7e4b24a4877ac907888804d98941..ba77d799d5dfd4730bf97dc8bfe13e62a87a3d57 100644 (file)
--- 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 5f60cb048c44a775b052e0c5d150c24bd7730f57..b9c5861d86e0b74b0ac7c65f16453b162f304140 100644 (file)
--- 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 c8039453f61a046c25d8bd3b184c93ec4fab086e..f63c565fc0bef558e553f2d4da8c62b0b4834587 100644 (file)
--- 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 2cb805a6741add91684d21dd0ce7ab1c4af22dd2..e4d83be42f29b8d94b2aa3bd658245bf12699b06 100644 (file)
--- 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 90ebce96a6487edbc8c0a09cebb97ded2015fc22..9f01fdaca94b4363e5628a759b914f53585acac5 100644 (file)
--- 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 232be8f7f91c300556e85c993c37a25bab50b00b..c8643022e6ef26f6d222582b65f21398c7fa2a5a 100644 (file)
--- 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