Bind 9.8 with DNSSEC and Thales nShield HSM

Fri Mar 18 13:19:40 UTC 2011

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

I conducted a DNSSEC tests with Bind 9.8 (also 9.7.3) and Thales nShield
HSM.

Everything compiled fine, I was able to generate keys and list keys on HSM:

# pkcs11-list -p xxx
object[0]: handle 1120 class 3 label[6] 'example-KSK' id[0]
object[1]: handle 1118 class 2 label[6] 'example-KSK' id[0]
object[2]: handle 1121 class 3 label[6] 'example-ZSK' id[0]
object[3]: handle 1119 class 2 label[6] 'example-ZSK' id[0]

after that I try to sign zone and signing process ends with signed
example zone.

After that I added more DS records into zone to check performance and
started signing zone again:

# dnssec-signzone -r /dev/urandom -K ../keys/ -A -t -H 12 -3
7A821C39150237743E55 -S -o example example
dnssec-signzone: warning: dns_dnssec_findmatchingkeys: error reading key
file Kexample.+010+12897.private: not found
Fetching KSK 57642/RSASHA512 from key repository.
dnssec-signzone: fatal: No non-KSK DNSKEY found; supply a ZSK or use '-z'.

No keys?! but how... Check HSM for stored keys:

# pkcs11-list -p xxx
object[0]: handle 1120 class 3 label[6] 'pl-KSK' id[0]
object[1]: handle 1118 class 2 label[6] 'pl-KSK' id[0]
object[2]: handle 1119 class 2 label[6] 'pl-ZSK' id[0]

It appears that in some odd way the key is removed from the HSM device.
Totally do not know why this is happening.

List keys on HSM with vendor tools:

# /opt/nfast/bin/nfkminfo -k (-k List keys)

Key list - 4 keys
 AppName pkcs11               Ident
uc65c8e963cca1145bd03dc67489b447d4edabdf02-18705e16324ea034c2d0ab0d77646aa74ef530a2
 AppName pkcs11               Ident
ucb7e2e031bf94c1a22fd05627ae352481a61aaaa0-ad7cfaa7dc5489c283957141d0141129f7c7ca42
 AppName pkcs11               Ident
uc65c8e963cca1145bd03dc67489b447d4edabdf02-01f2a911363a8399b5d533658e4f0c3f4a945f5b
 AppName pkcs11               Ident
ucb7e2e031bf94c1a22fd05627ae352481a61aaaa0-19434597a848accd73417c203221596829f5f748

# /opt/nfast/bin/nfkminfo -l (-l List keys and names, ordered by protection)

Keys protected by cardsets:
 key_pkcs11_uc65c8e963cca1145bd03dc67489b447d4edabdf02-18705e16324ea034c2d0ab0d77646aa74ef530a2 `pl-KSK'
 key_pkcs11_ucb7e2e031bf94c1a22fd05627ae352481a61aaaa0-ad7cfaa7dc5489c283957141d0141129f7c7ca42 `pl-KSK'

definitely something's has gone wrong. so I started to debug it when it
happens. Key is missing after calling dst_lib_destroy() function from
dnssec-signzone.c (line: 3963) and setting PKCS#11 library debug to
highest shows:

2011-03-18 12:49:27 [22986]: pkcs11: 000008CC >>   C_DestroyObject
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC >    hSession 0x000008CC
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC >    hObject 0x00000461
2011-03-18 12:49:27 [22986]: pkcs11: 00000000 D    NFC__hash_session
0x000008CC
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    hashmap lookup hash
465E9E2260D probe 13 step 77
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    lookup try
hashmap[13] hash 465E9E2260D value 0x8a52a0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    found hashmap[13]
value 0x8a52a0
2011-03-18 12:49:27 [22986]: pkcs11: 00000000 D    NFC__hash_session
0x000008CC
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    hashmap lookup hash
465E9E2260D probe 13 step 77
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    lookup try
hashmap[13] hash 465E9E2260D value 0x8a52a0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    found hashmap[13]
value 0x8a52a0
2011-03-18 12:49:27 [22986]: pkcs11: 00000000 D
NFC__hash_object_handle 0x00000461
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    hashmap lookup hash
2308A65EDFE probe 126 step 91
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    lookup try
hashmap[126] hash 2308A65EDFE value 0x890fb0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    found hashmap[126]
value 0x890fb0
2011-03-18 12:49:27 [22986]: pkcs11: 00000000 D    NFC__hash_session
0x000008CC
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    hashmap lookup hash
465E9E2260D probe 13 step 77
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    lookup try
hashmap[13] hash 465E9E2260D value 0x8a52a0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    found hashmap[13]
value 0x8a52a0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    NFC__free_object,
objdata 0x890fb0 handle 0x00000461
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    delete_nfkmkey
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    Only delete half of
key pair, privblob.len 1136 pubblob.len 476
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    Delete private key
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    And the matching
recovery data
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    NFKM_recordkey
appname pkcs11 keyident
ucb7e2e031bf94c1a22fd05627ae352481a61aaaa0-19434597a848accd73417c20
3221596829f5f748 objpriv.len 0 objpub.len 476
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    unload key
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    NFC__destroy_key
0x7fff78f14234
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    unloaded key
2011-03-18 12:49:27 [22986]: pkcs11: 00000000 D
NFC__hash_object_handle 0x00000461
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    hashmap lookup hash
2308A65EDFE probe 126 step 91
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    lookup try
hashmap[126] hash 2308A65EDFE value 0x890fb0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    found hashmap[126]
value 0x890fb0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    After remove size
128, used 3
2011-03-18 12:49:27 [22986]: pkcs11: 00000000 D
NFC__hash_object_ident 19434597a848accd73417c203221596829f5f748
0xCDAC48A897454319
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    hashmap lookup hash
CDAC48A897454319 probe 25 step 7
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    lookup try
hashmap[25] hash CDAC48A897454319 value 0x890fb0
2011-03-18 12:49:27 [22986]: pkcs11: 00000000 D    NFC__cmp_object_ident
ucb7e2e031bf94c1a22fd05627ae352481a61aaaa0-19434597a848accd73417c203221596829f5f748
ucb7e2e031bf94c1a22fd05627ae352481a61aaaa0-19434597a848accd73417c203221596829f5f748
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    found hashmap[25]
value 0x890fb0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    After remove size
128, used 1
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    NFC__unlink_object
00000461 slotID 1D622496 objdata->obj 0x8a56d0
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    unlinking pair
0000045F (nfmkey 0x892250)
2011-03-18 12:49:27 [22986]: pkcs11: 000008CC D    NF_FreeCK_CKObjectNew

At this point I'm not able to do more debuging and don't know if it is
Bind or PKCS#11 library issue.

if anyone is familiar with something like that and can share experience
I will be appreciate.

- -- 
regards

zbigniew jasinski
[SYStem OPerator]

.: www.dns.pl :.

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQIcBAEBAgAGBQJNg1vrAAoJEH26UYiRhe/gOxkQAIy97r7G9haNzF/7c1q8h7IX
0jUpFFIYjTVTw329nOT71SGazEvacHypclW1Ckt6xI2nDCQ0mkLeWvcEiEbyDThP
PcUNbZKBRWK/uOwNpIvrLEyHXfF2+W9JjLmDMjU9/+hA7mXwq4cVuF6ISWN1NZQL
HbQxdP5jDRWojhB2hIV3yzt7U3uniTxqKucVkeTQ8yO6L6N4itVY/zILWpo6YLUH
VJtnxsltGg7+Z/RhaQrHgzojQsuUMI/PoEKnNpY14YtnuxPFgGAcXOuDXv1N5Lm3
Mj5xfA4V1NZjTQivBQLfQ6hJCQ2B+gBn30CrABrBZ+SpJx4+HGF0JDanc1XQ3lBo
JnA8da1zmOOR2B0ideGpO0oXMZl0KBtPh9Hdh7TVTNf+uUD5rp4DU6jL0jrisvgy
h9nOn+t5jTq6evjM9ESDeggS5dVgkOzD1ZPOdTUkHEPgzK40x/BU0YApWiv9NJ/y
YzHzTp2q0Vpu4hPpb3bpu6pU2RNwue6/ake10RRxBzC35AVulfd4SydwXH9omGqU
2Ka2zzQaNsWphVSjqKyjD+sVhDkDKMGoN1lSyLQLXsvxiEQVFgyNsoSDlk8HQIuV
KbC+cO767uDKjh2Cmx4PWmZKZh7rtbynN85N1DoeJr9jz2Jb7JM9ErwNcZL9wjd8
+aQWV+6YyiKU80BITB/n
=/d/+
-----END PGP SIGNATURE-----