Uploaded image for project: 'OpenDNSSEC TRAC Import'
  1. OpenDNSSEC TRAC Import
  2. ODSTRACIMPORT-233

Ods-signerd - drudger - seems unstable

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Signer
    • Labels:
      None

      Description

      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)]

        Attachments

          Activity

            People

            Assignee:
            matthijs Matthijs Mekking
            Reporter:
            nick Nick van den Heuvel
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: