-
Type:
Bug
-
Status: Closed
-
Priority:
Major
-
Resolution: Cannot Reproduce
-
Affects Version/s: None
-
Fix Version/s: None
-
Component/s: Signer
-
Labels:None
Test steps:
- Clean tmp and signed folder
- Purge keys
- Run a setup for ODS (ods-ksmutil setup)
- Sign large zone with 20 threads in the conf.xml
- Check signing speed
Expected result:
- Zone signed
Observed result:
- Zone not signed.
- Error message from ods-signerd: [drudger[1]] unable to drudge: error creating libhsm context
When I run the same test steps again I get no errors and the zone gets signed.
Note: this has been tested in 1.3.0rc2 (not yet in the version list)
Logging:
May 23 12:56:14 DEVELOPER15 ods-enforcerd: opendnssec starting...
May 23 12:56:14 DEVELOPER15 ods-enforcerd: opendnssec Parent exiting...
May 23 12:56:14 DEVELOPER15 ods-enforcerd: opendnssec forked OK...
May 23 12:56:14 DEVELOPER15 ods-enforcerd: opendnssec started (version 1.3.0rc2), pid 2897
May 23 12:56:14 DEVELOPER15 ods-enforcerd: HSM opened successfully.
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Reading config "/etc/opendnssec/conf.xml"
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Reading config schema "/usr/local/share/opendnssec/conf.rng"
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Communication Interval: 3600
May 23 12:56:14 DEVELOPER15 ods-enforcerd: No DS Submit command supplied
May 23 12:56:14 DEVELOPER15 ods-enforcerd: MySQL database host set to: localhost
May 23 12:56:14 DEVELOPER15 ods-enforcerd: MySQL database port set to: 3306
May 23 12:56:14 DEVELOPER15 ods-enforcerd: MySQL database schema set to: KASP
May 23 12:56:14 DEVELOPER15 ods-enforcerd: MySQL database user set to: kaspuser
May 23 12:56:14 DEVELOPER15 ods-enforcerd: MySQL database password set
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Log User set to: local0
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Switched log facility to: local0
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Connecting to Database...
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Policy default found.
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Key sharing is Off.
May 23 12:56:14 DEVELOPER15 ods-enforcerd: SoftHSM: C_GenerateKeyPair: Key pair generated
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Created key in repository SoftHSM
May 23 12:56:14 DEVELOPER15 ods-enforcerd: Created KSK size: 2048, alg: 7 with id: 6225eeba1865bb47c86d369c94684a8b in repository: SoftHSM and database.
May 23 12:56:15 DEVELOPER15 ods-signerd: [engine] signer started
May 23 12:56:15 DEVELOPER15 ods-signerd: [signconf] zone nel signconf: RESIGN[PT180S] REFRESH[PT900S] VALIDITY[PT3600S] DENIAL[PT3600S] JITTER[PT60S] OFFSET[PT60S] NSEC[50] DNSKEYTTL[PT600S] SOATTL[PT600S] MINIMUM[PT300S] SERIAL[unixtime] AUDIT[1]
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[1]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[3]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[5]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[7]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[10]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[12]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[14]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[16]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[18]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[20]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-signerd: [drudger[4]] unable to drudge: error creating libhsm context
May 23 12:56:15 DEVELOPER15 ods-enforcerd: SoftHSM: C_GenerateKeyPair: Key pair generated
May 23 12:56:15 DEVELOPER15 ods-enforcerd: Created key in repository SoftHSM
May 23 12:56:15 DEVELOPER15 ods-enforcerd: Created ZSK size: 1024, alg: 7 with id: d7d522cb66162dece8a9cbe7d821e429 in repository: SoftHSM and database.
May 23 12:56:15 DEVELOPER15 ods-enforcerd: Purging keys...
May 23 12:56:15 DEVELOPER15 ods-enforcerd: zonelist filename set to /etc/opendnssec/zonelist.xml.
May 23 12:56:15 DEVELOPER15 ods-enforcerd: Zone nel found.
May 23 12:56:15 DEVELOPER15 ods-enforcerd: Policy for nel set to default.
May 23 12:56:15 DEVELOPER15 ods-enforcerd: Config will be output to /var/opendnssec/signconf/nel.xml.
May 23 12:56:15 DEVELOPER15 ods-enforcerd: INFO: Promoting ZSK from publish to active as this is the first pass for the zone
May 23 12:56:15 DEVELOPER15 ods-enforcerd: WARNING: Making non-backed up ZSK active, PLEASE make sure that you know the potential problems of using keys which are not recoverable
May 23 12:58:25 DEVELOPER15 ods-signerd: [worker[2]] sign zone nel failed: 17603 of 18401 signatures failed
May 23 12:58:25 DEVELOPER15 ods-signerd: [worker[2]] backoff task [read] for zone nel with 60 seconds
May 23 12:58:25 DEVELOPER15 ods-enforcerd: Disconnecting from Database...
May 23 12:58:25 DEVELOPER15 ods-enforcerd: Sleeping for 3600 seconds.
May 23 12:58:25 DEVELOPER15 ods-signerd: [signconf] zone nel signconf: RESIGN[PT180S] REFRESH[PT900S] VALIDITY[PT3600S] DENIAL[PT3600S] JITTER[PT60S] OFFSET[PT60S] NSEC[50] DNSKEYTTL[PT600S] SOATTL[PT600S] MINIMUM[PT300S] SERIAL[unixtime] AUDIT[1]
May 23 13:00:02 DEVELOPER15 ods-signerd: [worker[1]] sign zone nel failed: 17724 of 18401 signatures failed
May 23 13:00:02 DEVELOPER15 ods-signerd: [worker[1]] backoff task [read] for zone nel with 60 seconds
May 23 13:02:37 DEVELOPER15 ods-signerd: [worker[1]] sign zone nel failed: 17149 of 18401 signatures failed
May 23 13:02:37 DEVELOPER15 ods-signerd: [worker[1]] backoff task [read] for zone nel with 120 seconds
May 23 13:06:13 DEVELOPER15 ods-signerd: [worker[1]] sign zone nel failed: 17628 of 18401 signatures failed
May 23 13:06:13 DEVELOPER15 ods-signerd: [worker[1]] backoff task [read] for zone nel with 240 seconds
May 23 13:11:10 DEVELOPER15 dhclient: DHCPREQUEST of 193.176.144.184 on eth0 to 193.176.144.163 port 67
May 23 13:11:10 DEVELOPER15 dhclient: DHCPACK of 193.176.144.184 from 193.176.144.163
May 23 13:11:10 DEVELOPER15 dhclient: bound to 193.176.144.184 -- renewal in 1387 seconds.
May 23 13:11:49 DEVELOPER15 ods-signerd: [worker[1]] sign zone nel failed: 17188 of 18401 signatures failed
May 23 13:11:49 DEVELOPER15 ods-signerd: [worker[1]] backoff task [read] for zone nel with 480 seconds
May 23 13:17:02 DEVELOPER15 CRON[2984]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 23 13:21:25 DEVELOPER15 ods-signerd: [worker[1]] sign zone nel failed: 17316 of 18401 signatures failed
May 23 13:21:25 DEVELOPER15 ods-signerd: [worker[1]] backoff task [read] for zone nel with 96
-------------------------------------------------------------
May 23 13:32:52 DEVELOPER15 ods-enforcerd: opendnssec starting...
May 23 13:32:52 DEVELOPER15 ods-enforcerd: opendnssec Parent exiting...
May 23 13:32:52 DEVELOPER15 ods-enforcerd: opendnssec forked OK...
May 23 13:32:52 DEVELOPER15 ods-enforcerd: opendnssec started (version 1.3.0rc2), pid 3018
May 23 13:32:52 DEVELOPER15 ods-enforcerd: HSM opened successfully.
May 23 13:32:52 DEVELOPER15 ods-enforcerd: Reading config "/etc/opendnssec/conf.xml"
May 23 13:32:52 DEVELOPER15 ods-enforcerd: Reading config schema "/usr/local/share/opendnssec/conf.rng"
May 23 13:32:52 DEVELOPER15 ods-enforcerd: Communication Interval: 3600
May 23 13:32:52 DEVELOPER15 ods-enforcerd: No DS Submit command supplied
May 23 13:32:52 DEVELOPER15 ods-enforcerd: MySQL database host set to: localhost
May 23 13:32:52 DEVELOPER15 ods-enforcerd: MySQL database port set to: 3306
May 23 13:32:52 DEVELOPER15 ods-enforcerd: MySQL database schema set to: KASP
May 23 13:32:52 DEVELOPER15 ods-enforcerd: MySQL database user set to: kaspuser
May 23 13:32:52 DEVELOPER15 ods-enforcerd: MySQL database password set
May 23 13:32:52 DEVELOPER15 ods-enforcerd: Log User set to: local0
May 23 13:32:52 DEVELOPER15 ods-enforcerd: Switched log facility to: local0
May 23 13:32:52 DEVELOPER15 ods-enforcerd: Connecting to Database...
May 23 13:32:52 DEVELOPER15 ods-enforcerd: Policy default found.
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Key sharing is Off.
May 23 13:32:53 DEVELOPER15 ods-enforcerd: SoftHSM: C_GenerateKeyPair: Key pair generated
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Created key in repository SoftHSM
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Created KSK size: 2048, alg: 7 with id: bf37cb5579dc5d836c5537ec531da341 in repository: SoftHSM and database.
May 23 13:32:53 DEVELOPER15 ods-enforcerd: SoftHSM: C_GenerateKeyPair: Key pair generated
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Created key in repository SoftHSM
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Created ZSK size: 1024, alg: 7 with id: 26f7cb70c7f14d9b98e6343d25f22637 in repository: SoftHSM and database.
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Purging keys...
May 23 13:32:53 DEVELOPER15 ods-enforcerd: zonelist filename set to /etc/opendnssec/zonelist.xml.
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Zone nel found.
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Policy for nel set to default.
May 23 13:32:53 DEVELOPER15 ods-enforcerd: Config will be output to /var/opendnssec/signconf/nel.xml.
May 23 13:32:53 DEVELOPER15 ods-signerd: [engine] signer started
May 23 13:32:53 DEVELOPER15 ods-signerd: [signconf] zone nel signconf: RESIGN[PT180S] REFRESH[PT900S] VALIDITY[PT3600S] DENIAL[PT3600S] JITTER[PT60S] OFFSET[PT60S] NSEC[50] DNSKEYTTL[PT600S] SOATTL[PT600S] MINIMUM[PT300S] SERIAL[unixtime] AUDIT[1]
May 23 13:32:53 DEVELOPER15 ods-signerd: [hsm] unable to get key: key 6225eeba1865bb47c86d369c94684a8b not found
May 23 13:32:53 DEVELOPER15 ods-signerd: [zone] unable to publish dnskeys zone nel: error creating DNSKEY for key 6225eeba1865bb47c86d369c94684a8b
May 23 13:32:53 DEVELOPER15 ods-signerd: [worker[3]] backoff task [signconf for|load] for zone nel with 60 seconds
May 23 13:32:54 DEVELOPER15 ods-enforcerd: INFO: Promoting ZSK from publish to active as this is the first pass for the zone
May 23 13:32:54 DEVELOPER15 ods-enforcerd: WARNING: Making non-backed up ZSK active, PLEASE make sure that you know the potential problems of using keys which are not recoverable
May 23 13:32:54 DEVELOPER15 ods-enforcerd: Disconnecting from Database...
May 23 13:32:54 DEVELOPER15 ods-enforcerd: Sleeping for 3600 seconds.
May 23 13:32:54 DEVELOPER15 ods-signerd: [signconf] zone nel signconf: RESIGN[PT180S] REFRESH[PT900S] VALIDITY[PT3600S] DENIAL[PT3600S] JITTER[PT60S] OFFSET[PT60S] NSEC[50] DNSKEYTTL[PT600S] SOATTL[PT600S] MINIMUM[PT300S] SERIAL[unixtime] AUDIT[1]
May 23 13:33:42 DEVELOPER15 pulseaudio[1629]: protocol-esound.c: write(): Broken pipe
May 23 13:34:17 DEVELOPER15 dhclient: DHCPREQUEST of 193.176.144.184 on eth0 to 193.176.144.163 port 67
May 23 13:34:17 DEVELOPER15 dhclient: DHCPACK of 193.176.144.184 from 193.176.144.163
May 23 13:34:17 DEVELOPER15 dhclient: bound to 193.176.144.184 -- renewal in 1418 seconds.
May 23 13:35:49 DEVELOPER15 ods-auditor[3148]: Auditor started
May 23 13:35:49 DEVELOPER15 ods-auditor[3148]: Auditor starting on nel
May 23 13:35:49 DEVELOPER15 ods-auditor[3148]: Auditing nel zone : NSEC3 SIGNED
May 23 13:37:48 DEVELOPER15 ods-auditor[3148]: SOA differs : from 1000 to 1306150503
May 23 13:37:48 DEVELOPER15 ods-auditor[3148]: Finished auditing nel zone
May 23 13:38:14 DEVELOPER15 ods-signerd: [STATS] nel RR[time=112(sec)|count=5500012] NSEC3[time=17(sec)|count=9198] RRSIG[reused=0 time=19(sec) avg=968(sig/sec)|new=18401] AUDIT[time=119(sec)] TOTAL[time=320(sec)]