This issue was reported on the OCSPD mailing list. It seems that the library performs HSM_init() twice and this prevents to get a valid session handle.
Nov 14 01:25:25 ocspd ocspd[1181]: OpenCA OCSPD v3.1.0 - starting.
Nov 14 01:25:25 ocspd ocspd[1181]: [token.c:2562] [DEBUG] ERROR, can not load directory /root/.libpki/profile.d!
Nov 14 01:25:25 ocspd ocspd[1181]: [token.c:834] [DEBUG] Can not load profiles (/root/.libpki/profile.d)
Nov 14 01:25:25 ocspd ocspd[1181]: [pki_config.c:1020] [DEBUG] Skipping file .
Nov 14 01:25:25 ocspd ocspd[1181]: [pki_config.c:1030] [DEBUG] Loading file /opt/openca/etc/ocspd/ca.d/tech_ca.xml
Nov 14 01:25:25 ocspd ocspd[1181]: [pki_config.c:1046] [DEBUG] Loaded /opt/openca/etc/ocspd/ca.d/tech_ca.xml file
Nov 14 01:25:25 ocspd ocspd[1181]: [pki_config.c:1020] [DEBUG] Skipping file ..
Nov 14 01:25:25 ocspd ocspd[1181]: [config.c:277] [DEBUG] Selected response digest algorithm: SHA1
Nov 14 01:25:25 ocspd ocspd[1181]: [config.c:298] [DEBUG] Selected signature digest algorithm: SHA1
Nov 14 01:25:25 ocspd ocspd[1181]: [config.c:382] [DEBUG] Building CA List
Nov 14 01:25:25 ocspd ocspd[1181]: [config.c:517] [DEBUG] Got CRL Url -> file:///opt/openca/etc/ocspd/crls/tech_ca.crl
Nov 14 01:25:25 ocspd ocspd[1181]: [crl.c:166] [DEBUG] CRL signature is verified!
Nov 14 01:25:25 ocspd ocspd[1181]: CRL matching CA cert ok [ 1 ]
Nov 14 01:25:25 ocspd ocspd[1181]: [crl.c:243] [DEBUG] CRL::Verify 1 [OK=1]
Nov 14 01:25:25 ocspd ocspd[1181]: INFO::CRL::3 Entries [ Technical CA ]
Nov 14 01:25:25 ocspd ocspd[1181]: [token.c:2562] [DEBUG] ERROR, can not load directory /root/.libpki/profile.d!
Nov 14 01:25:25 ocspd ocspd[1181]: [token.c:834] [DEBUG] Can not load profiles (/root/.libpki/profile.d)
Nov 14 01:25:25 ocspd ocspd[1181]: Configuration loaded and parsed
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:940] [DEBUG] GOT SEARCH PATHS => 1
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:953] [DEBUG] SEARCHING FOR Tech CA Token in dir /opt/openca/etc/ocspd/pki/token.d
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [.]
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:854] [DEBUG] Skipping .
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [tech_ca.xml.engine]
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:854] [DEBUG] Skipping tech_ca.xml.engine
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [tech_ca.xml.software]
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:854] [DEBUG] Skipping tech_ca.xml.software
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [tech_ca.xml]
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:868] [DEBUG] Opening File /opt/openca/etc/ocspd/pki/token.d/tech_ca.xmlNov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:880] [DEBUG] Getting Name Param...
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:886] [DEBUG] Got Name::Tech CA Token
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:894] [DEBUG] File successfully loaded /opt/openca/etc/ocspd/pki/token.d/tech_ca.xml
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:957] [DEBUG] FOUND => Tech CA Token [/opt/openca/etc/ocspd/pki/token.d]
Nov 14 01:25:25 ocspd ocspd[1182]: [token.c:576] [DEBUG] TK: Hardware Token: Name is cs-pkcs11
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:940] [DEBUG] GOT SEARCH PATHS => 1
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:953] [DEBUG] SEARCHING FOR cs-pkcs11 in dir /opt/openca/etc/ocspd/pki/hsm.d
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [.]
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:854] [DEBUG] Skipping .
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [cs-pkcs11.xml]
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:868] [DEBUG] Opening File /opt/openca/etc/ocspd/pki/hsm.d/cs-pkcs11.xml
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:880] [DEBUG] Getting Name Param...
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:886] [DEBUG] Got Name::cs-pkcs11
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:894] [DEBUG] File successfully loaded /opt/openca/etc/ocspd/pki/hsm.d/cs-pkcs11.xml
Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:957] [DEBUG] FOUND => cs-pkcs11 [/opt/openca/etc/ocspd/pki/hsm.d]
Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:325] [DEBUG] HSM_PKCS11_init()::Start
Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:408] [DEBUG] HSM INFO::Manufacturer Utimaco Safeware AG (v2.20)
Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:413] [DEBUG] HSM INFO::Library CryptoServer PKCS#11 Library R2 (v2.18)
Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:325] [DEBUG] HSM_PKCS11_init()::Start
Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:408] [DEBUG] HSM INFO::Manufacturer Utimaco Safeware AG (v2.20)
Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:413] [DEBUG] HSM INFO::Library CryptoServer PKCS#11 Library R2 (v2.18)
Nov 14 01:25:25 ocspd ocspd[1182]: [hsm_main.c:197] [DEBUG] HSM created in non-FIPS mode
Nov 14 01:25:25 ocspd ocspd[1182]: [utils/pkcs11_init.c:585] [DEBUG] HSM_PKCS11_session new ()::Failed opening a new session 0x4 with the token (0) [0x00000003]
Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:909] [DEBUG] HSM_PKCS11_SLOT_select()::Can not initiate a new session
Nov 14 01:25:25 ocspd ocspd[1182]: [token.c:677] Error while setting HSM slot to use
Nov 14 01:25:25 ocspd ocspd[1182]: [token.c:842] Can not load Token's Profile => Tech CA Token
Nov 14 01:25:25 ocspd ocspd[1182]: [core.c:42] [ERROR] Can not load default token (/opt/openca/etc/ocspd/ocspd.xml/Tech CA Token)
Nov 14 01:25:25 ocspd ocspd[1182]: Exiting, Glad to serve you, Master!
I also activated the trace in the PKCS11 library:
14.11.2014 01:25:25 | P11Config | I: PKCS11 version 2.18 [Linux-x86_64](Feb 14 2014)
14.11.2014 01:25:25 | P11Config | I: Configfile: /opt/openca/etc/pkcs11/cs_pkcs11_R2.cfg
14.11.2014 01:25:25 | C_GetInfo | T: enter...
14.11.2014 01:25:25 | C_Initialize | E: Error CKR_CRYPTOKI_ALREADY_INITIALIZED occured.
14.11.2014 01:25:25 | C_GetInfo | T: enter...
14.11.2014 01:25:25 | C_GetSessionInfo | T: enter...
14.11.2014 01:25:25 | operator[] | E: No entry with key 0x00000000 available.
14.11.2014 01:25:25 | C_GetSessionInfo | E: Error CKR_SESSION_HANDLE_INVALID occured.
14.11.2014 01:25:25 | C_OpenSession | T: enter...
14.11.2014 01:25:25 | operator[] | E: No entry with key 0x00000000 available.
14.11.2014 01:25:25 | C_OpenSession | E: Error CKR_SLOT_ID_INVALID occured.
Here are the things I don’t understand:
Why is the daemon performing a C_Initialize twice (HSM_PKCS11_init)?
Why do I get a CKR_SLOT_ID_INVALID error on the C_OpenSession (HSM_PKCS11_session new)?
I wrote some C code using the same PKCS11 library and configuration file, but can’t reproduce the problem:
./cs_openssession
This issue was reported on the OCSPD mailing list. It seems that the library performs HSM_init() twice and this prevents to get a valid session handle.
Nov 14 01:25:25 ocspd ocspd[1181]: OpenCA OCSPD v3.1.0 - starting. Nov 14 01:25:25 ocspd ocspd[1181]: [token.c:2562] [DEBUG] ERROR, can not load directory /root/.libpki/profile.d! Nov 14 01:25:25 ocspd ocspd[1181]: [token.c:834] [DEBUG] Can not load profiles (/root/.libpki/profile.d) Nov 14 01:25:25 ocspd ocspd[1181]: [pki_config.c:1020] [DEBUG] Skipping file . Nov 14 01:25:25 ocspd ocspd[1181]: [pki_config.c:1030] [DEBUG] Loading file /opt/openca/etc/ocspd/ca.d/tech_ca.xml Nov 14 01:25:25 ocspd ocspd[1181]: [pki_config.c:1046] [DEBUG] Loaded /opt/openca/etc/ocspd/ca.d/tech_ca.xml file Nov 14 01:25:25 ocspd ocspd[1181]: [pki_config.c:1020] [DEBUG] Skipping file .. Nov 14 01:25:25 ocspd ocspd[1181]: [config.c:277] [DEBUG] Selected response digest algorithm: SHA1 Nov 14 01:25:25 ocspd ocspd[1181]: [config.c:298] [DEBUG] Selected signature digest algorithm: SHA1 Nov 14 01:25:25 ocspd ocspd[1181]: [config.c:382] [DEBUG] Building CA List Nov 14 01:25:25 ocspd ocspd[1181]: [config.c:517] [DEBUG] Got CRL Url -> file:///opt/openca/etc/ocspd/crls/tech_ca.crl Nov 14 01:25:25 ocspd ocspd[1181]: [crl.c:166] [DEBUG] CRL signature is verified! Nov 14 01:25:25 ocspd ocspd[1181]: CRL matching CA cert ok [ 1 ] Nov 14 01:25:25 ocspd ocspd[1181]: [crl.c:243] [DEBUG] CRL::Verify 1 [OK=1] Nov 14 01:25:25 ocspd ocspd[1181]: INFO::CRL::3 Entries [ Technical CA ] Nov 14 01:25:25 ocspd ocspd[1181]: [token.c:2562] [DEBUG] ERROR, can not load directory /root/.libpki/profile.d! Nov 14 01:25:25 ocspd ocspd[1181]: [token.c:834] [DEBUG] Can not load profiles (/root/.libpki/profile.d) Nov 14 01:25:25 ocspd ocspd[1181]: Configuration loaded and parsed Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:940] [DEBUG] GOT SEARCH PATHS => 1 Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:953] [DEBUG] SEARCHING FOR Tech CA Token in dir /opt/openca/etc/ocspd/pki/token.d Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [.] Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:854] [DEBUG] Skipping . Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [tech_ca.xml.engine] Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:854] [DEBUG] Skipping tech_ca.xml.engine Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [tech_ca.xml.software] Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:854] [DEBUG] Skipping tech_ca.xml.software Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [tech_ca.xml] Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:868] [DEBUG] Opening File /opt/openca/etc/ocspd/pki/token.d/tech_ca.xmlNov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:880] [DEBUG] Getting Name Param... Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:886] [DEBUG] Got Name::Tech CA Token Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:894] [DEBUG] File successfully loaded /opt/openca/etc/ocspd/pki/token.d/tech_ca.xml Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:957] [DEBUG] FOUND => Tech CA Token [/opt/openca/etc/ocspd/pki/token.d] Nov 14 01:25:25 ocspd ocspd[1182]: [token.c:576] [DEBUG] TK: Hardware Token: Name is cs-pkcs11 Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:940] [DEBUG] GOT SEARCH PATHS => 1 Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:953] [DEBUG] SEARCHING FOR cs-pkcs11 in dir /opt/openca/etc/ocspd/pki/hsm.d Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [.] Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:854] [DEBUG] Skipping . Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:850] [DEBUG] Processing file [cs-pkcs11.xml] Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:868] [DEBUG] Opening File /opt/openca/etc/ocspd/pki/hsm.d/cs-pkcs11.xml Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:880] [DEBUG] Getting Name Param... Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:886] [DEBUG] Got Name::cs-pkcs11 Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:894] [DEBUG] File successfully loaded /opt/openca/etc/ocspd/pki/hsm.d/cs-pkcs11.xml Nov 14 01:25:25 ocspd ocspd[1182]: [pki_config.c:957] [DEBUG] FOUND => cs-pkcs11 [/opt/openca/etc/ocspd/pki/hsm.d] Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:325] [DEBUG] HSM_PKCS11_init()::Start Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:408] [DEBUG] HSM INFO::Manufacturer Utimaco Safeware AG (v2.20) Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:413] [DEBUG] HSM INFO::Library CryptoServer PKCS#11 Library R2 (v2.18) Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:325] [DEBUG] HSM_PKCS11_init()::Start Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:408] [DEBUG] HSM INFO::Manufacturer Utimaco Safeware AG (v2.20) Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:413] [DEBUG] HSM INFO::Library CryptoServer PKCS#11 Library R2 (v2.18) Nov 14 01:25:25 ocspd ocspd[1182]: [hsm_main.c:197] [DEBUG] HSM created in non-FIPS mode Nov 14 01:25:25 ocspd ocspd[1182]: [utils/pkcs11_init.c:585] [DEBUG] HSM_PKCS11_session new ()::Failed opening a new session 0x4 with the token (0) [0x00000003] Nov 14 01:25:25 ocspd ocspd[1182]: [pkcs11_hsm.c:909] [DEBUG] HSM_PKCS11_SLOT_select()::Can not initiate a new session Nov 14 01:25:25 ocspd ocspd[1182]: [token.c:677] Error while setting HSM slot to use Nov 14 01:25:25 ocspd ocspd[1182]: [token.c:842] Can not load Token's Profile => Tech CA Token Nov 14 01:25:25 ocspd ocspd[1182]: [core.c:42] [ERROR] Can not load default token (/opt/openca/etc/ocspd/ocspd.xml/Tech CA Token) Nov 14 01:25:25 ocspd ocspd[1182]: Exiting, Glad to serve you, Master! I also activated the trace in the PKCS11 library: 14.11.2014 01:25:25 | P11Config | I: PKCS11 version 2.18 [Linux-x86_64](Feb 14 2014) 14.11.2014 01:25:25 | P11Config | I: Configfile: /opt/openca/etc/pkcs11/cs_pkcs11_R2.cfg 14.11.2014 01:25:25 | C_GetInfo | T: enter... 14.11.2014 01:25:25 | C_Initialize | E: Error CKR_CRYPTOKI_ALREADY_INITIALIZED occured. 14.11.2014 01:25:25 | C_GetInfo | T: enter... 14.11.2014 01:25:25 | C_GetSessionInfo | T: enter... 14.11.2014 01:25:25 | operator[] | E: No entry with key 0x00000000 available. 14.11.2014 01:25:25 | C_GetSessionInfo | E: Error CKR_SESSION_HANDLE_INVALID occured. 14.11.2014 01:25:25 | C_OpenSession | T: enter... 14.11.2014 01:25:25 | operator[] | E: No entry with key 0x00000000 available. 14.11.2014 01:25:25 | C_OpenSession | E: Error CKR_SLOT_ID_INVALID occured.
Here are the things I don’t understand:
I wrote some C code using the same PKCS11 library and configuration file, but can’t reproduce the problem: ./cs_openssession
Slot Info: slot desc. : 3001@172.16.88.10 - SLOT_0000
manufacturerID : Utimaco Safeware AG
flags : 0x00000005 hardwareVersion : 3.0 firmwareVersion : 2.1
Session Info: slotID: 0 state : 0x00 flags : 0x04