[SUPPORT-160] Signer failure with PKCS#11 and SmartCard HSM / Enforcer segfault - OpenDNSSEC

XML

Word

Printable

Details

Type: Bug
Status: Open
Priority: Minor
Resolution: Unresolved
Affects Version/s: OpenDNSSEC 1.4.7
Fix Version/s: None
Component/s: Signer
Labels:
None
Environment:

Ubuntu 14.04.2LTS, 3.13.0-30-generic #55-Ubuntu SMP, OpenDNSSEC 1.4/develop (commit 91769197a9f3ed06c75adaf75fe1872fc4dee913), SoftHSM 1.3.5-1ubuntu3

Description

Hardware: ContactCard SmartCard HSM

[680574.152470] usb 5-1: USB disconnect, device number 13
[680583.884245] usb 5-1: new full-speed USB device number 14 using uhci_hcd
[680584.072654] usb 5-1: New USB device found, idVendor=04e6, idProduct=5817
[680584.072666] usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=5
[680584.072675] usb 5-1: Product: SCT3522CC token
[680584.072682] usb 5-1: Manufacturer: Identive

$ pkcs11-tool --module opensc-pkcs11.so --list-mechanisms
Using slot 1 with a present token (0x1)
Supported mechanisms:
  SHA-1, digest
  SHA256, digest
  SHA384, digest
  SHA512, digest
  MD5, digest
  RIPEMD160, digest
  GOSTR3411, digest
  ECDSA, keySize={192,320}, hw, sign, other flags=0x1500000
  ECDSA-SHA1, keySize={192,320}, hw, sign, other flags=0x1500000
  ECDH1-COFACTOR-DERIVE, keySize={192,320}, hw, derive, other flags=0x1500000
  ECDH1-DERIVE, keySize={192,320}, hw, derive, other flags=0x1500000
  ECDSA-KEY-PAIR-GEN, keySize={192,320}, hw, generate_key_pair, other flags=0x1500000
  RSA-X-509, keySize={1024,2048}, hw, decrypt, sign, verify
  RSA-PKCS, keySize={1024,2048}, hw, decrypt, sign, verify
  SHA1-RSA-PKCS, keySize={1024,2048}, sign, verify
  SHA256-RSA-PKCS, keySize={1024,2048}, sign, verify
  MD5-RSA-PKCS, keySize={1024,2048}, sign, verify
  RIPEMD160-RSA-PKCS, keySize={1024,2048}, sign, verify
  RSA-PKCS-KEY-PAIR-GEN, keySize={1024,2048}, generate_key_pair

configured:

<RepositoryList>
  <Repository name="SoftHSM">
    <Module>/usr/lib/softhsm/libsofthsm.so</Module>
    <TokenLabel>OpenDNSSEC</TokenLabel>
    <PIN>1234</PIN>
    <SkipPublicKey/>
  </Repository>

  <Repository name="SmartCard-HSM">
    <Module>/usr/lib/x86_64-linux-gnu/opensc-pkcs11.so</Module>
    <TokenLabel>SmartCard-HSM (UserPIN)</TokenLabel>
    <!-- <PIN>test:1234</PIN> -->
    <Capacity>255</Capacity> <!-- I don't know -->
    <!-- <RequireBackup/> -->
    <SkipPublicKey/>
  </Repository>
</RepositoryList>

kasp.xml:

<Keys>
  <TTL>PT300S</TTL>
  <RetireSafety>PT360S</RetireSafety>
  <PublishSafety>PT360S</PublishSafety>
  <Purge>P14D</Purge>
  <KSK>
    <Algorithm length="1024">8</Algorithm>
    <Lifetime>P1D</Lifetime>
    <Repository>SmartCard-HSM</Repository>
  </KSK>

  <ZSK>
    <Algorithm length="1024">8</Algorithm>
    <Lifetime>PT4H</Lifetime>
    <Repository>SoftHSM</Repository>
    <!-- <ManualRollover/> -->
  </ZSK>
</Keys>

$ ods-hsmutil info
Enter PIN for token SmartCard-HSM:
Repository: SoftHSM
        Module:        /usr/lib/softhsm/libsofthsm.so
        Slot:          0
        Token Label:   OpenDNSSEC
        Manufacturer:  SoftHSM
        Model:         SoftHSM
        Serial:        1

Repository: SmartCard-HSM
        Module:        /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so
        Slot:          1
        Token Label:   SmartCard-HSM (UserPIN)
        Manufacturer:  www.CardContact.de
        Model:         PKCS#15 emulated
        Serial:        DECC0100509

$ ods-hsmutil login
The tokens are now logged in.

$ ods-control start

$ ods-ksmutil key list -v
Keys:
Zone:              Keytype:      State:    Date of next transition (to):  Size:   Algorithm:  CKA_ID:                           Repository:                       Keytag:
po1.aa             KSK           publish   2015-03-15 12:52:53 (ready)    1024    8           24b94aad4ae8502c968d2dab6e6f590b  SmartCard-HSM                     35020
po1.aa             ZSK           active    2015-03-15 16:36:53 (retire)   1024    8           236f93a2302012c138436a3ebd0160a6  SoftHSM                           32140

A little later, when OpenDNSSEC was about to sign the zone again:

Mar 15 13:05:13 ubu10 ods-signerd: [xfrd] zone po1.aa got update indicating current serial 1 from 192.168.1.114
Mar 15 13:06:53 ubu10 ods-signerd: [STATS] po1.aa 1426421213 RR[count=0 time=0(sec)] NSEC[count=0 time=0(sec)] RRSIG[new=2 reused=3 time=0(sec) avg=0(sig/sec)] TOTAL[time=0(sec)]
Mar 15 13:16:53 ubu10 ods-signerd: [hsm] sign final: CKR_FUNCTION_FAILED
Mar 15 13:16:53 ubu10 ods-signerd: [hsm] error signing rrset with libhsm
Mar 15 13:16:53 ubu10 ods-signerd: [rrset] unable to sign RRset[48]: lhsm_sign() failed
Mar 15 13:16:53 ubu10 ods-signerd: [worker[4]] sign zone po1.aa failed: 1 RRsets failed
Mar 15 13:16:53 ubu10 ods-signerd: [worker[4]] CRITICAL: failed to sign zone po1.aa: General error
Mar 15 13:16:53 ubu10 ods-signerd: [worker[4]] backoff task [sign] for zone po1.aa with 60 seconds
Mar 15 13:17:53 ubu10 ods-signerd: [hsm] sign final: CKR_FUNCTION_FAILED
Mar 15 13:17:53 ubu10 ods-signerd: [hsm] error signing rrset with libhsm
Mar 15 13:17:53 ubu10 ods-signerd: [rrset] unable to sign RRset[48]: lhsm_sign() failed
Mar 15 13:17:53 ubu10 ods-signerd: [worker[4]] sign zone po1.aa failed: 1 RRsets failed
Mar 15 13:17:53 ubu10 ods-signerd: [worker[4]] CRITICAL: failed to sign zone po1.aa: General error
Mar 15 13:17:53 ubu10 ods-signerd: [worker[4]] backoff task [sign] for zone po1.aa with 120 seconds
Mar 15 13:19:53 ubu10 ods-signerd: [hsm] sign final: CKR_FUNCTION_FAILED
Mar 15 13:19:53 ubu10 ods-signerd: [hsm] error signing rrset with libhsm
Mar 15 13:19:53 ubu10 ods-signerd: [rrset] unable to sign RRset[48]: lhsm_sign() failed
Mar 15 13:19:53 ubu10 ods-signerd: [worker[4]] sign zone po1.aa failed: 1 RRsets failed
Mar 15 13:19:53 ubu10 ods-signerd: [worker[4]] CRITICAL: failed to sign zone po1.aa: General error
Mar 15 13:19:53 ubu10 ods-signerd: [worker[4]] backoff task [sign] for zone po1.aa with 240 seconds
Mar 15 13:23:53 ubu10 ods-signerd: [hsm] sign final: CKR_FUNCTION_FAILED
Mar 15 13:23:53 ubu10 ods-signerd: [hsm] error signing rrset with libhsm
Mar 15 13:23:53 ubu10 ods-signerd: [rrset] unable to sign RRset[48]: lhsm_sign() failed
Mar 15 13:23:53 ubu10 ods-signerd: [worker[1]] sign zone po1.aa failed: 1 RRsets failed
Mar 15 13:23:53 ubu10 ods-signerd: [worker[1]] CRITICAL: failed to sign zone po1.aa: General error
Mar 15 13:23:53 ubu10 ods-signerd: [worker[1]] backoff task [sign] for zone po1.aa with 480 seconds
Mar 15 13:31:53 ubu10 ods-signerd: [hsm] sign final: CKR_FUNCTION_FAILED
Mar 15 13:31:53 ubu10 ods-signerd: [hsm] error signing rrset with libhsm
Mar 15 13:31:53 ubu10 ods-signerd: [rrset] unable to sign RRset[48]: lhsm_sign() failed
Mar 15 13:31:53 ubu10 ods-signerd: [worker[1]] sign zone po1.aa failed: 1 RRsets failed
Mar 15 13:31:53 ubu10 ods-signerd: [worker[1]] CRITICAL: failed to sign zone po1.aa: General error
Mar 15 13:31:53 ubu10 ods-signerd: [worker[1]] backoff task [sign] for zone po1.aa with 960 seconds

and the enforcer had died. After restarting it, I tried a rollover

Mar 15 13:40:13 ubu10 ods-enforcerd: 1 new KSK(s) (1024 bits) need to be created for policy lab: keys_to_generate(1) = keys_needed(1) - keys_available(0).
Mar 15 13:40:13 ubu10 ods-enforcerd: Error creating key in repository SmartCard-HSM
Mar 15 13:40:13 ubu10 ods-enforcerd: generate key pair: CKR_DATA_LEN_RANGE

only to find the enforcer died again. Creating KSK keys manually on the SmartCard-HSM with ods-ksmutil key generate works, however.

Mar 15 14:04:41 ubu10 ods-enforcerd: 1 new KSK(s) (1024 bits) need to be created for policy lab: keys_to_generate(1) = keys_needed(1) - keys_available(0).
Mar 15 14:04:41 ubu10 ods-enforcerd: Error creating key in repository SmartCard-HSM
Mar 15 14:04:41 ubu10 ods-enforcerd: generate key pair: CKR_DATA_LEN_RANGE

n spite of having pre-generated sufficient keys, things are not going as I'd hoped they would: when I kick the signer, I see this in the logs, and the signed file isn't updated.

Mar 15 14:33:20 ubu10 ods-signerd: [drudger[1]] report for duty
Mar 15 14:33:20 ubu10 ods-signerd: [drudger[1]] nothing to do, wait
Mar 15 14:33:20 ubu10 ods-signerd: [hsm] sign final: CKR_FUNCTION_FAILED
Mar 15 14:33:20 ubu10 ods-signerd: [hsm] error signing rrset with libhsm
Mar 15 14:33:20 ubu10 ods-signerd: [rrset] unable to sign RRset[48]: lhsm_sign() failed
Mar 15 14:33:20 ubu10 ods-signerd: [drudger[2]] wake up superior[3], work is done
Mar 15 14:33:20 ubu10 ods-signerd: [worker[3]] wake up
Mar 15 14:33:20 ubu10 ods-signerd: [drudger[2]] report for duty
Mar 15 14:33:20 ubu10 ods-signerd: [drudger[2]] nothing to do, wait
Mar 15 14:33:20 ubu10 ods-signerd: [worker[3]] somebody poked me, check completed jobs 5 appointed, 4 completed, 1 failed
Mar 15 14:33:20 ubu10 ods-signerd: [worker[3]] sign zone po1.aa failed: 1 RRsets failed
Mar 15 14:33:20 ubu10 ods-signerd: [worker[3]] CRITICAL: failed to sign zone po1.aa: General error

ods-hsmutil test SmartCard-HSM
Testing repository: SmartCard-HSM

Generating 512-bit RSA key... Failed
generate key pair: CKR_FUNCTION_NOT_SUPPORTED

Generating 768-bit RSA key... Failed
generate key pair: CKR_FUNCTION_NOT_SUPPORTED

Generating 1024-bit RSA key... Failed
generate key pair: CKR_GENERAL_ERROR

Generating 1536-bit RSA key... Failed
generate key pair: CKR_GENERAL_ERROR

Generating 2048-bit RSA key... Failed
generate key pair: CKR_GENERAL_ERROR

Generating 4096-bit RSA key... Failed
generate key pair: CKR_FUNCTION_NOT_SUPPORTED

Generating 512-bit DSA key... Failed
generate domain parameters: CKR_FUNCTION_NOT_SUPPORTED

Generating 768-bit DSA key... Failed
generate domain parameters: CKR_FUNCTION_NOT_SUPPORTED

Generating 1024-bit DSA key... Failed
generate domain parameters: CKR_FUNCTION_NOT_SUPPORTED

Generating 512-bit GOST key... Failed
generate key pair: CKR_FUNCTION_NOT_SUPPORTED

Generating 1024 bytes of random data... OK
Generating 32-bit random data... 2099948928
Generating 64-bit random data... 8427886638822312380

what? If that all failed, how could OpenDNSSEC have created the very first KSK when it initially launched?

Several days later, I pick up again where I left off. Then:

Mar 29 19:07:33 ubu10 ods-enforcerd: HSM connection open.
Mar 29 19:07:33 ubu10 ods-enforcerd: Reading config "/etc/opendnssec/conf.xml"
Mar 29 19:07:33 ubu10 ods-enforcerd: Reading config schema "/usr/local/share/opendnssec/conf.rng"
Mar 29 19:07:33 ubu10 ods-enforcerd: Communication Interval: 3600
Mar 29 19:07:33 ubu10 ods-enforcerd: No DS Submit command supplied
Mar 29 19:07:33 ubu10 ods-enforcerd: SQLite database set to: /var/opendnssec/kasp.db
Mar 29 19:07:33 ubu10 ods-enforcerd: Log User set to: local0
Mar 29 19:07:33 ubu10 ods-enforcerd: Switched log facility to: local0
Mar 29 19:07:33 ubu10 ods-enforcerd: Connecting to Database...
Mar 29 19:07:33 ubu10 ods-enforcerd: Policy default found.
Mar 29 19:07:33 ubu10 ods-enforcerd: Key sharing is Off.
Mar 29 19:07:33 ubu10 ods-enforcerd: No zones on policy default, skipping...
Mar 29 19:07:33 ubu10 ods-enforcerd: Purging keys...
Mar 29 19:07:33 ubu10 ods-enforcerd: Policy lab found.
Mar 29 19:07:33 ubu10 ods-enforcerd: Key sharing is Off.
Mar 29 19:07:33 ubu10 ods-enforcerd: 1 zone(s) found on policy "lab"
Mar 29 19:07:33 ubu10 ods-enforcerd: 1 new KSK(s) (1024 bits) need to be created for policy lab: keys_to_generate(1) = keys_needed(1) - keys_available(0).
Mar 29 19:07:33 ubu10 kernel: [1297147.947932] ods-enforcerd[11566]: segfault at 18 ip 00007fa3ab8970dd sp 00007fff02de3b60 error 4 in libc-2.19.so[7fa3ab818000+1bb000]
Mar 29 19:07:48 ubu10 ods-signerd: [worker[2]] report for duty
Mar 29 19:07:48 ubu10 ods-signerd: [worker[1]] report for duty
Mar 29 19:07:48 ubu10 ods-signerd: [scheduler] pop task for zone po1.aa
Mar 29 19:07:48 ubu10 ods-signerd: [scheduler] unschedule task [sign] for zone po1.aa
Mar 29 19:07:48 ubu10 ods-signerd: [worker[2]] start working on zone po1.aa
Mar 29 19:07:48 ubu10 ods-signerd: [worker[2]] perform task [sign] for zone po1.aa at 1427648868
Mar 29 19:07:48 ubu10 ods-signerd: [worker[2]] sign zone po1.aa
Mar 29 19:07:48 ubu10 ods-signerd: [namedb] zone po1.aa update serial: format=unixtime in=1 internal=1427647668 out=1427647668 now=1427648868
Mar 29 19:07:48 ubu10 ods-signerd: [namedb] zone po1.aa update serial: 1427647668 + 1200 = 1427648868

I give up.

Attachments

Activity

People

Assignee:: Unassigned

Reporter:: Jan-Piet Mens

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 2015-03-30 17:36

Updated:: 2015-03-30 17:36