[Opendnssec-user] Missing keys and various other problems on 2.0

Mon Jun 25 13:45:01 UTC 2018

On 06/25/2018 03:05 PM, Casper Gielen wrote:
> Op 25-06-18 om 11:49 schreef Casper Gielen:
>>
>> I've verified that everything under /var/lib/opendnssec is readable and
>> writable by the opendnssec user. The configuration, under
>> /etc/opendnssec, is readable but not writable.
> 
> Minutes after I wrote this a colleague added a new zone (ucgv.nl) that immediately ran into trouble. 
> Unfortunately I do not have complete logging, this is what I do have:

This could be much unrelated from the earlier issue.

Are you using SoftHSM as HSM?  If so, which version?
There is a known, resolved issue with certain versions.

\Berry

>  Jun 25 11:15:49 ramachandra ods-enforcerd: [zonelist_import] zone ucgv.nl created
>  ...
>  Jun 25 11:16:02 ramachandra ods-enforcerd: [enforcer] update zone: ucgv.nl
>  Jun 25 11:16:02 ramachandra ods-enforcerd: 199 zone(s) found on policy "sidn"
>  Jun 25 11:16:02 ramachandra ods-enforcerd: [hsm_key_factory_generate] 1 keys needed for 199 zones covering 31536000 seconds, generating 1 keys for policy sidn
>  Jun 25 11:16:02 ramachandra ods-enforcerd: 1 new KSK(s) (2048 bits) need to be created.
>  Jun 25 11:16:02 ramachandra ods-enforcerd: 199 zone(s) found on policy "sidn"
>  Jun 25 11:16:02 ramachandra ods-enforcerd: [hsm_key_factory_generate] 13 keys needed for 199 zones covering 31536000 seconds, generating 1 keys for policy sidn
>  Jun 25 11:16:02 ramachandra ods-enforcerd: 1 new ZSK(s) (1024 bits) need to be created.
>  Jun 25 11:16:02 ramachandra ods-enforcerd: [signconf_cmd] performing signconf for all zones
>  Jun 25 11:16:02 ramachandra ods-enforcerd: [signconf_cmd] signconf done, notifying signer
>  ...
>  Jun 25 11:30:17 ramachandra ods-signerd: [hsm] unable to get key: key a1d5274f2e3c73eb73ec99c16e781d0d not found
>  Jun 25 11:30:17 ramachandra ods-signerd: [hsm] hsm_get_dnskey(): Got NULL key
>  Jun 25 11:30:17 ramachandra ods-signerd: [hsm] unable to get key: hsm failed to create dnskey
>  Jun 25 11:30:17 ramachandra ods-signerd: [zone] unable to prepare signing keys for zone ucgv.nl: error getting dnskey
>  Jun 25 11:30:17 ramachandra ods-signerd: [worker[1]] CRITICAL: failed to sign zone ucgv.nl: General error
> 
> root at ramachandra:~# ods-enforcer key list --zone ucgv.nl -v
> Keys:
> Zone:                           Keytype: State:    Date of next transition: Size: Algorithm: CKA_ID:                          Repository: KeyTag:
> ucgv.nl                         ZSK      publish   2018-06-26 11:16:27      1024  8          991337c6e4aba10487ef75d8ca990668 LocalHSM    24390
> 
> root at ramachandra:~# ods-enforcer key list --zone ucgv.nl -d
> Keys:
> Zone:                           Key role:     DS:          DNSKEY:      RRSIGDNSKEY: RRSIG:       Pub: Act: Id:
> ucgv.nl                         ZSK           NA           hidden       NA           rumoured     0    1    991337c6e4aba10487ef75d8ca990668
> 
> The log shows he followed our usual procedure to the tee.
> I immediatly repeated his steps, except for a different domain name, but was unable to reproduce te problem.
> The difference might be that I worked with a frehsly restarted ods-enforcer, while it had been running for three days straight when my colleague added the zone.
> 
> 
> 
> Jun 25 13:40:08 ramachandra ods-enforcerd: [zonelist_import] zone ucgvtest2.nl created
> Jun 25 13:40:16 ramachandra ods-enforcerd: [enforcer] update zone: ucgvtest2.nl
> Jun 25 13:40:16 ramachandra ods-enforcerd: [hsm_key_factory_get_key] key allocated
> Jun 25 13:40:16 ramachandra ods-enforcerd: [scheduler] schedule task [hsmkeygen] for policy_key
> Jun 25 13:40:16 ramachandra ods-enforcerd: [scheduler] signal now
> Jun 25 13:40:16 ramachandra ods-enforcerd: [enforcer] updatePolicy: got new key from HSM
> Jun 25 13:40:16 ramachandra ods-enforcerd: [worker[4]]: report for duty
> Jun 25 13:40:16 ramachandra ods-enforcerd: [scheduler] SIGALRM set
> Jun 25 13:40:16 ramachandra ods-enforcerd: [worker[4]] start working
> Jun 25 13:40:16 ramachandra ods-enforcerd: [worker[4]]: perform task [hsmkeygen] for policy_key
> Jun 25 13:40:16 ramachandra ods-enforcerd: SELECT policy.id, policy.rev, policy.name, policy.description, policy.signaturesResign, policy.signaturesRefresh, policy.signaturesJitter, policy.signaturesInceptionOffset, policy.signaturesValidityDefault, policy.signaturesValidityDenial, policy.signaturesValidityKeyset, policy.signaturesMaxZoneTtl, policy.denialType, policy.denialOptout, policy.denialTtl, policy.denialResalt, policy.denialAlgorithm, policy.denialIterations, policy.denialSaltLength, policy.denialSalt, policy.denialSaltLastChange, policy.keysTtl, policy.keysRetireSafety, policy.keysPublishSafety, policy.keysShared, policy.keysPurgeAfter, policy.zonePropagationDelay, policy.zoneSoaTtl, policy.zoneSoaMinimum, policy.zoneSoaSerial, policy.parentRegistrationDelay, policy.parentPropagationDelay, policy.parentDsTtl, policy.parentSoaTtl, policy.parentSoaMinimum, policy.passthrough FROM policy WHERE policy.id = ?
> Jun 25 13:40:16 ramachandra ods-enforcerd: [hsm_key_factory_generate_task] generate for policy key [duration: 0]
> Jun 25 13:40:16 ramachandra ods-enforcerd: [hsm_key_factory_generate] repository LocalHSM role KSK
> Jun 25 13:40:16 ramachandra ods-enforcerd: SELECT COUNT(*) FROM hsmKey WHERE hsmKey.policyId = ? AND hsmKey.state = ? AND hsmKey.bits = ? AND hsmKey.algorithm = ? AND hsmKey.role = ? AND hsmKey.isRevoked = ? AND hsmKey.keyType = ? AND hsmKey.repository = ?
> Jun 25 13:40:16 ramachandra ods-enforcerd: SELECT COUNT(*) FROM zone WHERE zone.policyId = ?
> Jun 25 13:40:16 ramachandra ods-enforcerd: 200 zone(s) found on policy "sidn"
> Jun 25 13:40:16 ramachandra ods-enforcerd: [hsm_key_factory_generate] 1 keys needed for 200 zones covering 31536000 seconds, generating 1 keys for policy sidn
> Jun 25 13:40:16 ramachandra ods-enforcerd: 1 new KSK(s) (2048 bits) need to be created.
> Jun 25 13:40:16 ramachandra ods-enforcerd: [hsm_key_factory_generate] generated key 5ddcfb83faa841d034ee262586391216 successfully
> Jun 25 13:40:16 ramachandra ods-enforcerd: [hsm_key_factory_generate_task] generate for policy key done
> 
> Jun 25 13:40:16 ramachandra ods-enforcerd: 200 zone(s) found on policy "sidn"
> Jun 25 13:40:16 ramachandra ods-enforcerd: [hsm_key_factory_generate] 13 keys needed for 200 zones covering 31536000 seconds, generating 1 keys for policy sidn
> Jun 25 13:40:16 ramachandra ods-enforcerd: 1 new ZSK(s) (1024 bits) need to be created.
> Jun 25 13:40:17 ramachandra ods-enforcerd: [hsm_key_factory_generate] generated key e484bf43583403c1a1658c2c7e30d47b successfully
> Jun 25 13:40:17 ramachandra ods-enforcerd: [hsm_key_factory_generate_task] generate for policy key done
> Jun 25 13:40:17 ramachandra ods-enforcerd: [worker[2]] finished working
> Jun 25 13:40:17 ramachandra ods-enforcerd: [worker[2]]: report for duty
> 
> 
> Jun 25 13:40:17 ramachandra ods-enforcerd: SELECT keyDependency.id, keyDependency.rev, keyDependency.zoneId, keyDependency.fromKeyDataId, keyDependency.toKeyDataId, keyDependency.type FROM keyDependency WHERE keyDependency.zoneId = ?
> Jun 25 13:40:17 ramachandra ods-enforcerd: SELECT keyState.id, keyState.rev, keyState.keyDataId, keyState.type, keyState.state, keyState.lastChange, keyState.minimize, keyState.ttl FROM keyState WHERE keyState.keyDataId = ?
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone: processing key 0c9c2506e33fe702c96f989bf78ab66f 4
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone: May KSK 0c9c2506e33fe702c96f989bf78ab66f DS in state hidden transition to rumoured?
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone: May KSK 0c9c2506e33fe702c96f989bf78ab66f DNSKEY in state hidden transition to rumoured?
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone Policy says we can (1/3)
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone: May KSK 0c9c2506e33fe702c96f989bf78ab66f RRSIGDNSKEY in state hidden transition to rumoured?
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone: processing key 68e476a72a0ab6e296dc309334276588 1
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone: May ZSK 68e476a72a0ab6e296dc309334276588 DNSKEY in state hidden transition to rumoured?
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone Policy says we can (1/3)
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone: May ZSK 68e476a72a0ab6e296dc309334276588 RRSIG in state rumoured transition to omnipresent?
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone Policy says we can (1/3)
> Jun 25 13:40:17 ramachandra ods-enforcerd: [enforcer] updateZone DNSSEC says we can (2/3)
> Jun 25 13:40:17 ramachandra ods-enforcerd: UPDATE keyData SET zoneId = ?, hsmKeyId = ?, algorithm = ?, inception = ?, role = ?, introducing = ?, shouldRevoke = ?, standby = ?, activeZsk = ?, publish = ?, activeKsk = ?, dsAtParent = ?, keytag = ?, minimize = ?, rev = ? WHERE keyData.id = ? AND keyData.rev = ?
> Jun 25 13:40:17 ramachandra ods-enforcerd: UPDATE keyData SET zoneId = ?, hsmKeyId = ?, algorithm = ?, inception = ?, role = ?, introducing = ?, shouldRevoke = ?, standby = ?, activeZsk = ?, publish = ?, activeKsk = ?, dsAtParent = ?, keytag = ?, minimize = ?, rev = ? WHERE keyData.id = ? AND keyData.rev = ?
> Jun 25 13:40:17 ramachandra ods-enforcerd: SELECT keyData.id, keyData.rev, keyData.zoneId, keyData.hsmKeyId, keyData.algorithm, keyData.inception, keyData.role, keyData.introducing, keyData.shouldRevoke, keyData.standby, keyData.activeZsk, keyData.publish, keyData.activeKsk, keyData.dsAtParent, keyData.keytag, keyData.minimize FROM keyData WHERE keyData.zoneId = ?
> Jun 25 13:40:17 ramachandra ods-enforcerd: Next update for zone ucgvtest2.nl scheduled at Tue Jun 26 13:40:40 2018
> 
> root at ramachandra:~# ods-enforcer key list --zone ucgvtest2.nl -v
> Keys:
> Zone:                           Keytype: State:    Date of next transition: Size: Algorithm: CKA_ID:                          Repository: KeyTag:
> ucgvtest2.nl                    ZSK      publish   2018-06-26 13:40:40      1024  8          68e476a72a0ab6e296dc309334276588 LocalHSM    14190
> key list completed in 0 seconds.
> root at ramachandra:~# ods-enforcer key list --zone ucgvtest2.nl -d
> Keys:
> Zone:                           Key role:     DS:          DNSKEY:      RRSIGDNSKEY: RRSIG:       Pub: Act: Id:
> ucgvtest2.nl                    ZSK           NA           hidden       NA           rumoured     0    1    68e476a72a0ab6e296dc309334276588
> 
> Now I'm a bit miffed by these zones with a ZSK but without a KSK.
> 
> My original problem, the zone wiskundeoptiu.nl, remains, but the situation has been slightly improved
> because some of the signatures have been replaced by signatures with the current ZSK.
> 
> I'm considering wether or not to edit the database directly to get the zone back in a workable condition by removing the problematic keys.
> First I'm going to delete the zone ucgv.nl, which is not yet in use, and redo it in the hope that it magically works out this time.
> 