Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

#

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Jump to bottom

Investigate double PKCS#11 initialization #4

Closed
opencrypto opened this issue Nov 14, 2014 · 0 comments
Closed

Investigate double PKCS#11 initialization #4

opencrypto opened this issue Nov 14, 2014 · 0 comments
Labels
question

Comments

@opencrypto
Copy link
Member

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

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
# for free to join this conversation on GitHub. Already have an account? # to comment
Assignees
No one assigned
Labels
question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@opencrypto