KASP views: only one view started signing when policy was for both.
Job #903708 failed for 79790edb:
example.net was supposed to be signed in both views (example1 and example2) but only example2 succeeded in signing example.net.
I:kasp:dnssec-verify zone override.none.unsigned (352)
I:kasp:wait for example.net to be signed (353)
I:kasp:error: wait for example.net to be signed failed
I:kasp:failed
I:kasp:check keys are created for zone example.net (354)
I:kasp:check number of keys for zone example.net in dir ns4 (355)
I:kasp:check key id 19778
I:kasp:KEY1 ID 19778
I:kasp:check DNSKEY rrset is signed correctly for zone example.net (356)
I:kasp:error: missing DNSKEY record in response for key 19778
I:kasp:error: DNSKEY RRset not signed with key 19778
I:kasp:error: DNSKEY RRset not signed with key 19778
I:kasp:failed
I:kasp:check SOA rrset is signed correctly for zone example.net (357)
I:kasp:error: SOA RRset not signed with key 19778
I:kasp:failed
I:kasp:check CDS and CDNSKEY rrset are signed correctly for zone example.net (358)
I:kasp:dnssec-verify zone example.net (359)
Zone contains no DNSSEC keys
I:kasp:error: dnssec verify zone example.net failed
I:kasp:failed
I:kasp:check TXT example.net (view example1) rrset is signed correctly (360)
I:kasp:error: TXT RRset not signed with key 19778
I:kasp:failed
I:kasp:wait for example.net to be signed (361)set_zone "override.none.unsigned"
set_policy "test" "1" "3600"
set_server "ns5" "10.53.0.5"
TSIG="hmac-sha256:sha256:$SHA256"
wait_for_nsec
check_keys
check_apex
check_subdomain
dnssec_verify
set_zone "example.net"
set_server "ns4" "10.53.0.4"
TSIG="hmac-sha1:keyforview1:$VIEW1"
wait_for_nsec
check_keys
check_apex
dnssec_verify
n=$((n+1))
# check subdomain
echo_i "check TXT example.net (view example1) rrset is signed correctly ($n)"
ret=0
dig_with_opts "view.${ZONE}" "@${SERVER}" TXT > "dig.out.$DIR.test$n.txt" || log_error "dig view.${ZONE} TXT failed"
grep "status: NOERROR" "dig.out.$DIR.test$n.txt" > /dev/null || log_error "mismatch status in DNS response"
grep "view.${ZONE}\..*${DEFAULT_TTL}.*IN.*TXT.*view1" "dig.out.$DIR.test$n.txt" > /dev/null || log_error "missing view.${ZONE} TXT record in response"
check_signatures TXT "dig.out.$DIR.test$n.txt" "ZSK"
test "$ret" -eq 0 || echo_i "failed"
status=$((status+ret))
TSIG="hmac-sha1:keyforview2:$VIEW2"
wait_for_nsec
check_keys
check_apex
dnssec_verify
n=$((n+1))
# check subdomain
echo_i "check TXT example.net (view example2) rrset is signed correctly ($n)"
ret=0
dig_with_opts "view.${ZONE}" "@${SERVER}" TXT > "dig.out.$DIR.test$n.txt" || log_error "dig view.${ZONE} TXT failed"
grep "status: NOERROR" "dig.out.$DIR.test$n.txt" > /dev/null || log_error "mismatch status in DNS response"
grep "view.${ZONE}\..*${DEFAULT_TTL}.*IN.*TXT.*view2" "dig.out.$DIR.test$n.txt" > /dev/null || log_error "missing view.${ZONE} TXT record in response"
check_signatures TXT "dig.out.$DIR.test$n.txt" "ZSK"
test "$ret" -eq 0 || echo_i "failed"
status=$((status+ret))25-May-2020 23:37:21.898 zone example.net/IN/example1: reconfiguring zone keys
25-May-2020 23:37:21.898 zone example.net/IN/example2: reconfiguring zone keys
25-May-2020 23:37:21.902 zone example.net/IN/example1: zone_rekey:dns_dnssec_findmatchingkeys failed: not found
25-May-2020 23:37:21.902 keymgr: keyring empty (zone example.net policy test)
25-May-2020 23:37:21.902 keymgr: no active key found for example.net (policy test)
25-May-2020 23:37:21.902 keymgr: DNSKEY example.net/ECDSAP384SHA384/19778 (CSK) created for policy test
25-May-2020 23:37:21.902 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type DNSKEY in state HIDDEN
25-May-2020 23:37:21.902 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type DNSKEY state HIDDEN to state RUMOURED?
25-May-2020 23:37:21.902 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record DNSKEY: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.902 keymgr: transition CSK example.net/ECDSAP384SHA384/19778 type DNSKEY state HIDDEN to state RUMOURED!
25-May-2020 23:37:21.902 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG in state HIDDEN
25-May-2020 23:37:21.902 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG state HIDDEN to state RUMOURED?
25-May-2020 23:37:21.902 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record ZRRSIG: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.902 keymgr: transition CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG state HIDDEN to state RUMOURED!
25-May-2020 23:37:21.902 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type KRRSIG in state HIDDEN
25-May-2020 23:37:21.902 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type KRRSIG state HIDDEN to state RUMOURED?
25-May-2020 23:37:21.902 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record KRRSIG: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.902 keymgr: transition CSK example.net/ECDSAP384SHA384/19778 type KRRSIG state HIDDEN to state RUMOURED!
25-May-2020 23:37:21.902 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type DS in state HIDDEN
25-May-2020 23:37:21.902 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type DS state HIDDEN to state RUMOURED?
25-May-2020 23:37:21.902 keymgr: policy says no to CSK example.net/ECDSAP384SHA384/19778 type DS state HIDDEN to state RUMOURED
25-May-2020 23:37:21.906 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type DNSKEY in state RUMOURED
25-May-2020 23:37:21.906 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type DNSKEY state RUMOURED to state OMNIPRESENT?
25-May-2020 23:37:21.906 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record DNSKEY: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.906 keymgr: time says no to CSK example.net/ECDSAP384SHA384/19778 type DNSKEY state RUMOURED to state OMNIPRESENT (wait 7500 seconds)
25-May-2020 23:37:21.906 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG in state RUMOURED
25-May-2020 23:37:21.906 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG state RUMOURED to state OMNIPRESENT?
25-May-2020 23:37:21.906 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record ZRRSIG: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.906 keymgr: time says no to CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG state RUMOURED to state OMNIPRESENT (wait 90300 seconds)
25-May-2020 23:37:21.906 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type KRRSIG in state RUMOURED
25-May-2020 23:37:21.906 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type KRRSIG state RUMOURED to state OMNIPRESENT?
25-May-2020 23:37:21.906 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record KRRSIG: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.906 keymgr: time says no to CSK example.net/ECDSAP384SHA384/19778 type KRRSIG state RUMOURED to state OMNIPRESENT (wait 7500 seconds)
25-May-2020 23:37:21.906 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type DS in state HIDDEN
25-May-2020 23:37:21.906 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type DS state HIDDEN to state RUMOURED?
25-May-2020 23:37:21.906 keymgr: policy says no to CSK example.net/ECDSAP384SHA384/19778 type DS state HIDDEN to state RUMOURED
25-May-2020 23:37:21.906 keymgr: keyring: dnskey example.net/ECDSAP384SHA384/19778 (policy test)
25-May-2020 23:37:21.906 keymgr: DNSKEY example.net/ECDSAP384SHA384/19778 (CSK) matches policy test
25-May-2020 23:37:21.906 keymgr: DNSKEY example.net/ECDSAP384SHA384/19778 (CSK) is active in policy test
25-May-2020 23:37:21.906 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type DNSKEY in state RUMOURED
25-May-2020 23:37:21.906 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type DNSKEY state RUMOURED to state OMNIPRESENT?
25-May-2020 23:37:21.906 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record DNSKEY: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.906 keymgr: time says no to CSK example.net/ECDSAP384SHA384/19778 type DNSKEY state RUMOURED to state OMNIPRESENT (wait 7500 seconds)
25-May-2020 23:37:21.906 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG in state RUMOURED
25-May-2020 23:37:21.906 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG state RUMOURED to state OMNIPRESENT?
25-May-2020 23:37:21.906 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record ZRRSIG: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.906 keymgr: time says no to CSK example.net/ECDSAP384SHA384/19778 type ZRRSIG state RUMOURED to state OMNIPRESENT (wait 90300 seconds)
25-May-2020 23:37:21.906 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type KRRSIG in state RUMOURED
25-May-2020 23:37:21.906 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type KRRSIG state RUMOURED to state OMNIPRESENT?
25-May-2020 23:37:21.906 keymgr: dnssec evaluation of CSK example.net/ECDSAP384SHA384/19778 record KRRSIG: rule1=(~false or false) rule2=(~true or true) rule3=(~true or true)
25-May-2020 23:37:21.906 keymgr: time says no to CSK example.net/ECDSAP384SHA384/19778 type KRRSIG state RUMOURED to state OMNIPRESENT (wait 7500 seconds)
25-May-2020 23:37:21.906 keymgr: examine CSK example.net/ECDSAP384SHA384/19778 type DS in state HIDDEN
25-May-2020 23:37:21.906 keymgr: can we transition CSK example.net/ECDSAP384SHA384/19778 type DS state HIDDEN to state RUMOURED?
25-May-2020 23:37:21.906 keymgr: policy says no to CSK example.net/ECDSAP384SHA384/19778 type DS state HIDDEN to state RUMOURED
[key read failure]
25-May-2020 23:37:21.906 dns_dnssec_findzonekeys2: error reading Kexample.net.+014+19778.private: end of file
25-May-2020 23:37:21.906 zone example.net/IN/example1: sign_apex:dns__zone_findkeys -> end of file
25-May-2020 23:37:21.906 zone_settimer: zone example.net/IN/example1: enter
25-May-2020 23:37:21.906 Fetching example.net/ECDSAP384SHA384/19778 (CSK) from key repository.
25-May-2020 23:37:21.906 DNSKEY example.net/ECDSAP384SHA384/19778 (CSK) is now published
25-May-2020 23:37:21.906 DNSKEY example.net/ECDSAP384SHA384/19778 (CSK) is now active
...
25-May-2020 23:37:21.918 zone_journal: zone example.net/IN/example2: enter
25-May-2020 23:37:21.918 journal file example2.db.jnl does not exist, creating it
25-May-2020 23:37:21.918 writing to journal
25-May-2020 23:37:21.918 del example.net. 300 IN SOA mname1. . 1 20 20 1814400 3600
25-May-2020 23:37:21.918 add example.net. 300 IN SOA mname1. . 2 20 20 1814400 3600
25-May-2020 23:37:21.918 add re-sign example.net. 3600 IN RRSIG DNSKEY 14 2 3600 20200608233721 20200525223721 19778 example.net. AHPN1pNiPLPBRrWHkKSSuD8eWKaqq7aFDQwynSoay+9dBxoGiI8BFhwR SQ8Uku5Y2jDwPn5nDuvN0Nvh7Omq+BiSUWhI+PRM/z0sglMi7RMxctC4 M+wJbsbI7YmAW1KT
25-May-2020 23:37:21.918 add re-sign example.net. 0 IN RRSIG TYPE65534 14 2 0 20200608233721 20200525223721 19778 example.net. 6Lk7Bkmme9tp1U5DSoNJ/2jyyujdmGeDEOdSjTSg81Ajmh3/k5Shz3UK QqrGZPLmJZ4I0q/UyiYt13CXQOPF3ZzXIeCB9TC4qkSvjWSuTSzHLPmF Rz9s68CtwKMCxhzW
25-May-2020 23:37:21.918 add re-sign example.net. 300 IN RRSIG SOA 14 2 300 20200608233721 20200525223721 19778 example.net. ZtWdbyf2mDjqd4ahChSQIZcY8fLJ2tPZqjUa1CQNrvn27sUVH5v6M2h0 tL2FDAiKOJiv0gUrMhOC87rxAkThaIOpAT/LG0oMEfvjXXu1UYzPaPAR F4mkKnQVPHEwJMLp
25-May-2020 23:37:21.918 add example.net. 3600 IN DNSKEY 257 3 14 TEEOTTNdzuL5C0AA1eGvZaMNPCGmTtRDNDVmbKws6JJ6G+kWd2bqVAWI Czc6Y3ni25L9dN34OBkAHkCh1NM5AoN+Jzp5HdNcRh9Nsw4mntNFu+3M H/qNn7IIhfwwM1vz
25-May-2020 23:37:21.918 add example.net. 0 IN TYPE65534 \# 5 0E4D420000
25-May-2020 23:37:22.318 zone_settimer: zone example.net/IN/example2: enter
25-May-2020 23:37:22.318 zone_settimer: zone example.net/IN/example2: enter
25-May-2020 23:37:22.318 zone_settimer: zone example.net/IN/example2: enter
25-May-2020 23:37:22.318 zone example.net/IN/example2: next key event in 7500 seconds
25-May-2020 23:37:22.318 zone example.net/IN/example2: next key event: 26-May-2020 01:42:21.898
25-May-2020 23:37:22.318 zone_settimer: zone example.net/IN/example2: enter
25-May-2020 23:37:22.318 zone_timer: zone example.net/IN/example2: enter
25-May-2020 23:37:22.318 zone_maintenance: zone example.net/IN/example2: enter
25-May-2020 23:37:22.318 zone_sign: zone example.net/IN/example2: enter
25-May-2020 23:37:22.338 zone_journal: zone example.net/IN/example2: enter
25-May-2020 23:37:22.338 writing to journal
25-May-2020 23:37:22.338 del example.net. 300 IN SOA mname1. . 2 20 20 1814400 3600
25-May-2020 23:37:22.338 del re-sign example.net. 0 IN RRSIG TYPE65534 14 2 0 20200608233721 20200525223721 19778 example.net. 6Lk7Bkmme9tp1U5DSoNJ/2jyyujdmGeDEOdSjTSg81Ajmh3/k5Shz3UK QqrGZPLmJZ4I0q/UyiYt13CXQOPF3ZzXIeCB9TC4qkSvjWSuTSzHLPmF Rz9s68CtwKMCxhzW
25-May-2020 23:37:22.338 del re-sign example.net. 300 IN RRSIG SOA 14 2 300 20200608233721 20200525223721 19778 example.net. ZtWdbyf2mDjqd4ahChSQIZcY8fLJ2tPZqjUa1CQNrvn27sUVH5v6M2h0 tL2FDAiKOJiv0gUrMhOC87rxAkThaIOpAT/LG0oMEfvjXXu1UYzPaPAR F4mkKnQVPHEwJMLp
25-May-2020 23:37:22.338 del example.net. 0 IN TYPE65534 \# 5 0E4D420000
25-May-2020 23:37:22.338 add example.net. 300 IN SOA mname1. . 3 20 20 1814400 3600
25-May-2020 23:37:22.338 add re-sign example.net. 300 IN RRSIG NS 14 2 300 20200606134700 20200525223722 19778 example.net. SxpQl+kWc3DaF1YzsaYmokBxvLZSjtTA3viYulQ98pSomLpJsEM9pA/r CZo2mlKvuUjBq5i3UpgV/Bo+MT6CrsvI1nzwb3VCA4viAoWaTGvqoVMm vtcx7dQdTnnhhCmP
25-May-2020 23:37:22.338 add re-sign ns4.example.net. 3600 IN RRSIG NSEC 14 3 3600 20200606134700 20200525223722 19778 example.net. 6nZD7wqpaUnHbnQwAS7WY0pPqr/LEpvkJtoDC2bdu/mVSSqhHkE8Bo63 CrTMAWAtdKQ9F02Eta6FNgjL1tXNJpd7FOBpR9HdrHZYgxxf6RqT1Cyq JvWSR2y97ga+MIPA
25-May-2020 23:37:22.338 add re-sign ns4.example.net. 300 IN RRSIG A 14 3 300 20200606134700 20200525223722 19778 example.net. 4wenD6hbHJoyzxcAmE3fML7pY/Uf+l9URT/lcZxSFXYbKuFsntFUaZdL Ot43v2VeKMaSQJ0WZbRVmWb6yAQOsmbrwiKIx7PheLAmajJxwO9v1Z7N MUSaL9/cE5Z6FU65
25-May-2020 23:37:22.338 add re-sign view.example.net. 3600 IN RRSIG NSEC 14 3 3600 20200606134700 20200525223722 19778 example.net. YVUwfqmUz9X0PLAcT0YWXe85vp1qp42pft+x24UM5zETrfVywXqZj1LJ GAswQILyaj8Nq9uH6JTIB20HIghjYaR5J4608xHov+wu4hs7YjoSFcWk +L5Zz1iYZPTouQmM
25-May-2020 23:37:22.338 add re-sign view.example.net. 300 IN RRSIG TXT 14 3 300 20200606134700 20200525223722 19778 example.net. EoRsqC/50MPHMc3yVCIB95Tty+uKXeQ96qq5DwvCs0jfhR0VRhYaMUk3 DI0CUCDD6k8tAYyj4WpDCTWSQoSFDB+YpYl5bA5ruX+g6Z6/EYRayMND jRE+7lBexK4PCRmT
25-May-2020 23:37:22.338 add re-sign example.net. 3600 IN RRSIG NSEC 14 2 3600 20200606134700 20200525223722 19778 example.net. vf4VJyOBQ+I2Isutgdz9sa4GdS7Lok9IfDnWsn6FqtG2Uk9zU1MFvnL2 8fvVr0VNu8SLBn9XbMNaOES0CMGbIsA5Chfz8oZmP30ut/2tSbr86d/G fdZeyFMWdMXPjKsy
25-May-2020 23:37:22.338 add re-sign example.net. 0 IN RRSIG TYPE65534 14 2 0 20200606134700 20200525223722 19778 example.net. SpkVjCbqdoiZU+HmbUyjXBebD2Nne4U0Gl6iOvi0rODseCI/ZVs803lv DcrtSKOJdVXHvImU4MnN5VylFi2OBsPqSlXNlnKXIl8v83QHoe+mUFqj 3j5/fO6B1PPXxjgn
25-May-2020 23:37:22.338 add re-sign example.net. 300 IN RRSIG SOA 14 2 300 20200608233722 20200525223722 19778 example.net. oP3xTp4arrw/3se2m1AYgzYk8YV66uahsvSxdqMM3YzVSXykPPeICbnP RNjmiiSYn47IvDCytgMzbvqGgsX+8dKNq5b/C5xLXBxjogdRW0uM4bU+ hnyYa+lujWTu+1Xb
25-May-2020 23:37:22.338 add ns4.example.net. 3600 IN NSEC view.example.net. A RRSIG NSEC
25-May-2020 23:37:22.338 add view.example.net. 3600 IN NSEC example.net. TXT RRSIG NSEC
25-May-2020 23:37:22.338 add example.net. 3600 IN NSEC ns4.example.net. NS SOA RRSIG NSEC DNSKEY TYPE65534
25-May-2020 23:37:22.338 add example.net. 0 IN TYPE65534 \# 5 0E4D420001
25-May-2020 23:37:22.766 zone_needdump: zone example.net/IN/example2: enter
...
25-May-2020 23:38:11.324 client @0x7f6fd8014ac0 10.53.0.1#38429: TCP request
25-May-2020 23:38:11.324 client @0x7f6fd8014ac0 10.53.0.1#38429: view example1: using view 'example1'
25-May-2020 23:38:11.324 client @0x7f6fd8014ac0 10.53.0.1#38429: view example1: request has valid signature: keyforview1
25-May-2020 23:38:11.324 client @0x7f6fd8014ac0 10.53.0.1#38429/key keyforview1: view example1: recursion not available
25-May-2020 23:38:11.324 query client=0x7f6fd8014ac0 thread=0x7f7011890700 (<unknown-query>): ns_query_start
25-May-2020 23:38:11.324 query client=0x7f6fd8014ac0 thread=0x7f7011890700 (example.net/NSEC): qctx_init
Edited by Mark Andrews