PKCS#11: Cannot perform signature 512:'CKR_FUNCTION_REJECTED'

[jank04]

Hello,

I have trouble using the IsoApplet to work with OpenVPN. The VPN Server as such does work, when I use the Keypair/Cert inline in the .ovpn file. When I import the Keypair + Cert to the SmartCard I cannot authenticate. It is no difference, wether or not import the files, or use on card generation and CSR.

I am using OpenSC as PKCS11 provider.

Some additional info:

I am using a NXP J3H145 dual interface JavaCard.

<javacard jckit="ext/sdks/jc305u3_kit">
            <cap targetsdk="ext/sdks/jc304_kit" aid="f2:76:a2:88:bc:fb:a6:9d:34:f3:10" output="IsoApplet.cap" sources="src" version="1.0">

.\openvpn.exe --show-pkcs11-ids "C:\Program Files\OpenSC Project\OpenSC\pkcs11\opensc-pkcs11.dll"
Certificate
       DN:             C=DE, ST=XXX, L=X, O=X OU=VPN, CN=SC VPN S/N X, emailAddress=X
       Serial:         XXX
       Serialized id:  pkcs11:model=PKCS%2315;token=Jan%20XXX%20%28User%20PIN%29;manufacturer=NXP;serial=XXX;id=E

I have edited the isoApplet Profile in OpenSC, so that the manufacurer is not "unknown" and the token label is not "JavaCard IsoApplet".

This is the full OpenVPN Client-Log (verb lvl 7) https://pastebin.com/nsf13PRy
Some log entries that are important (in my opinion):

2021-06-26 17:09:23 us=333565 OpenVPN 2.5.3 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Jun 17 2021
2021-06-26 17:09:24 us=110498 PKCS#11: Adding PKCS#11 provider 'C:\Program Files\OpenSC Project\OpenSC\pkcs11\opensc-pkcs11.dll'
2021-06-26 17:09:24 us=110498 PKCS#11: Adding provider 'C:\Program Files\OpenSC Project\OpenSC\pkcs11\opensc-pkcs11.dll'-'C:\Program Files\OpenSC Project\OpenSC\pkcs11\opensc-pkcs11.dll'
2021-06-26 17:09:25 us=405056 PKCS#11: Provider 'C:\Program Files\OpenSC Project\OpenSC\pkcs11\opensc-pkcs11.dll' added rv=0-'CKR_OK'
2021-06-26 17:09:25 us=409046 PKCS#11: Creating a new session
2021-06-26 17:09:25 us=471878 VERIFY OK: depth=2, C=DE, ST=XXX, L=XXX, O=XXX, OU=Certificate Authority, CN=ROOT CA V2 XXX, emailAddress=support@XXX
2021-06-26 17:09:25 us=472876 VERIFY OK: depth=1, C=DE, ST=XXX, L=XXX, O=XXX, OU=Certificate Authority, CN=Intermediate CA VPN V2 XXX, emailAddress=support@XXX
2021-06-26 17:09:25 us=472876 VERIFY KU OK
2021-06-26 17:09:25 us=472876 Validating certificate extended key usage
2021-06-26 17:09:25 us=472876 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2021-06-26 17:09:25 us=472876 VERIFY EKU OK
2021-06-26 17:09:25 us=472876 VERIFY X509NAME OK: C=DE, ST=XXX, L=XXX, O=XXX, OU=VPN, CN=OpenVPN_SRV_3, emailAddress=support@XXX
2021-06-26 17:09:25 us=472876 VERIFY OK: depth=0, C=DE, ST=XXX, L=XXX, O=XXX, OU=VPN, CN=OpenVPN_SRV_3, emailAddress=support@XXX
2021-06-26 17:09:25 us=472876 PKCS#11: Performing signature
2021-06-26 17:09:25 us=472876 PKCS#11: Getting key attributes
2021-06-26 17:09:25 us=472876 PKCS#11: Get private key attributes failed: 130:'CKR_OBJECT_HANDLE_INVALID'
2021-06-26 17:09:25 us=474871 PKCS#11: Calling pin_prompt hook for ''
2021-06-26 17:09:27 us=503476 MANAGEMENT: CMD 'password [...]'
2021-06-26 17:09:27 us=503476 PKCS#11: pin_prompt hook return rv=0
2021-06-26 17:09:27 us=549354 PKCS#11: Cannot perform signature 512:'CKR_FUNCTION_REJECTED'
2021-06-26 17:09:27 us=549354 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
2021-06-26 17:09:27 us=549354 TLS_ERROR: BIO read tls_read_plaintext error
2021-06-26 17:09:27 us=549354 TLS Error: TLS object -> incoming plaintext read error
2021-06-26 17:09:27 us=549354 TLS Error: TLS handshake failed

The signature algorithm used to sign the certificate is sha256

Maybe you have some ideas to resolve this issue? Maybe it is just a config related thing?

[philipWendland]

Hi,
Get private key attributes failed: 130:'CKR_OBJECT_HANDLE_INVALID'
is suspicious, yes.
I never used OpenSC with OpenVPN, and never with Windows.
Before I try to reproduce this, the next step for further debugging would be to acquire OpenSC logs.
Could you try OPENSC_DEBUG=10 to get those?

[jank04]

Yes of course. Here you are: https://pastebin.com/W7PgmtA6

I think at P:13004; T:9796 2021-07-10 11:22:30.535 [opensc-pkcs11] trying driver 'isoApplet' it gets interesting. At least the correct driver is used at this point. From there on I think it is looking for objects like Certs, Keys, Auth, and so on. At the end I think there comes OpenVPN into play, because I found my entered PIN there (which I redacted). I hope there is nothing more critical private stuff in there. Some "private" attributes like CN, State and so on I did not touch. Maybe interesting for troubleshooting and better understanding.

Nearly at the end there is:

P:13004; T:9796 2021-07-10 11:22:33.027 [opensc-pkcs11] card.c:523:sc_unlock: called
P:13004; T:9796 2021-07-10 11:22:33.027 [opensc-pkcs11] sec.c:256:sc_pin_cmd: returning with: 0 (Success)
P:13004; T:9796 2021-07-10 11:22:33.027 [opensc-pkcs11] PIN cmd result 0
P:13004; T:9796 2021-07-10 11:22:33.027 [opensc-pkcs11] pkcs15-pin.c:761:sc_pkcs15_pincache_add: called
P:13004; T:9796 2021-07-10 11:22:33.027 [opensc-pkcs11] PIN(User PIN) cached
P:13004; T:9796 2021-07-10 11:22:33.031 [opensc-pkcs11] card.c:523:sc_unlock: called
P:13004; T:9796 2021-07-10 11:22:33.031 [opensc-pkcs11] reader-pcsc.c:736:pcsc_unlock: called
P:13004; T:9796 2021-07-10 11:22:33.032 [opensc-pkcs11] pkcs15-pin.c:477:sc_pkcs15_verify_pin_with_session_pin: returning with: 0 (Success)
P:13004; T:9796 2021-07-10 11:22:33.032 [opensc-pkcs11] pkcs15-pin.c:761:sc_pkcs15_pincache_add: called
P:13004; T:9796 2021-07-10 11:22:33.032 [opensc-pkcs11] PIN(User PIN) cached
P:13004; T:9796 2021-07-10 11:22:33.032 [opensc-pkcs11] pkcs15-pin.c:333:sc_pkcs15_verify_pin: returning with: 0 (Success)
P:13004; T:9796 2021-07-10 11:22:33.033 [opensc-pkcs11] PKCS15 verify PIN returned 0
P:13004; T:9796 2021-07-10 11:22:33.033 [opensc-pkcs11] Check if pkcs15 object list can be completed.
P:13004; T:9796 2021-07-10 11:22:33.033 [opensc-pkcs11] fLogin() rv 0
P:13004; T:9796 2021-07-10 11:22:33.033 [opensc-pkcs11] C_FindObjectsInit(slot = 0)
P:13004; T:9796 2021-07-10 11:22:33.033 [opensc-pkcs11] pkcs11-object.c:363:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = CKO_PRIVATE_KEY
P:13004; T:9796 2021-07-10 11:22:33.033 [opensc-pkcs11] pkcs11-object.c:363:C_FindObjectsInit: C_FindObjectsInit(): CKA_ID = 45
P:13004; T:9796 2021-07-10 11:22:33.034 [opensc-pkcs11] misc.c:284:session_start_operation: called
P:13004; T:9796 2021-07-10 11:22:33.034 [opensc-pkcs11] Session 0x132cb0, type 0
P:13004; T:9796 2021-07-10 11:22:33.034 [opensc-pkcs11] Object with handle 0xc7060
P:13004; T:9796 2021-07-10 11:22:33.034 [opensc-pkcs11] pkcs15_prkey_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.034 [opensc-pkcs11] pkcs15_prkey_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.034 [opensc-pkcs11] Object 0/815200: Attribute 0x0 matches.
P:13004; T:9796 2021-07-10 11:22:33.035 [opensc-pkcs11] pkcs15_prkey_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.035 [opensc-pkcs11] pkcs15_prkey_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.035 [opensc-pkcs11] Object 0/815200: Attribute 0x102 does NOT match.
P:13004; T:9796 2021-07-10 11:22:33.035 [opensc-pkcs11] Object with handle 0xc7360
P:13004; T:9796 2021-07-10 11:22:33.035 [opensc-pkcs11] pkcs15_pubkey_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.035 [opensc-pkcs11] pkcs15_pubkey_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.036 [opensc-pkcs11] Object 0/815968: Attribute 0x0 does NOT match.
P:13004; T:9796 2021-07-10 11:22:33.036 [opensc-pkcs11] Object with handle 0x12bcf0
P:13004; T:9796 2021-07-10 11:22:33.036 [opensc-pkcs11] pkcs15_cert_cmp_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.036 [opensc-pkcs11] pkcs15_cert_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.037 [opensc-pkcs11] pkcs15_cert_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.037 [opensc-pkcs11] Object 0/1228016: Attribute 0x0 does NOT match.
P:13004; T:9796 2021-07-10 11:22:33.037 [opensc-pkcs11] Object with handle 0x12b810
P:13004; T:9796 2021-07-10 11:22:33.037 [opensc-pkcs11] pkcs15_pubkey_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.037 [opensc-pkcs11] pkcs15_pubkey_get_attribute() called
P:13004; T:9796 2021-07-10 11:22:33.037 [opensc-pkcs11] Object 0/1226768: Attribute 0x0 does NOT match.
P:13004; T:9796 2021-07-10 11:22:33.038 [opensc-pkcs11] 0 matching objects
P:13004; T:9796 2021-07-10 11:22:33.038 [opensc-pkcs11] misc.c:306:session_get_operation: called
P:13004; T:9796 2021-07-10 11:22:33.038 [opensc-pkcs11] misc.c:306:session_get_operation: called
P:13004; T:9796 2021-07-10 11:22:35.056 [opensc-pkcs11] C_Finalize()
P:13004; T:9796 2021-07-10 11:22:35.056 [opensc-pkcs11] ctx.c:906:sc_cancel: called
P:13004; T:9796 2021-07-10 11:22:35.057 [opensc-pkcs11] reader-pcsc.c:786:pcsc_cancel: called
P:13004; T:9796 2021-07-10 11:22:35.057 [opensc-pkcs11] REINER SCT cyberJack RFID standard USB 1: card removed
P:13004; T:9796 2021-07-10 11:22:35.057 [opensc-pkcs11] slot_token_removed(0x0)
P:13004; T:9796 2021-07-10 11:22:35.057 [opensc-pkcs11] real C_CloseAllSessions(0x0) 1
P:13004; T:9796 2021-07-10 11:22:35.057 [opensc-pkcs11] real C_CloseSession(0x132cb0)
P:13004; T:9796 2021-07-10 11:22:35.058 [opensc-pkcs11] pkcs15-pin.c:863:sc_pkcs15_pincache_clear: called
P:13004; T:9796 2021-07-10 11:22:35.058 [opensc-pkcs11] pkcs15_release_token() not implemented
P:13004; T:9796 2021-07-10 11:22:35.058 [opensc-pkcs11] slot_token_removed(0x1)
P:13004; T:9796 2021-07-10 11:22:35.058 [opensc-pkcs11] real C_CloseAllSessions(0x1) 0
P:13004; T:9796 2021-07-10 11:22:35.058 [opensc-pkcs11] slot_token_removed(0x2)
P:13004; T:9796 2021-07-10 11:22:35.059 [opensc-pkcs11] real C_CloseAllSessions(0x2) 0
P:13004; T:9796 2021-07-10 11:22:35.059 [opensc-pkcs11] slot_token_removed(0x3)
P:13004; T:9796 2021-07-10 11:22:35.059 [opensc-pkcs11] real C_CloseAllSessions(0x3) 0
P:13004; T:9796 2021-07-10 11:22:35.059 [opensc-pkcs11] sc.c:335:sc_detect_card_presence: called
P:13004; T:9796 2021-07-10 11:22:35.059 [opensc-pkcs11] reader-pcsc.c:472:pcsc_detect_card_presence: called
P:13004; T:9796 2021-07-10 11:22:35.059 [opensc-pkcs11] REINER SCT cyberJack RFID standard USB 1 check
P:13004; T:9796 2021-07-10 11:22:35.060 [opensc-pkcs11] REINER SCT cyberJack RFID standard USB 1:SCardGetStatusChange failed: 0x80100002
P:13004; T:9796 2021-07-10 11:22:35.060 [opensc-pkcs11] reader-pcsc.c:476:pcsc_detect_card_presence: returning with: -1900 (Unknown error)
P:13004; T:9796 2021-07-10 11:22:35.061 [opensc-pkcs11] sc.c:340:sc_detect_card_presence: returning with: -1900 (Unknown error)

Note: I did not remove the card from the slot. I am using the contactless method. But there is no difference when I use the contact method.

Interesting is also, that PKCS-Admin shows two public keys. Maybe there is the Problem? I imported both the private and public key. And now there are two pubs? Is a corresponing public key auto-generated, when I import a private key?
(I only used the pkcs-binarys to import the private/pub key. The PKCS-Admin tool just shows the Objects, as importing is not implemented yet).

Edit:
I think I imported just the private key, because the corresponding pubkey is auto-generated then. But I also imported the Certifcate for the VPN-auth. Is it correct, that this has label "Certificate" and has Key-Type public?

See: https://jan-home.de/public/keys.png ; https://jan-home.de/public/keys2.png

[philipWendland]

I'm clsoing this issue for now due to its age. I seem to have missed the notification about your response.

This seems to have been an issue with your smartcard/reader/drivers instead of the applet. It is weird that PC/SC thinks that your card has been removed...