"Error: java.security.ProviderException: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_USER_NOT_LOGGED_IN" for Thales Protect ToolKit 7.2 emurator mode

[umegaya]

hi, we try to build serious pki with ejbca-ce container (keyfactor/ejbca-ce:7.10.0.2) and using HSM.

testing with softhsm2 do quite well, then we try to integrate our ejbca infrastructure with Thales Protect Server 3+ External / Protect ToolKit C 7.2. first we test ejbca with Protect ToolKit C's emurator mode, because the documentation site
https://download.primekey.com/docs/EJBCA-Enterprise/7_0_0/Hardware_Security_Modules_(HSM).html#src-26771673_safe-id-aWQtLkhhcmR3YXJlU2VjdXJpdHlNb2R1bGVzKEhTTSl2Ny4wLjAtU2FmZU5ldF9Qcm90ZWN0U2VydmVyU2FmZU5ldFByb3RlY3RTZXJ2ZXI seems to encourages it.

it seems that ejbca.sh cryptotoken create goes well, we saw new crypto token is created with hsm slot and able to view from https://our.ejbca.deployment/ejbca/adminweb/cryptotoken/cryptotokens.xhtml and https://our.ejbca.deployment/ejbca/adminweb/cryptotoken/cryptotoken.jsf?cryptoTokenId=$id_here&ref=default, like this

but pressing Generate new key pair, it pauses for a few seconds, then throws error in title.

Error: java.security.ProviderException: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_USER_NOT_LOGGED_IN.

do you have any idea what I am missing out?

or the version of protect toolkit C in explanation of above document site, seems to be a bit old. does ejbca-ce still support latest protect toolkit C's emurator mode?

regards,

[primetomas]

ProtectServer should be supported.

CKR_USER_NOT_LOGGED_IN is a message from the HSM, which makes it sound as if the HSM was not logged into, the session was broken or something like that. Skip auto-activation and activate the crypto token manually.

[umegaya]

@primetomas hi, Skip auto-activation does not seem to help. I activated crypto token manually and try to generate key but got same error.

any other suggestion?

regards,

[umegaya]

@primetomas

because softHSM works correctly like this,

I have created the exact same objects in the HSM provided by ptk emurator mode using pkcs11-tools -write-object as objects contained in softHSM. (see below logs)

unfortunately still keys are not visible from cryptotoken.

### ptk emurator mode
# pkcs11-tool --module=/opt/safenet/protecttoolkit7/ptk/lib/libcryptoki.so --list-objects -l    
Using slot 0 with a present token (0x0)
Logging in to "** slot name is reducted **".
Please enter User PIN: 
Certificate Object; type = X.509 cert
  label:      ca2-signKey
  subject:    DN: **DN is reducted**
  ID:         6361322d7369676e4b6579
Certificate Object; type = X.509 cert
  label:      ca1-encryptKey
  subject:    DN: **DN is reducted**
  ID:         6361312d656e63727970744b6579
Private Key Object; RSA 
  label:      ca1-signKey
  ID:         6361312d7369676e4b6579
  Usage:      decrypt, sign, unwrap
warning: PKCS11 function C_GetAttributeValue(ALWAYS_AUTHENTICATE) failed: rv = CKR_ATTRIBUTE_TYPE_INVALID (0x12)

Private Key Object; RSA 
  label:      ca2-encryptKey
  ID:         6361322d656e63727970744b6579
  Usage:      decrypt, sign, unwrap
warning: PKCS11 function C_GetAttributeValue(ALWAYS_AUTHENTICATE) failed: rv = CKR_ATTRIBUTE_TYPE_INVALID (0x12)

Certificate Object; type = X.509 cert
  label:      ca1-signKey
  subject:    DN: **DN is reducted**
  ID:         6361312d7369676e4b6579
Certificate Object; type = X.509 cert
  label:      ca2-encryptKey
  subject:    DN: **DN is reducted**
  ID:         6361322d656e63727970744b6579
Private Key Object; RSA 
  label:      ca1-encryptKey
  ID:         6361312d656e63727970744b6579
  Usage:      decrypt, sign, unwrap
warning: PKCS11 function C_GetAttributeValue(ALWAYS_AUTHENTICATE) failed: rv = CKR_ATTRIBUTE_TYPE_INVALID (0x12)

Private Key Object; RSA 
  label:      ca2-signKey
  ID:         6361322d7369676e4b6579
  Usage:      decrypt, sign, unwrap
warning: PKCS11 function C_GetAttributeValue(ALWAYS_AUTHENTICATE) failed: rv = CKR_ATTRIBUTE_TYPE_INVALID (0x12)

### softHSM
# pkcs11-tool --module=/usr/local/lib/softhsm/libsofthsm2.so --list-objects -l
Using slot 0 with a present token (0x75c81298)
Logging in to "**slot name is reducted**".
Please enter User PIN: 
Certificate Object; type = X.509 cert
  label:      ca2-signKey
  subject:    DN: **DN is reducted**
  ID:         6361322d7369676e4b6579
Certificate Object; type = X.509 cert
  label:      ca2-encryptKey
  subject:    DN: **DN is reducted**
  ID:         6361322d656e63727970744b6579
Private Key Object; RSA 
  label:      ca2-encryptKey
  ID:         6361322d656e63727970744b6579
  Usage:      decrypt, sign, unwrap
Private Key Object; RSA 
  label:      ca1-encryptKey
  ID:         6361312d656e63727970744b6579
  Usage:      decrypt, sign, unwrap
Private Key Object; RSA 
  label:      ca2-signKey
  ID:         6361322d7369676e4b6579
  Usage:      decrypt, sign, unwrap
Certificate Object; type = X.509 cert
  label:      ca1-signKey
  subject:    DN: **DN is reducted**
  ID:         6361312d7369676e4b6579
Certificate Object; type = X.509 cert
  label:      ca1-encryptKey
  subject:    DN: **DN is reducted**
  ID:         6361312d656e63727970744b6579
Private Key Object; RSA 
  label:      ca1-signKey
  ID:         6361312d7369676e4b6579
  Usage:      decrypt, sign, unwrap

but I saw strange error warning: PKCS11 function C_GetAttributeValue(ALWAYS_AUTHENTICATE) failed: rv = CKR_ATTRIBUTE_TYPE_INVALID (0x12) when try to see objects in HSM of ptk emurator mode only.

do you think this causes problem?

regards,

[umegaya]

@primetomas I have enabled ptk library function call logging, with instruction of https://www.thalesdocs.com/gphsm/ptk/protectserver3/docs/ps_ptk_docs/ptkc_programming/logger_library/index.html

logs are like this:

pid(355) tid(139852439500544) time(2023-02-02 06:55:42.403)     > C_GenerateKeyPair hSession=0x00000003 pMechanism=0x0x55c2b65e7c40{type=0x0{RSA_PKCS_KEY_PAIR_GEN} pParam=0x(nil) paramLen=0} pPubTpl=0x 0x55c2b7434000ubTplCount=6 pPriTpl=0x0x55c2b7434160 priTplCount=8 phPubKey=0x0x55c2b65e7c60 phPriKey=0x0x55c2b65e7c68

pid(355) tid(139852439500544) time(2023-02-02 06:55:57.352)     << C_GenerateKeyPair rv=0x00000101{user not logged in} phPubKey=0x0x55c2b65e7c60{0x0000000B} phPriKey=0x0x55c2b65e7c68{0x00000000

I checked all log line, but actually C_Login was not called before C_GenerateKeyPair was called.

# cat /tmp/ct.log | grep C_Login
# cat /tmp/ct.log | grep C_GenerateKeyPair
pid(355) tid(139852439500544) time(2023-02-02 06:55:42.403)     > C_GenerateKeyPair hSession=0x00000003 pMechanism=0x0x55c2b65e7c40{type=0x0{RSA_PKCS_KEY_PAIR_GEN} pParam=0x(nil) paramLen=0} pPubTpl=0x 0x55c2b7434000ubTplCount=6 pPriTpl=0x0x55c2b7434160 priTplCount=8 phPubKey=0x0x55c2b65e7c60 phPriKey=0x0x55c2b65e7c68
pid(355) tid(139852439500544) time(2023-02-02 06:55:57.352)     << C_GenerateKeyPair rv=0x00000101{user not logged in} phPubKey=0x0x55c2b65e7c60{0x0000000B} phPriKey=0x0x55c2b65e7c68{0x00000000

is it expect behaviour of ejbca? if so, how can ejbca avoid user not logged in without calling C_Login?
regards,

[primetomas]

C_Login is called to start the session. PKCS#11 sessions are long lived and you call C_Login once, and then you can use the session (which you cache) to do many operation. I suspect some specific HSM configuration here.
You can troubleshoot much easier using clientToolBox, see the documentation here for instructions, and also ProtectServer specific config. https://doc.primekey.com/ejbca/ejbca-integration/hardware-security-modules-hsm/thales-protectserver

For EJBCA Enterprise, it is advised to move to P11NG. See here:
https://doc.primekey.com/ejbca/ejbca-operations/ejbca-operations-guide/command-line-interfaces/p11ng-cli
and here (for references):
https://doc.primekey.com/ejbca/ejbca-integration/hardware-security-modules-hsm/utimaco-cryptoserver-cp5
https://doc.primekey.com/ejbca/ejbca-integration/hardware-security-modules-hsm/securosys-primus-hsm-and-cloudshsm-service
https://doc.primekey.com/ejbca/ejbca-integration/hardware-security-modules-hsm/smartcard-hsm

[umegaya]

@primetomas

C_Login is called to start the session. PKCS#11 sessions are long lived and you call C_Login once, and then you can use the session (which you cache) to do many operation.

but does this mean ejbca should call C_Login at least once for interacting HSM, right?

the log I checked in #230 (comment), should contains all the pkcs11 operation since ejbca startup.

since the log does not contain C_Login, I think ejbca never calls C_Login since startup.

is this expected behaviour?

I suspect some specific HSM configuration here.

possible. any idea what configuration should I check? I think its not critical one. because we evaluate multiple ca server product and another ca server correctly run on our ptk emurator mode HSM.

or EJBCA Enterprise, it is advised to move to P11NG.

I tried to use p11ng like following.

• Replaced keyfactor/ejbca-ce:7.10.0.2 with registry.primekey.com/primekey/ejbca-ee:7.11.0, tried p11ng-cli.sh generatekey|generatekeypair
• p11ng-cli.sh asks for the token password, so at least I was able to create the key by entering it.
  • In that case, C_Login was recorded in the log as follows. Considering these things with past observed fact, it is possible that the ejbca body does not call C_Login, causing an error (CKR_USER_NOT_LOGGED_IN)

    # cat /tmp/ct.log | grep C_Login
    pid(21) tid(139867804325696) time(2023-02-03 03:17:13.339) > C_Login hSession=0x00000002 userType=1{USER} pPin=0x0x631130 pinLen=6
    pid(21) tid(139867804325696) time(2023-02-03 03:17:13.340) < C_Login rv=0x00000000{success} 
    

• However, the key created by p11ng-cli.sh is also not visible to ejbca after all (even after restarting ejbca-ee). The situation was not improved because the key creation in ptk emurator mode HSM is already done using pkcs11-tool (https://github.com/OpenSC/OpenSC) as described in "Error: java.security.ProviderException: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_USER_NOT_LOGGED_IN" for Thales Protect ToolKit 7.2 emurator mode #230 (comment).
• When I try to generate new key pair from ejbca ee's GUI, I get the same error as before java.security.ProviderException: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_USER_ NOT_LOGGED_IN happens
• ejbca ee itself appears to use jdk.crypto.cryptoki as well as ce, so it would look like the problem is either jdk.crypto.cryptoki or its usage does not support ptk emurator mode well, which p11ng cannot help to solve problem.

[primetomas]

When using P11NG, you must use the "PKCS11NG Crypto Token" in EJBCA, not the "PKCS11 Crypto Token". "PKCS11 Crypto Token" uses Java PKCS#11 provider where Java/OpenJDK does all the PKCS#11 calls with no control from EJBCA.
"PKCS11NG Crypto Token" does not use Java PKCS#11 provider.

[umegaya]

@primetomas thanks, but how can I create "PKCS11NG Crypto Token" from command line? I tried ejbca.sh cryptotoken create --token ${token_name} --pin ${HSM_PIN} --autoactivate true \ --type PKCS11NGCryptoToken --lib $(crypto_lib) \ --slotlabel "${slot_label}" --slotlabeltype SLOT_LABEL but got error Invalid CryptoToken type: PKCS11NGCryptoToken.

could you tell me proper crypto token type to create PKCS11NG backed crypto token? (I checked GUI at https://my.ejcba.deployment/ejbca/adminweb/cryptotoken/cryptotoken.jsf?cryptoTokenId=0&ref=cryptotokens of ejbca ee, but it only shows SOFT, Azure Key Vault, AWS KMS in its select box)

regards,

EDIT: --type P11NGCryptoToken also does not help
EDIT: reading ejbca ce repository, --type Pkcs11NgCryptoToken seems to work. but got error

2023-02-06 01:03:01,728+0000 INFO  [org.ejbca.ui.cli.cryptotoken.CryptoTokenCreateCommand] (main) The P11 slot is already used by another crypto token: JackNJI11 (database protection?)
2023-02-06 01:03:01,729+0000 INFO  [org.ejbca.ui.cli.cryptotoken.CryptoTokenCreateCommand] (main) Do you want to continue anyhow? [yes/no]: 

EDIT: adding --forceusedslots option to ejbca.sh cryptotoken create solves problem above

[umegaya]

@primetomas ok, I can create key with ptk emurator mode, by using Pkcs11NgCryptoToken of ejbca enterprise.
because I saw many C_Login calls when I used Pkcs11NgCryptoToken, but not for PKCS11CryptoToken of ejbca-ce, absence of C_Login call seems to relate with the problem of ejbca-ce.

# cat /tmp/ct.log | grep C_Login
pid(355) tid(140436106987264) time(2023-02-06 01:12:21.970)     > C_Login hSession=0x00020002 userType=1{USER} pPin=0x0x563d7bcf6840 pinLen=6
pid(355) tid(140436106987264) time(2023-02-06 01:12:21.970)     < C_Login rv=0x00000000{success} 
pid(355) tid(140436106987264) time(2023-02-06 01:12:21.975)     > C_Login hSession=0x00020002 userType=1{USER} pPin=0x0x563d7bcf6840 pinLen=6
pid(355) tid(140436106987264) time(2023-02-06 01:12:21.975)     << C_Login rv=0x00000100{user already logged in} 
pid(355) tid(140436106987264) time(2023-02-06 01:12:21.975)     > C_Login hSession=0x00020002 userType=1{USER} pPin=0x0x563d7fc3c8f0 pinLen=6
pid(355) tid(140436106987264) time(2023-02-06 01:12:21.975)     << C_Login rv=0x00000100{user already logged in} 
pid(355) tid(140436081522432) time(2023-02-06 01:12:40.435)     > C_Login hSession=0x00020002 userType=1{USER} pPin=0x0x563d7e8eeb90 pinLen=6
pid(355) tid(140436081522432) time(2023-02-06 01:12:40.435)     << C_Login rv=0x00000100{user already logged in} 
pid(355) tid(140436081522432) time(2023-02-06 01:12:43.176)     > C_Login hSession=0x00020002 userType=1{USER} pPin=0x0x563d7e800600 pinLen=6
pid(355) tid(140436081522432) time(2023-02-06 01:12:43.176)     << C_Login rv=0x00000100{user already logged in} 
pid(355) tid(140436081522432) time(2023-02-06 01:13:07.268)     > C_Login hSession=0x00020002 userType=1{USER} pPin=0x0x563d7fb782c0 pinLen=6
pid(355) tid(140436081522432) time(2023-02-06 01:13:07.268)     << C_Login rv=0x00000100{user already logged in} 

[primetomas]

Ah, that was a regression that the Pkcs11NgCryptoToken type does not show up when you do "bin/ejbca.sh cryptotoken --help". But you should be able to do it anyway with the correct type as you noticed.

The regression will be fixed in the next release. Thanks for the report.