step-ca pkcs11 HSM startup issue

[johanpostema]

Hi,

step-ca fails to start when trying to use pkcs11 and keys stored in an HSM device (entrust).
The error step-ca returns on startup is a bit generic and not very usefull:

./step-ca
badger 2025/09/24 16:33:19 INFO: All 0 tables opened in 0s
badger 2025/09/24 16:33:19 INFO: Replaying file id: 0 at offset: 0
badger 2025/09/24 16:33:19 INFO: Replay took: 5.974168ms
2025/09/24 16:33:19 Building new tls configuration using step-ca x509 Signer Interface
authority.GetTLSCertificate: error creating certificate: pkcs11: 0x6: CKR_FUNCTION_FAILED

When checking the HSM client/library logs there is too much logging to include here, but the tail of the log:

2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CC <    rv 0x00000000 (CKR_OK)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 >>   C_OpenSession
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 >    slotID 0x2D622495
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 >    flags 0x00000006
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    new session handle 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    NFC__hash_session 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    hashmap insert hash 46669DAC9FA probe 122 step 19
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    Session 0x7f4e64039530
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    insert try hashmap[122] hash 00000000 value (nil)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    insert hashmap[122] value 0x7f4e64039530
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    After insert size 128, used 3
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 <    *phSession 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 <    rv 0x00000000 (CKR_OK)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >>   C_SignInit
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >    hSession 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >    pMechanism->mechanism 0x00000001 (CKM_RSA_PKCS)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >    hKey 0x00000460
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    NFC__hash_session 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    hashmap lookup hash 46669DAC9FA probe 122 step 19
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    lookup try hashmap[122] hash 46669DAC9FA value 0x7f4e64039530
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    found hashmap[122] value 0x7f4e64039530
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    NFC__hash_object_handle 0x00000460
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    hashmap lookup hash 2300A6D4A11 probe 17 step 21
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    lookup try hashmap[17] hash 2300A6D4A11 value 0x7f4e640301e0
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    found hashmap[17] value 0x7f4e640301e0
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    NFC__CheckMechanismAllowedGetInfo type 0x00000001
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    NFC__GetMechanismInfoEx type 0x00000001
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    NFC__SignInitVerifyPublic ok
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD <    rv 0x00000000 (CKR_OK)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >>   C_Sign
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >    hSession 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >
  pData= 51 bytes
    3031300d 06096086 48016503 04020105 000420cc bd529aba 16189efc 34b3d522
                                  0b0fc3dc 974455a3 6b9fc028 518bb35d 42375b

2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >    pSignature (nil)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    NFC__hash_session 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    hashmap lookup hash 46669DAC9FA probe 122 step 19
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    lookup try hashmap[122] hash 46669DAC9FA value 0x7f4e64039530
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    found hashmap[122] value 0x7f4e64039530
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    SignPublic
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    keyobj 0x7f4e640301e0
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    Sign estimate length 512
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD <    *pulSignatureLen 512
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD <    rv 0x00000000 (CKR_OK)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >>   C_Sign
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >    hSession 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >
  pData= 51 bytes
    3031300d 06096086 48016503 04020105 000420cc bd529aba 16189efc 34b3d522
                                  0b0fc3dc 974455a3 6b9fc028 518bb35d 42375b

2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >    pSignature 0x7f4e64038910
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD >    *pulSignatureLen 512l
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 00000000 D    NFC__hash_session 0x000008CD
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    hashmap lookup hash 46669DAC9FA probe 122 step 19
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    lookup try hashmap[122] hash 46669DAC9FA value 0x7f4e64039530
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    found hashmap[122] value 0x7f4e64039530
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    SignPublic
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    keyobj 0x7f4e640301e0
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    NFC__load_key objdata 0x00000460 (0x7f4e640301e0)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    loading blob single, module 1, num realslots 4
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    load_blob_single objdata 0x00000460 (0x7f4e640301e0), logtokid 0x00000000
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    NFC__getconnection
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    load_blob_single loaded keyid 0x7f4e84b5b304 (module 0)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    realkeyids[1] = 0xa16a6e56
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    NFC__alloc_transact, slot_mutex_held FALSE
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    Merged keyid 0xa16a6e55, (realkeyids 0x7f4e640344b0 n_realkeyids 1)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    keyid is 0xa16a6e55
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    n_realkeyids is 1
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    NFC__load_key load_blob_merged keyid 0xa16a6e55 (module 0)
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    CKM_SHA256_RSA_PKCS - plain text hash
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    NFC__alloc_transact, slot_mutex_held FALSE
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    Generic stub command Sign returned 62
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD D    Status_StrictFIPS140
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD Error: Generic stub command Sign returned 62
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD Error: Status_StrictFIPS140
2025-09-24 16:25:24 [2036444] tc0c6b5844e7f0000: pkcs11: 000008CD <    rv 0x00000006 (CKR_FUNCTION_FAILED)

From what I can understand from this logging is that on startup
- some type of ASN.1 SHA256 OID that wants to be signed (see the data starting with 3031300d ....)
- it looks like the mechanism requested is CKM_RSA_PKCS
- it looks like the mechanism it gets is CKM_SHA256_RSA_PKCS instead(?)
- it returns an error Status_StrictFIPS140 which indicates the request is not conform the FIPS140 standard?

The HSM is configured in FIPS140-2 level 3.

Just using OpenSSL and pkcs11 for signing works fine.