[9.20] chg: test: 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.

Closes #5493

Backport of MR !10923

Merge branch 'backport-5493-algoroll-csk-step3-manual-unstable-test-9.20' into 'bind-9.20'

See merge request isc-projects/bind9!10929
This commit is contained in:
Matthijs Mekking 2025-09-02 13:40:47 +00:00
commit ec484f6727
8 changed files with 86 additions and 26 deletions

View file

@ -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 = [

View file

@ -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,

View file

@ -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,

View file

@ -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,

View file

@ -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,

View file

@ -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,

View file

@ -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

View file

@ -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