[Opendnssec-develop] [OpenDNSSEC] #243: Ods-signerd - drudger - seems unstable
OpenDNSSEC
owner-dnssec-trac at kirei.se
Mon May 23 12:06:32 UTC 2011
#243: Ods-signerd - drudger - seems unstable
--------------------------------------+-------------------------------------
Reporter: nick.vandenheuvel@… | Owner: matthijs
Type: defect | Status: new
Priority: major | Component: Signer
Version: 1.3.0rc1 | Keywords:
--------------------------------------+-------------------------------------
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 [load
signconf for] 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[count=5500012
time=112(sec)] NSEC3[count=9198 time=17(sec)] RRSIG[new=18401 reused=0
time=19(sec) avg=968(sig/sec)] AUDIT[time=119(sec)] TOTAL[time=320(sec)]
--
Ticket URL: <http://trac.opendnssec.org/ticket/243>
OpenDNSSEC <http://www.opendnssec.org/>
OpenDNSSEC
More information about the Opendnssec-develop
mailing list