search

alonbl / gnupg-pkcs11-scd

PKCS#11 GnuPG SCD
http://gnupg-pkcs11.sourceforge.net/
Other
68 stars 17 forks source link

gpg --sign not triggering pin entry using a key with 'always authenticate' #58

Closed filip-zyzniewski closed 12 months ago

filip-zyzniewski commented 1 year ago

Hi,

big thanks for developing and maintaining gnupg-pkcs11-scd!

I am trying to set up my smartcard-hsm cards to be used with GPG using a reader with a pinpad and I have discovered a behavior that has surprised me quite a bit.

I have written a script and prepared a docker image to reproduce the issue, it's @ https://github.com/filip-zyzniewski/issues/blob/main/gnupg-pkcs11-scd/gpg_sign_without_auth/run.sh .

I have uploaded the output of the script @ https://gist.github.com/filip-zyzniewski/fed564bb5b7418506931fe8104b02d83, adding <PINENTRY> everywhere where I was offered pin entry.

The surprising fact is that not each gpg --sign has triggered a pin entry:

filip@dell1:~/git/github.com/filip-zyzniewski/issues/gnupg-pkcs11-scd/gpg_sign_without_auth$ egrep 'gpg_setup_sign|<PINENTRY' gpg_sign_without_auth-66677653961753f4551fef254dab18bdc4051321.log 
2023-09-07T20:06:50,174221277+00:00 gpg_setup_sign: waiting for the card to be available
2023-09-07T20:06:50,799849867+00:00 gpg_setup_sign: information about the card
2023-09-07T20:06:51,218269729+00:00 gpg_setup_sign: initializing the card
2023-09-07T20:06:51,584758698+00:00 gpg_setup_sign: generating a key pair
<PINENTRY>
2023-09-07T20:07:01,347624564+00:00 gpg_setup_sign: creating the certificate
<PINENTRY>
2023-09-07T20:07:07,629788009+00:00 gpg_setup_sign: converting /tmp/cert-1694117211.pem to /tmp/cert-1694117211.der
2023-09-07T20:07:07,699249192+00:00 gpg_setup_sign: writing the certificate to the card
<PINENTRY>
2023-09-07T20:07:14,044661298+00:00 gpg_setup_sign: looking up the key grip
2023-09-07T20:07:14,493354103+00:00 gpg_setup_sign: adding the key to GPG
<PINENTRY>
2023-09-07T20:07:20,471903691+00:00 gpg_setup_sign: objects on the card
<PINENTRY>
2023-09-07T20:07:27,134262824+00:00 gpg_setup_sign: first signing of a message
<PINENTRY>
2023-09-07T20:07:33,993742142+00:00 gpg_setup_sign: second signing of a message
2023-09-07T20:07:34,206958795+00:00 gpg_setup_sign: resetting the card
2023-09-07T20:07:35,278657808+00:00 gpg_setup_sign: third signing of a message
<PINENTRY>
<PINENTRY>
2023-09-07T20:07:49,924574029+00:00 gpg_setup_sign: fourth signing of a message
filip@dell1:~/git/github.com/filip-zyzniewski/issues/gnupg-pkcs11-scd/gpg_sign_without_auth$

As you can see, the second and fourth signing of a message have been done without authenticating to the card. I don't think it should be possible given that the private key is marked as 'always authenticate' (https://gist.github.com/filip-zyzniewski/fed564bb5b7418506931fe8104b02d83#file-gpg_sign_without_auth-66677653961753f4551fef254dab18bdc4051321-log-L5370)

The script ran in the container (https://github.com/filip-zyzniewski/issues/blob/main/gnupg-pkcs11-scd/gpg_sign_without_auth/gpg_setup_sign.sh) contains all steps taken, starting from initializing the card with sc-hsm-tool.

Is this a problem with one of the components of this setup, or am I misunderstanding something?

alonbl commented 1 year ago

What version of pkcs11-helper and what version of gnupg-pkcs11-scd are you using?

filip-zyzniewski commented 1 year ago

These are declared in the Dockerfile:

All other components are specified there as well.

alonbl commented 1 year ago

You can search for:

The provider accepts protected authentication and succeeds, it is not a cached PIN or anything at the gnupg-pkcs11-scd side.

filip-zyzniewski commented 12 months ago

Hmm, from this:

filip@dell1:~/git/github.com/filip-zyzniewski/issues/gnupg-pkcs11-scd/gpg_sign_without_auth$ egrep "gpg_setup_sign|<PINENTRY>|(__pkcs11h_certificate_doPrivateOperation entry .*p_target_size=0000000000000100)|CKU_CONTEXT_SPECIFIC login|(_pkcs11h_session_login_context C_Login rv=0-'CKR_OK')" gpg_sign_without_auth-66677653961753f4551fef254dab18bdc4051321.log 
2023-09-07T20:06:50,174221277+00:00 gpg_setup_sign: waiting for the card to be available
2023-09-07T20:06:50,799849867+00:00 gpg_setup_sign: information about the card
2023-09-07T20:06:51,218269729+00:00 gpg_setup_sign: initializing the card
2023-09-07T20:06:51,584758698+00:00 gpg_setup_sign: generating a key pair
<PINENTRY>
2023-09-07T20:07:01,347624564+00:00 gpg_setup_sign: creating the certificate
<PINENTRY>
2023-09-07T20:07:07,629788009+00:00 gpg_setup_sign: converting /tmp/cert-1694117211.pem to /tmp/cert-1694117211.der
2023-09-07T20:07:07,699249192+00:00 gpg_setup_sign: writing the certificate to the card
<PINENTRY>
2023-09-07T20:07:14,044661298+00:00 gpg_setup_sign: looking up the key grip
2023-09-07T20:07:14,493354103+00:00 gpg_setup_sign: adding the key to GPG
<PINENTRY>
2023-09-07T20:07:20,187847808+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
2023-09-07T20:07:20,263430572+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: CKU_CONTEXT_SPECIFIC login
2023-09-07T20:07:20,267240064+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
2023-09-07T20:07:20,278293759+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x56286c0ced60, op=0, mech_type=1, source=0x56286c0d20e0, source_size=0000000000000033, target=0x56286c0c2160, *p_target_size=0000000000000100
2023-09-07T20:07:20,471903691+00:00 gpg_setup_sign: objects on the card
2023-09-07T20:07:20,607452402+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: CKU_CONTEXT_SPECIFIC login
2023-09-07T20:07:20,611418693+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
2023-09-07T20:07:20,623523768+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x56286c0ced60, op=0, mech_type=1, source=0x56286c0df710, source_size=0000000000000033, target=0x56286c0b25c0, *p_target_size=0000000000000100
<PINENTRY>
2023-09-07T20:07:27,134262824+00:00 gpg_setup_sign: first signing of a message
2023-09-07T20:07:27,748470649+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: CKU_CONTEXT_SPECIFIC login
<PINENTRY>
2023-09-07T20:07:32,866289775+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
2023-09-07T20:07:32,891130390+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x56286c0e4850, op=0, mech_type=1, source=0x56286c0df510, source_size=0000000000000033, target=0x56286c0a7ca0, *p_target_size=0000000000000100
2023-09-07T20:07:33,993742142+00:00 gpg_setup_sign: second signing of a message
2023-09-07T20:07:34,206958795+00:00 gpg_setup_sign: resetting the card
2023-09-07T20:07:34,607425209+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: CKU_CONTEXT_SPECIFIC login
2023-09-07T20:07:34,611430172+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
2023-09-07T20:07:34,623389914+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x56286c0e4850, op=0, mech_type=1, source=0x56286c0d20e0, source_size=0000000000000033, target=0x56286c0c2160, *p_target_size=0000000000000100
2023-09-07T20:07:35,278657808+00:00 gpg_setup_sign: third signing of a message
2023-09-07T20:07:35,911908720+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: CKU_CONTEXT_SPECIFIC login
<PINENTRY>
2023-09-07T20:07:41,543530541+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: CKU_CONTEXT_SPECIFIC login rv=5
<PINENTRY>
2023-09-07T20:07:48,793379989+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
2023-09-07T20:07:48,853504002+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: CKU_CONTEXT_SPECIFIC login
2023-09-07T20:07:48,859318576+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
2023-09-07T20:07:48,873090198+00:00 : gnupg-pkcs11-scd[5797.3348207424]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x56286c0e4850, op=0, mech_type=1, source=0x56286c0df710, source_size=0000000000000033, target=0x56286c0e1c70, *p_target_size=0000000000000100
2023-09-07T20:07:49,924574029+00:00 gpg_setup_sign: fourth signing of a message
filip@dell1:~/git/github.com/filip-zyzniewski/issues/gnupg-pkcs11-scd/gpg_sign_without_auth$

it seems to me that there is no private key operation attempted on second and fourth signing. Am I interpreting this correctly? If so, does it mean that gpg is signing the message without performing a private key operation?

EDIT: something seems off with the log messages - there are login related entries after 'resetting the card', yet there was no activity on the pinpad - perhaps the thingy I did with awk is messing with the ordering, I'll look into it more.

filip-zyzniewski commented 12 months ago

Indeed, after https://github.com/filip-zyzniewski/issues/commit/1a2ea6fe88c2ef9e79c1ca017ce6556a113c9b78 it looks clearer (https://gist.github.com/filip-zyzniewski/9b9d3e478302b9d68866d2fb8cae4664):

filip@dell1:~/git/github.com/filip-zyzniewski/issues/gnupg-pkcs11-scd/gpg_sign_without_auth$ egrep "gpg_setup_sign|<PINENTRY>|(__pkcs11h_certificate_doPrivateOperation entry .*p_target_size=0000000000000100)|CKU_CONTEXT_SPECIFIC login|(_pkcs11h_session_login_context C_Login rv=0-'CKR_OK')"  ~/tmp/gpg_sign_without_auth-1a2ea6fe88c2ef9e79c1ca017ce6556a113c9b78.log 
2023-09-08T19:24:40,180717486+00:00 gpg_setup_sign: waiting for the card to be available
2023-09-08T19:24:40,842452994+00:00 gpg_setup_sign: information about the card
2023-09-08T19:24:41,303508616+00:00 gpg_setup_sign: initializing the card
2023-09-08T19:24:41,698075986+00:00 gpg_setup_sign: generating a key pair
<PINENTRY>
2023-09-08T19:24:51,989940389+00:00 gpg_setup_sign: creating the certificate
<PINENTRY>
2023-09-08T19:24:57,769880713+00:00 gpg_setup_sign: converting /tmp/cert-1694201081.pem to /tmp/cert-1694201081.der
2023-09-08T19:24:57,813039166+00:00 gpg_setup_sign: writing the certificate to the card
<PINENTRY>
2023-09-08T19:25:03,200868907+00:00 gpg_setup_sign: looking up the key grip
2023-09-08T19:25:03,684507903+00:00 gpg_setup_sign: adding the key to GPG
<PINENTRY>
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: CKU_CONTEXT_SPECIFIC login
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x559fb8446d60, op=0, mech_type=1, source=0x559fb844a0e0, source_size=0000000000000033, target=0x559fb843a160, *p_target_size=0000000000000100
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: CKU_CONTEXT_SPECIFIC login
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x559fb8446d60, op=0, mech_type=1, source=0x559fb8457710, source_size=0000000000000033, target=0x559fb842a5c0, *p_target_size=0000000000000100
2023-09-08T19:25:09,250854173+00:00 gpg_setup_sign: objects on the card
<PINENTRY>
2023-09-08T19:25:16,605750675+00:00 gpg_setup_sign: first signing of a message
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: CKU_CONTEXT_SPECIFIC login
<PINENTRY>
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x559fb845c850, op=0, mech_type=1, source=0x559fb8457510, source_size=0000000000000033, target=0x559fb841fca0, *p_target_size=0000000000000100
2023-09-08T19:25:22,757838950+00:00 gpg_setup_sign: second signing of a message
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: CKU_CONTEXT_SPECIFIC login
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x559fb845c850, op=0, mech_type=1, source=0x559fb844a0e0, source_size=0000000000000033, target=0x559fb843a160, *p_target_size=0000000000000100
2023-09-08T19:25:23,009486633+00:00 gpg_setup_sign: resetting the card
2023-09-08T19:25:24,101107349+00:00 gpg_setup_sign: third signing of a message
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: CKU_CONTEXT_SPECIFIC login
<PINENTRY>
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: CKU_CONTEXT_SPECIFIC login rv=5
<PINENTRY>
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: CKU_CONTEXT_SPECIFIC login
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x559fb845c850, op=0, mech_type=1, source=0x559fb8457710, source_size=0000000000000033, target=0x559fb8459c70, *p_target_size=0000000000000100
2023-09-08T19:25:36,276591221+00:00 gpg_setup_sign: fourth signing of a message
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: CKU_CONTEXT_SPECIFIC login
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK'
gnupg-pkcs11-scd[56.2717521728]: PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x559fb845c850, op=0, mech_type=1, source=0x559fb844b740, source_size=0000000000000033, target=0x559fb842a5c0, *p_target_size=0000000000000100
filip@dell1:~/git/github.com/filip-zyzniewski/issues/gnupg-pkcs11-scd/gpg_sign_without_auth$

So there is a successful login (PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK') before each signing, yet there was no pin provided. I am entering the pin using the pinpad only, so the host can't really cache it.

@alonbl do you think I should raise this issue with the smartcard-hsm vendor, https://www.cardcontact.de/ ? Do you have any ideas on how could I reproduce this issue without involving gpg?

alonbl commented 12 months ago

Yes, please work with your vendor to resolve this issue.

filip-zyzniewski commented 12 months ago

Thank you for looking into this @alonbl .

CardContact commented 11 months ago

If you enter the PIN on the PIN pad, then the only explanation is, that the SmartCard-HSM remains active in the card reader.

Login in PKCS#11 is token and not session related. If you open a new session and the authentication is still valid, then the new session is already logged in. The OpenSC driver also makes sure, that an authenticated card remains active. You would need to explicitly logout or reset the card in the reader.

However with reset there seems to be an issue with contactless PIN Pad reader, that do not full recycle the field to reset the card.

The SmartCard-HSM does not have an Always Authenticate mechanism, once you are logged in, you can perform a arbitrary number of cryptographic operations.

alonbl commented 11 months ago

Implementation (at secure element side) may invalidate the session (secure messaging) each private key operation that requires always authenticate to force re-authenticate as session must be re-created. Of course the software should also support the sequence. OpenSC behavior was always permissive.

filip-zyzniewski commented 11 months ago

The SmartCard-HSM does not have an Always Authenticate mechanism

@CardContact should pkcs11-tool --keypairgen --always-auth not fail on SmartCard-HSM then?

The OpenSC driver also makes sure, that an authenticated card remains active.

Is there a way to prevent that? I'd like an explicit secure user input to be required on each private key operation.