search

OpenSC / pkcs11-helper

Library that simplifies the interaction with PKCS#11 providers for end-user applications using a simple API and optional OpenSSL engine
Other
65 stars 43 forks source link

Error "Cannot perform signature 18:'CKR_ATTRIBUTE_TYPE_INVALID'" #51

Closed larsjaas closed 2 years ago

larsjaas commented 2 years ago

Hi,

I have a VPN connection that uses keys stored on a Norwegian "Buypass" card. This is handled on MacOS 12.3 with OpenVPN 2.4.9 + openSSL 1.1.1 + pkcs11-helper and a library from "Net iD Access" as the pkcs11-provider in the OpenVPN conf file. When "brew upgrade" downloaded version 1.28.0 of pkcs11-helper, this stopped working for me and the OpenVPN log contained this error:

Enter BEID token Password:
Wed Mar 30 13:37:00 2022 **PKCS#11: Cannot perform signature 18:'CKR_ATTRIBUTE_TYPE_INVALID'**
Wed Mar 30 13:37:00 2022 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Wed Mar 30 13:37:00 2022 TLS_ERROR: BIO read tls_read_plaintext error
Wed Mar 30 13:37:00 2022 TLS Error: TLS object -> incoming plaintext read error
Wed Mar 30 13:37:00 2022 TLS Error: TLS handshake failed
Wed Mar 30 13:37:00 2022 SIGUSR1[soft,tls-error] received, process restarting

After trying to downgrade one and one dependency the OpenVPN binary had link dependencies to, the magic step that got things working again was to downgrade pkcs11-helper to 1.27.0.

alonbl commented 2 years ago

Please enable debug logs and attach the output.

larsjaas commented 2 years ago

Same section, with "verb 8" in the openvpn configuration:

[...]
Thu Mar 31 11:02:00 2022 us=779954 UDP WRITE [22] to [AF_INET]87.238.36.122:1194: P_ACK_V1 kid=0 [ 36 ]
Thu Mar 31 11:02:00 2022 us=788454 UDP READ [114] from [AF_INET]87.238.36.122:1194: P_CONTROL_V1 kid=0 [ ] pid=37 DATA len=100
Thu Mar 31 11:02:00 2022 us=788554 UDP WRITE [22] to [AF_INET]87.238.36.122:1194: P_ACK_V1 kid=0 [ 37 ]
Thu Mar 31 11:02:00 2022 us=788657 UDP READ [114] from [AF_INET]87.238.36.122:1194: P_CONTROL_V1 kid=0 [ ] pid=38 DATA len=100
Thu Mar 31 11:02:00 2022 us=788704 UDP WRITE [22] to [AF_INET]87.238.36.122:1194: P_ACK_V1 kid=0 [ 38 ]
Thu Mar 31 11:02:00 2022 us=789337 UDP READ [67] from [AF_INET]87.238.36.122:1194: P_CONTROL_V1 kid=0 [ ] pid=39 DATA len=53
Enter BEID token Password:
Thu Mar 31 11:02:05 2022 us=716523 PKCS#11: Cannot perform signature 18:'CKR_ATTRIBUTE_TYPE_INVALID'
Thu Mar 31 11:02:05 2022 us=716645 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Thu Mar 31 11:02:05 2022 us=716664 TLS_ERROR: BIO read tls_read_plaintext error
Thu Mar 31 11:02:05 2022 us=716679 TLS Error: TLS object -> incoming plaintext read error
Thu Mar 31 11:02:05 2022 us=716692 TLS Error: TLS handshake failed
Thu Mar 31 11:02:05 2022 us=716826 TCP/UDP: Closing socket
Thu Mar 31 11:02:05 2022 us=717198 SIGUSR1[soft,tls-error] received, process restarting
Thu Mar 31 11:02:05 2022 us=717230 Restart pause, 5 second(s)
alonbl commented 2 years ago

Insufficient level, please reach to a level in which you see ton of pkcs11 messages.

larsjaas commented 2 years ago

Yeah, I saw there was no significant difference. I tried level 50, same amount of output on that exact sequence. It's maybe the binary built for homebrew? Built with no debug-output or something?

I'll try to build HEAD from source - it will have to wait till the weekend though.

alonbl commented 2 years ago

255

larsjaas commented 2 years ago

Unfortunately no change with 255 for that part of the output.

alonbl commented 2 years ago

Please send me the entire log as attachment do not cut or format it it in any way.

larsjaas commented 2 years ago

I built from source and got proper debug logging.

[...]
Tue Apr  5 13:32:07 2022 us=642818  event_wait returned 1
Tue Apr  5 13:32:07 2022 us=642840 UDP WRITE [22] to [AF_INET]87.238.36.122:1194: P_ACK_V1 kid=0 sid=f6df7bac f836902b [ 38 sid=a091e8b9 85d4c520 ]
Tue Apr  5 13:32:07 2022 us=642876 UDP write returned 22
Tue Apr  5 13:32:07 2022 us=645352  event_wait returned 1
Tue Apr  5 13:32:07 2022 us=645407 UDP read returned 67
Tue Apr  5 13:32:07 2022 us=645452 UDP READ [67] from [AF_INET]87.238.36.122:1194: P_CONTROL_V1 kid=0 sid=a091e8b9 85d4c520 [ ] pid=39 DATA 79706173 73204153 2d393833 31363333 3237311d 301b0603 5504030c 1442757[more...]
Tue Apr  5 13:32:07 2022 us=675571 PKCS#11: __pkcs11h_openssl_rsa_enc entered - flen=36, from=0x7ff7bee11200, to=0x600000c84000, rsa=0x600000798160, padding=1
Tue Apr  5 13:32:07 2022 us=675614 PKCS#11: Performing signature
Tue Apr  5 13:32:07 2022 us=675627 PKCS#11: pkcs11h_certificate_signAny_ex entry certificate=0x600001e94580, mech_type=1, source=0x7ff7bee11200, source_size=0000000000000024, target=0x600000c84000, *p_target_size=00000000000000fe
Tue Apr  5 13:32:07 2022 us=675637 PKCS#11: Getting key attributes
Tue Apr  5 13:32:07 2022 us=675645 PKCS#11: __pkcs11h_certificate_getKeyAttributes entry certificate=0x600001e94580
Tue Apr  5 13:32:07 2022 us=675655 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0x7ff7bee10f90, count=6
Tue Apr  5 13:32:07 2022 us=675663 PKCS#11: _pkcs11h_session_freeObjectAttributes return
Tue Apr  5 13:32:07 2022 us=675672 PKCS#11: Get private key attributes failed: 130:'CKR_OBJECT_HANDLE_INVALID'
Tue Apr  5 13:32:07 2022 us=675681 PKCS#11: _pkcs11h_certificate_resetSession entry certificate=0x600001e94580, public_only=0, session_mutex_locked=1
Tue Apr  5 13:32:07 2022 us=675691 PKCS#11: _pkcs11h_session_getObjectById entry session=0x600000298090, class=3, id=0x6000032904f0, id_size=0000000000000001, p_handle=0x600001e945a0
Tue Apr  5 13:32:07 2022 us=675699 PKCS#11: _pkcs11h_session_validate entry session=0x600000298090
Tue Apr  5 13:32:07 2022 us=675708 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1649158327
Tue Apr  5 13:32:07 2022 us=675717 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK'
Tue Apr  5 13:32:07 2022 us=675726 PKCS#11: _pkcs11h_session_findObjects entry session=0x600000298090, filter=0x7ff7bee10ed0, filter_attrs=2, p_objects=0x7ff7bee10ec8, p_objects_found=0x7ff7bee10ec0
Tue Apr  5 13:32:07 2022 us=675792 PKCS#11: _pkcs11h_session_findObjects return rv=0-'CKR_OK', *p_objects_found=0
Tue Apr  5 13:32:07 2022 us=675806 PKCS#11: _pkcs11h_session_getObjectById return rv=512-'CKR_FUNCTION_REJECTED', *p_handle=ffffffffffffffff
Tue Apr  5 13:32:07 2022 us=675815 PKCS#11: _pkcs11h_session_login entry session=0x600000298090, is_publicOnly=0, readonly=1, user_data=0x0, mask_prompt=00000003
Tue Apr  5 13:32:07 2022 us=675824 PKCS#11: _pkcs11h_session_logout entry session=0x600000298090
Tue Apr  5 13:32:07 2022 us=675841 PKCS#11: _pkcs11h_session_logout return
Tue Apr  5 13:32:07 2022 us=675852 PKCS#11: _pkcs11h_session_reset entry session=0x600000298090, user_data=0x0, mask_prompt=00000003, p_slot=0x7ff7bee10ef8
Tue Apr  5 13:32:07 2022 us=675861 PKCS#11: _pkcs11h_session_reset Expected token manufacturerID='Buypass' model='BeID', serialNumber='010119051A6A1760', label='BEID'
Tue Apr  5 13:32:07 2022 us=675870 PKCS#11: _pkcs11h_session_getSlotList entry provider=0x7f98ef80a400, token_present=1, pSlotList=0x7ff7bee10dd0, pulCount=0x7ff7bee10da0
Tue Apr  5 13:32:07 2022 us=675882 PKCS#11: _pkcs11h_session_getSlotList return rv=0-'CKR_OK' *pulCount=2
Tue Apr  5 13:32:07 2022 us=822535 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7ff7bee10db8
Tue Apr  5 13:32:07 2022 us=822592 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7ff7bee10d58
Tue Apr  5 13:32:07 2022 us=822609 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x7f98ef80ee00
Tue Apr  5 13:32:07 2022 us=822623 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x7f98ef80ee00
Tue Apr  5 13:32:07 2022 us=822634 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='Buypass' model='BeID', serialNumber='010119051A6A1760', label='BEID'
Tue Apr  5 13:32:07 2022 us=822646 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x7f98ef80ee00
Tue Apr  5 13:32:07 2022 us=822722 PKCS#11: pkcs11h_token_freeTokenId return
Tue Apr  5 13:32:07 2022 us=822752 PKCS#11: _pkcs11h_session_reset return rv=0-'CKR_OK', *p_slot=1
Tue Apr  5 13:32:07 2022 us=823424 PKCS#11: _pkcs11h_session_login_context entry session=0x600000298090, user=1, label='(null)', user_data=0x0, mask_prompt=00000003
Tue Apr  5 13:32:07 2022 us=823454 PKCS#11: Calling pin_prompt hook for ''
Enter BEID token Password:
Tue Apr  5 13:32:13 2022 us=284792 PKCS#11: key_prompt/pin_prompt hook return rv=0
Tue Apr  5 13:32:13 2022 us=680409 PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
Tue Apr  5 13:32:13 2022 us=680476 PKCS#11: _pkcs11h_session_login_context return rv=0-'CKR_OK'
Tue Apr  5 13:32:13 2022 us=680497 PKCS#11: _pkcs11h_session_login return rv=0-'CKR_OK'
Tue Apr  5 13:32:13 2022 us=680516 PKCS#11: _pkcs11h_session_getObjectById entry session=0x600000298090, class=3, id=0x6000032904f0, id_size=0000000000000001, p_handle=0x600001e945a0
Tue Apr  5 13:32:13 2022 us=680533 PKCS#11: _pkcs11h_session_validate entry session=0x600000298090
Tue Apr  5 13:32:13 2022 us=680550 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1649158333
Tue Apr  5 13:32:13 2022 us=680566 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK'
Tue Apr  5 13:32:13 2022 us=680582 PKCS#11: _pkcs11h_session_findObjects entry session=0x600000298090, filter=0x7ff7bee10ed0, filter_attrs=2, p_objects=0x7ff7bee10ec8, p_objects_found=0x7ff7bee10ec0
Tue Apr  5 13:32:13 2022 us=681249 PKCS#11: _pkcs11h_session_findObjects return rv=0-'CKR_OK', *p_objects_found=1
Tue Apr  5 13:32:13 2022 us=681291 PKCS#11: _pkcs11h_session_getObjectById return rv=0-'CKR_OK', *p_handle=8000000b
Tue Apr  5 13:32:13 2022 us=681313 PKCS#11: _pkcs11h_certificate_resetSession return rv=0-'CKR_OK'
Tue Apr  5 13:32:13 2022 us=681333 PKCS#11: _pkcs11h_session_getObjectAttributes entry session=0x600000298090, object=2147483659, attrs=0x7ff7bee10f90, count=6
Tue Apr  5 13:32:13 2022 us=681360 PKCS#11: _pkcs11h_session_getObjectAttributes return rv=18-'CKR_ATTRIBUTE_TYPE_INVALID'
Tue Apr  5 13:32:13 2022 us=681379 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0x7ff7bee10f90, count=6
Tue Apr  5 13:32:13 2022 us=681394 PKCS#11: _pkcs11h_session_freeObjectAttributes return
Tue Apr  5 13:32:13 2022 us=681410 PKCS#11: __pkcs11h_certificate_getKeyAttributes return rv=18-'CKR_ATTRIBUTE_TYPE_INVALID'
Tue Apr  5 13:32:13 2022 us=681430 PKCS#11: pkcs11h_certificate_signAny return rv=18-'CKR_ATTRIBUTE_TYPE_INVALID', *p_target_size=00000000000000fe
Tue Apr  5 13:32:13 2022 us=681446 PKCS#11: Cannot perform signature 18:'CKR_ATTRIBUTE_TYPE_INVALID'
Tue Apr  5 13:32:13 2022 us=681462 PKCS#11: __pkcs11h_openssl_rsa_enc - return rv=18-'CKR_ATTRIBUTE_TYPE_INVALID'
Tue Apr  5 13:32:13 2022 us=681517 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Tue Apr  5 13:32:13 2022 us=681543 TLS_ERROR: BIO read tls_read_plaintext error
Tue Apr  5 13:32:13 2022 us=681560 TLS Error: TLS object -> incoming plaintext read error
Tue Apr  5 13:32:13 2022 us=681576 TLS Error: TLS handshake failed
Tue Apr  5 13:32:13 2022 us=681629 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x600000798370, ptr=0x0, ad=0x6000007983d8, idx=1, argl=0, argp=0x10137e00c
Tue Apr  5 13:32:13 2022 us=681748 TCP/UDP: Closing socket
Tue Apr  5 13:32:13 2022 us=681922 SIGUSR1[soft,tls-error] received, process restarting
Tue Apr  5 13:32:13 2022 us=681963 Restart pause, 5 second(s)
alonbl commented 2 years ago

Thanks for the log.

Can you please check this[1] branch? Please provide a log.

[1] https://github.com/alonbl/pkcs11-helper/tree/work

larsjaas commented 2 years ago

Sent as email...

alonbl commented 2 years ago

Thank you @larsjaas, I had a typo which caused the problem you experience. Can you please recheck the branch?

larsjaas commented 2 years ago

That worked. You should warn when you rewrite git history - my first blind pull didn't update anything :) Log is sent as email, in case you need it.

alonbl commented 2 years ago

Oh... never do git pull always git fetch and git rebase, the git pull tends to do harm in so many cases :)

Thank you for testing, the log seems ok. For some reason the provided does not recognize CKA_ALWAYS_AUTHENTICATE attribute. Now the library ignores the error and sets default.