Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Problem interacting with OpenSC, maybe with p11-kit too #234

Closed
mouse07410 opened this issue Apr 30, 2023 · 71 comments
Closed

Problem interacting with OpenSC, maybe with p11-kit too #234

mouse07410 opened this issue Apr 30, 2023 · 71 comments

Comments

@mouse07410
Copy link

Describe the bug
Fails to decrypt or sign. Showing example of CMS decrypt failure:

$ openssl cms -decrypt -aes256 -binary -inform PEM -in /tmp/pt.cms.pem -out /tmp/pt.txt.dec -inkey "pkcs11:manufacturer=piv_II;object=KEY%20MAN%20key;type=private"
Error decrypting CMS structure
405BA0FA01000000:error:1C800064:Provider routines:ossl_cipher_unpadblock:bad decrypt:providers/implementations/ciphers/ciphercommon_block.c:129:
$ openssl storeutl -keys -text "pkcs11:manufacturer=piv_II;object=KEY%20MAN%20key;type=private"
0: Pkey
PKCS11 RSA Private Key (2048 bits)
[Can't export and print private key data]
PKCS11 RSA Public Key (2048 bits)
Modulus:
    00:ab:9b:f4:1c:92:fd:23:de:9d:df:82:eb:50:ba:
    .  .  .
    28:a4:7d:bd:d5:6b:34:1c:95:6e:10:91:4e:36:04:
    d1:a3
Exponent: xxxxxxxxx
URI pkcs11:model=PKCS%2315%20emulated;manufacturer=piv_II;serial=b15xxxxxxxxx;token=XXXXXXXXXX;id=%03;object=KEY%20MAN%20key;type=private
Total found: 1
$ 

Excerpt from openssl.cnf:

[pkcs11_sect]
 module = /opt/local/libexec/openssl3/lib/ossl-modules/pkcs11.dylib
 pkcs11-module-quirks = no-deinit
 pkcs11-module-login-behavior = auto
 pkcs11-module-cache-pins = cache
 #pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so
 #pkcs11-module-path = /usr/local/lib/libykcs11.dylib
 #pkcs11-module-path = /Library/OpenSC/lib/pkcs11-spy.so
 pkcs11-module-path = /opt/local/lib/p11-kit-proxy.dylib
 activate = 1

To Reproduce
Steps to reproduce the behavior:

  1. Install OpenSSL-3.1.0, this provider, OpenSC, preferably yubico-piv-tool if you have a Yubikey.
  2. Create some dummy files, like openssl rand -base64 -out /tmp/pt.txt 30 or so.
  3. Attempt to sign /tmp/pt.txt with openssl dgst or encrypt to Yubikey KEY MAN pubkey via openssl cms.
  4. See error trying to sign, or when trying to decrypt resulting CMS PEM file.

Expected behavior
Successful signature creation and verification, successful unwrapping of CMS.

Operating environment (please complete the following information):

  • OS: MacOS Ventura
  • Version 13.3.1

Token and application used (please complete the following information):

  • Device: [e.g. ACME HSM Pro 1.7]
  • PKCS11 Driver version: OpenSC master
  • Application: OpenSSL
  • Version: 3.1.0

Additional context

After replacing in openssl.cnf pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so with /usr/local/lib/libykcs11.dylib:

$ openssl cms -decrypt -aes256 -binary -inform PEM -in /tmp/pt.cms.pem -out /tmp/pt.txt.dec -inkey "pkcs11:id=%03;type=private"
Enter pass phrase for PKCS#11 Token (Slot 0 - Yubico YubiKey OTP+FIDO+CCID):
$ cat /tmp/pt.txt.dec
yMg38rLgrUu8rQTjn79VZaQJ1JojOnR9dPguotA8
$ cat /tmp/pt.txt    
yMg38rLgrUu8rQTjn79VZaQJ1JojOnR9dPguotA8
$

Another attempt, also successful:

$ pkcs11-cms-demo                           
Generate a random data file (30 bytes), Base64-encoded...
openssl rand -base64 -out /tmp/derive.23092.text 30
P9kALJQ0ajQcQm+rAsABVfT2gma/Xu3XB/GRE+lK

Get encryption certificate from the token...
pkcs11-tool -r -y cert --id 03 -o /tmp/derive.23092.cert.der
Using slot 0 with a present token (0x0)
subject=CN = Uri the Great

Encrypt file /tmp/derive.23092.text in CMS format using public key on token...

openssl cms -aes256 -encrypt -binary -in /tmp/derive.23092.text -outform PEM -out /tmp/derive.23092.text.cms /tmp/derive.23092.cert.pem

Encrypted CMS file:
-----BEGIN CMS-----
MIIBtgYJKoZIhvcNAQcDoIIBpzCCAaMCAQAxggE+MIIBOgIBADAiMBoxGDAWBgNV
BAMMD0ZvcmVzdCBDQSBSU0EgNAIEXVw67jANBgkqhkiG9w0BAQEFAASCAQBag1Tv
0S2cGBmt1DeLqZNhsbFq4L8+G8idc17bilpS8vufcPkG3Km6T+yx6EECpqX/ZwHu
md8Kxm21oJTg2vlXSEEDcAFZ92+5aRcbjLdo8O/EvDaUwGKL3rwnNWg891mfn3ze
uplkNPCmFj86M2gWsvjypN8B8VRICTsmJslc2Fs1JDyJVxA7nylcjNa0mQPSMqCf
ehBdnjNqZ48Rh08LBm1aUZAEoSrwJBsYhV5c+Gf9M9ndg43TV5Grvav+hpyqDWBf
5teIfeFKfeqTni5HlzE7B0DT1hrnjzRZmiMBbG7Xgqeh0FtjZS5EaLkIMSGUWy9S
KIpA28wxJPW5c2g2MFwGCSqGSIb3DQEHATAdBglghkgBZQMEASoEEILpm+u4Q5qM
CUdF+X9YIcyAMApZzeHSHzqFsAqtKdcXAsETykC3lmY/H4NpbNHlxUJ4TE1YPMOR
lt/M8neruuQcUQ==
-----END CMS-----


Decrypt CMS message in file /tmp/derive.23092.text.cms...
openssl cms -decrypt -aes256 -binary -inform PEM -in /tmp/derive.23092.text.cms -out /tmp/derive.23092.text.dec -inkey "pkcs11:model=YubiKey%20YK4;id=%03;type=private"
Enter pass phrase for PKCS#11 Token (Slot 21 - Yubico YubiKey OTP+FIDO+CCID):

Original and decrypted files match:
P9kALJQ0ajQcQm+rAsABVfT2gma/Xu3XB/GRE+lK
P9kALJQ0ajQcQm+rAsABVfT2gma/Xu3XB/GRE+lK
$ 

With openssl.cnf containing:

[pkcs11_sect]
 module = /opt/local/libexec/openssl3/lib/ossl-modules/pkcs11.dylib
 pkcs11-module-quirks = no-deinit
 pkcs11-module-login-behavior = auto
 pkcs11-module-cache-pins = cache
 #pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so
 #pkcs11-module-path = /usr/local/lib/libykcs11.dylib
 #pkcs11-module-path = /Library/OpenSC/lib/pkcs11-spy.so
 pkcs11-module-path = /opt/local/lib/p11-kit-proxy.dylib
 activate = 1 

With signature:

Using OpenSC

openssl rand -hex -out /tmp/derive.54096.text 5120

Signing file /tmp/derive.54096.text...
openssl dgst  -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/derive.54096.text.sig /tmp/derive.54096.text
Error setting context
405BA0FA01000000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
Signature for /tmp/derive.54096.text is stored in /tmp/derive.54096.text.sig

Verifying signature:
openssl dgst  -verify "pkcs11:manufacturer=piv_II;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -signature /tmp/derive.54096.text.sig  /tmp/derive.54096.text
Error reading signature file /tmp/derive.54096.text.sig

Using YKCS11

openssl rand -hex -out /tmp/derive.54175.text 5120

Signing file /tmp/derive.54175.text...
openssl dgst  -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/derive.54175.text.sig /tmp/derive.54175.text
Enter pass phrase for PKCS#11 Token (Slot 21 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
405BA0FA01000000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
Signature for /tmp/derive.54175.text is stored in /tmp/derive.54175.text.sig

Verifying signature:
openssl dgst  -verify "pkcs11:model=YubiKey%20YK4;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -signature /tmp/derive.54175.text.sig  /tmp/derive.54175.text
Error reading signature file /tmp/derive.54175.text.sig

$ $ openssl storeutl -keys -text "pkcs11:model=YubiKey%20YK4;id=%02;type=private"
Enter pass phrase for PKCS#11 Token (Slot 21 - Yubico YubiKey OTP+FIDO+CCID):
0: Pkey
PKCS11 RSA Private Key (2048 bits)
[Can't export and print private key data]
PKCS11 RSA Public Key (2048 bits)
Modulus:
    00:bf:03:6f:94:56:56:89:d1:91:8b:1d:f5:63:7f:
    .  .  .
    4a:52:ed:ec:ea:97:83:46:d9:0a:34:51:19:60:bd:
    5e:eb
Exponent: xxxxxxx
URI pkcs11:model=YubiKey%20YK4;manufacturer=Yubico%20(www.yubico.com);serial=xxxxxxxx;token=YubiKey%20PIV%20%237xxxxxxxxx;id=%02;object=Private%20key%20for%20Digital%20Signature;type=private
Total found: 1
$ 

Foregoing p11-kit:

In openssl.cnf forcing YKCS11:

[pkcs11_sect]
 module = /opt/local/libexec/openssl3/lib/ossl-modules/pkcs11.dylib
 pkcs11-module-quirks = no-deinit
 pkcs11-module-login-behavior = auto
 pkcs11-module-cache-pins = cache
 #pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so
 pkcs11-module-path = /usr/local/lib/libykcs11.dylib
 #pkcs11-module-path = /Library/OpenSC/lib/pkcs11-spy.so
 #pkcs11-module-path = /opt/local/lib/p11-kit-proxy.dylib
 activate = 1 

results in success

openssl rand -hex -out /tmp/derive.54503.text 5120

Signing file /tmp/derive.54503.text...
openssl dgst  -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/derive.54503.text.sig /tmp/derive.54503.text
Enter pass phrase for PKCS#11 Token (Slot 0 - Yubico YubiKey OTP+FIDO+CCID):
Signature for /tmp/derive.54503.text is stored in /tmp/derive.54503.text.sig

Verifying signature:
openssl dgst  -verify "pkcs11:model=YubiKey%20YK4;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -signature /tmp/derive.54503.text.sig  /tmp/derive.54503.text
Verified OK

Verifying signature using pkcs11-tool:
pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --verify -m SHA384-RSA-PKCS-PSS -y cert -d 02 --signature-file /tmp/derive.54503.text.sig -i /tmp/derive.54503.text
Using slot 0 with a present token (0x0)
Using signature algorithm SHA384-RSA-PKCS-PSS
PSS parameters: hashAlg=SHA384, mgf=MGF1-SHA384, salt_len=48 B
Signature is valid
@dengert
Copy link
Contributor

dengert commented Apr 30, 2023

Maybe I am missing something, but I don't see an example of using /usr/local/lib/opensc-pkcs11.so directly.
All the OpenSC failures appear to be via p11-kit. I see the "Foregoing p11-kit:" but only with libykcs11.dylib.

Does it fail when only " #pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so" is uncommented?

What modules is p11-kit loading? What version of OpenSC is it loading?

@mouse07410
Copy link
Author

Maybe I am missing something, but I don't see an example of using /usr/local/lib/opensc-pkcs11.so directly.

You mean /Library/OpenSC/lib/opensc-pkcs11.so directly? Here it is:

$ openssl dgst  -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig2 /tmp/pt.txt
Error setting context
405BA0FA01000000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$ openssl storeutl -keys -text "pkcs11:manufacturer=piv_II;id=%02;type=private"
0: Pkey
PKCS11 RSA Private Key (2048 bits)
[Can't export and print private key data]
PKCS11 RSA Public Key (2048 bits)
Modulus:
    00:bf:03:6f:94:56:56:89:d1:91:8b:1d:f5:63:7f:
    .  .  .
    4a:52:ed:ec:ea:97:83:46:d9:0a:34:51:19:60:bd:
    5e:eb
Exponent: xxxxxxxx
URI pkcs11:model=PKCS%2315%20emulated;manufacturer=piv_II;serial=b15xxxxxxx;token=XXXXXXXX;id=%02;object=SIGN%20key;type=private
Total found: 1
$

with openssl.cnf:

[pkcs11_sect]
 module = /opt/local/libexec/openssl3/lib/ossl-modules/pkcs11.dylib
 pkcs11-module-quirks = no-deinit
 pkcs11-module-login-behavior = auto
 pkcs11-module-cache-pins = cache
 pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so
 #pkcs11-module-path = /usr/local/lib/libykcs11.dylib
 #pkcs11-module-path = /Library/OpenSC/lib/pkcs11-spy.so
 #pkcs11-module-path = /opt/local/lib/p11-kit-proxy.dylib
 activate = 1

Does it fail when only " #pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so" is uncommented?

Oh yes.

What modules is p11-kit loading? What version of OpenSC is it loading?

p11-kit is loading OpenSC, YKCS11, SOftHSM, and YubiHSM2 drivers.
OpenSC - current master.

$ cat ~/.config/pkcs11/modules/opensc.module 
module: /Library/OpenSC/lib/opensc-pkcs11.so
#module: /opt/local/lib/pkcs11-spy.so
#module: /usr/local/lib/keychain-pkcs11.dylib
critical: no
$ ll /Library/OpenSC/lib/opensc-pkcs11.so
-rwxr-xr-x  1 root  wheel  304013 Apr 30 10:47 /Library/OpenSC/lib/opensc-pkcs11.so*
$ 

@mouse07410
Copy link
Author

One correction. with provider - YKCS11 also seems to fail on signature:

$ pkcs11-rsa-prov-sign-demo2 

Testing pkcs11 engine (libp11)

This is not a CAC
Generating ephemeral file /tmp/derive.80369.text to test RSA-PSS signature...

openssl rand -hex -out /tmp/derive.80369.text 5120

Signing file /tmp/derive.80369.text...
openssl dgst -engine pkcs11 -keyform engine -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/derive.80369.text.sig /tmp/derive.80369.text
Engine "pkcs11" set.
Enter PKCS#11 token PIN for YubiKey PIV #7973739:
Enter PKCS#11 key PIN for Private key for Digital Signature:
Signature for /tmp/derive.80369.text is stored in /tmp/derive.80369.text.sig

Verifying signature:
openssl dgst -engine pkcs11 -keyform engine -verify "pkcs11:model=YubiKey%20YK4;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -signature /tmp/derive.80369.text.sig  /tmp/derive.80369.text
Engine "pkcs11" set.
Verified OK

Verifying signature using pkcs11-tool:
pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --verify -m SHA384-RSA-PKCS-PSS -y cert -d 02 --signature-file /tmp/derive.80369.text.sig -i /tmp/derive.80369.text
Using slot 0 with a present token (0x0)
Using signature algorithm SHA384-RSA-PKCS-PSS
PSS parameters: hashAlg=SHA384, mgf=MGF1-SHA384, salt_len=48 B
Signature is valid

$ pkcs11-rsa-prov-sign-demo2 prov

Testing pkcs11-provider

This is not a CAC
Generating ephemeral file /tmp/derive.80389.text to test RSA-PSS signature...

openssl rand -hex -out /tmp/derive.80389.text 5120

Signing file /tmp/derive.80389.text...
openssl dgst  -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/derive.80389.text.sig /tmp/derive.80389.text
Enter pass phrase for PKCS#11 Token (Slot 21 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
405BA0FA01000000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
Signature for /tmp/derive.80389.text is stored in /tmp/derive.80389.text.sig

Verifying signature:
openssl dgst  -verify "pkcs11:model=YubiKey%20YK4;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -signature /tmp/derive.80389.text.sig  /tmp/derive.80389.text
Error reading signature file /tmp/derive.80389.text.sig

Verifying signature using pkcs11-tool:
pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --verify -m SHA384-RSA-PKCS-PSS -y cert -d 02 --signature-file /tmp/derive.80389.text.sig -i /tmp/derive.80389.text
Using slot 0 with a present token (0x0)
Using signature algorithm SHA384-RSA-PKCS-PSS
PSS parameters: hashAlg=SHA384, mgf=MGF1-SHA384, salt_len=48 B
Invalid signature

$ 

@mouse07410
Copy link
Author

mouse07410 commented Apr 30, 2023

Here's more details:

$ openssl dgst  -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig2 /tmp/pt.txt
Enter pass phrase for PKCS#11 Token (Slot 21 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
405BA0FA01000000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$
$ env | grep PKCS
YUBIHSM_PKCS11_CONF=/Users/ur20980/yubihsm_pkcs11.conf
YUBIHSM_PKCS11_MODULE=/usr/local/lib/pkcs11/yubihsm_pkcs11.dylib
PKCS11SPY_OUTPUT=/tmp/spy.log
PKCS11SPY=/opt/local/lib/p11-kit-proxy.dylib
$
$ openssl version
OpenSSL 3.1.0 14 Mar 2023 (Library: OpenSSL 3.1.0 14 Mar 2023)
$ openssl list -providers
Providers:
  base
    name: OpenSSL Base Provider
    version: 3.1.0
    status: active
  default
    name: OpenSSL Default Provider
    version: 3.1.0
    status: active
  legacy
    name: OpenSSL Legacy Provider
    version: 3.1.0
    status: active
  oqs
    name: OpenSSL OQS Provider
    version: 0.5.0-dev
    status: active
  pkcs11
    name: PKCS#11 Provider
    version: 3.1.0
    status: active
$ 
$ cat ~/.config/pkcs11/modules/ykcs11.module 
# Normal
module: /usr/local/lib/libykcs11.dylib
# For SPY
#module: /Library/OpenSC/lib/pkcs11-spy.so
$

openssl.cnf:

[pkcs11_sect]
 module = /opt/local/libexec/openssl3/lib/ossl-modules/pkcs11.dylib
 pkcs11-module-quirks = no-deinit
 pkcs11-module-login-behavior = auto
 pkcs11-module-cache-pins = cache
 #pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so
 #pkcs11-module-path = /usr/local/lib/libykcs11.dylib
 pkcs11-module-path = /Library/OpenSC/lib/pkcs11-spy.so
 #pkcs11-module-path = /opt/local/lib/p11-kit-proxy.dylib
 activate = 1 

Finally, spy.log: spy2.log.txt

@dengert
Copy link
Contributor

dengert commented May 1, 2023

based on the spy2.log.txt:

58: C_GetAttributeValue
P:85482; T:0x8499780416 2023-04-30 17:30:12.556
[in] hSession = 0x17
[in] hObject = 0x57
[in] pTemplate[1]: 
    CKA_ALLOWED_MECHANISMS  0000000000000000 / 0
[out] pTemplate[1]: 
    CKA_ALLOWED_MECHANISMS  0000000000000000 / -1
Returned:  18 CKR_ATTRIBUTE_TYPE_INVALID

It appears OpenSC does not support CKA_ALLOWED_MECHANISMS accept in spy:

OpenSC/src/pkcs11$ grep CKA_ALLOWED_MECHANISMS *
pkcs11-display.c:  { CKA_ALLOWED_MECHANISMS, "CKA_ALLOWED_MECHANISMS ", print_generic, NULL },
pkcs11.h:#define CKA_ALLOWED_MECHANISMS		(CKF_ARRAY_ATTRIBUTE | 0x600UL)

If it did for private keys it would be in pkcs15_prkey_get_attribute here:

https://github.com/OpenSC/OpenSC/blob/master/src/pkcs11/framework-pkcs15.c#L3981-L4118

@dengert
Copy link
Contributor

dengert commented May 1, 2023

Maybe if CKA_ALLOWED_MECHANISMS is not supported, provider should uses the list returned by:

27: C_GetMechanismList
P:85482; T:0x8499780416 2023-04-30 17:30:09.028
[in] slotID = 0x13
[out] pMechanismList[70]: 
 CKM_AES_CBC                   
 CKM_AES_CBC_ENCRYPT_DATA      
 CKM_AES_CBC_PAD               
 CKM_AES_CMAC                  
 CKM_AES_CTR                   
 CKM_AES_ECB                   
 CKM_AES_ECB_ENCRYPT_DATA      
 CKM_AES_GCM                   
 CKM_AES_KEY_GEN               
 CKM_AES_KEY_WRAP              
 Unknown Mechanism (0000210a)  
 CKM_DES2_KEY_GEN              
 CKM_DES3_CBC                  
 CKM_DES3_CBC_ENCRYPT_DATA     
 CKM_DES3_CBC_PAD              
 CKM_DES3_CMAC                 
 CKM_DES3_ECB                  
 CKM_DES3_ECB_ENCRYPT_DATA     
 CKM_DES3_KEY_GEN              
 CKM_DES_CBC                   
 CKM_DES_CBC_ENCRYPT_DATA      
 CKM_DES_CBC_PAD               
 CKM_DES_ECB                   
 CKM_DES_ECB_ENCRYPT_DATA      
 CKM_DES_KEY_GEN               
 CKM_DH_PKCS_DERIVE            
 CKM_DH_PKCS_KEY_PAIR_GEN      
 CKM_DH_PKCS_PARAMETER_GEN     
 CKM_DSA                       
 CKM_DSA_KEY_PAIR_GEN          
 CKM_DSA_PARAMETER_GEN         
 CKM_DSA_SHA1                  
 CKM_DSA_SHA224                
 CKM_DSA_SHA256                
 CKM_DSA_SHA384                
 CKM_DSA_SHA512                
 CKM_ECDH1_DERIVE              
 CKM_ECDSA                     
 Unknown Mechanism (00001055)  
 CKM_EC_KEY_PAIR_GEN           
 CKM_EDDSA                     
 CKM_GENERIC_SECRET_KEY_GEN    
 CKM_MD5                       
 CKM_MD5_HMAC                  
 CKM_MD5_RSA_PKCS              
 CKM_RSA_PKCS                  
 CKM_RSA_PKCS_KEY_PAIR_GEN     
 CKM_RSA_PKCS_OAEP             
 CKM_RSA_PKCS_PSS              
 CKM_RSA_X_509                 
 CKM_SHA1_RSA_PKCS             
 CKM_SHA1_RSA_PKCS_PSS         
 Unknown Mechanism (00000255)  
 Unknown Mechanism (00000256)  
 Unknown Mechanism (00000046)  
 Unknown Mechanism (00000047)  
 CKM_SHA256                    
 CKM_SHA256_HMAC               
 CKM_SHA256_RSA_PKCS           
 CKM_SHA256_RSA_PKCS_PSS       
 CKM_SHA384                    
 CKM_SHA384_HMAC               
 CKM_SHA384_RSA_PKCS           
 CKM_SHA384_RSA_PKCS_PSS       
 CKM_SHA512                    
 CKM_SHA512_HMAC               
 CKM_SHA512_RSA_PKCS           
 CKM_SHA512_RSA_PKCS_PSS       
 CKM_SHA_1                     
 CKM_SHA_1_HMAC                
Returned:  0 CKR_OK

and if found, assume the card can do it and try the crypto operation.

@dengert
Copy link
Contributor

dengert commented May 1, 2023

It looks like provider fixed a similar problem for SoftHSM: 0e25049

@mouse07410
Copy link
Author

It looks like provider fixed a similar problem for SoftHSM: 0e25049

@simo5 perhaps you could do that?

@simo5
Copy link
Member

simo5 commented May 1, 2023

@dengert pkcs11-provider already filter session by the mechanisms supported by the token.
And as you saw we also have code to ignore bogis CKA_MECHANISM_ALLOWED set to 0 elements

@mouse07410 not sure what I should do, I just tested once again the dgst sign/verify with the yubico pkcs11 driver and it works fine here. The cms also works fine with the yubico driver.

What version of the provider are you using?

To me it seem this may be either a bug/limitation in p11-kit proxy or in OpenSC, but the logs are not enough to figure out what fails. The CKA_ALLOW_MECHANISMS is not the problem if this is origin/main of pkcs11-provider, but it could be if you use OpenSC and older build.

@mouse07410
Copy link
Author

@mouse07410 not sure what I should do, I just tested once again the dgst sign/verify with the yubico pkcs11 driver and it works fine here. The cms also works fine with the yubico driver.

Frankly, I don't know - the problem stymies me, and I've no clue what seems to be causing it. The only thing that seems reasonably sure is that OpenSC does not integrate well...

I use:

  • origin/main of pkcs11-provider
  • master of OpenSC
  • Macports-installed OpenSSL-3.1.0

the logs are not enough to figure out what fails.

If you (or somebody else) could tell me how to get more/other logs that could be more helpful - I'll be happy to provide.

@simo5
Copy link
Member

simo5 commented May 1, 2023

I think we need to go in steps.
First we need to make this working with the native drivers.

You showed a failure with a Yubikey (4 or 5) in generating a PSS signature.
Can you capture the pkcs11-provider log when that happens ?
Please set level:2 as I want to see what mechanisms it publishes and what driver is in use.

@dengert
Copy link
Contributor

dengert commented May 1, 2023

I can reproduce one of @mouse07410 problems on Ubuntu 22.04 with OpenSC master, OpenSSL 3.1.0 and provider main with Yubico 5:

gdb--args ./openssl dgst  -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig2 /tmp/pt.txt
Enter pass phrase for PKCS#11 Token (Slot 0 - Yubico YubiKey OTP+FIDO+CCID 00 00):
Signature parameter error "rsa_padding_mode:pss"
4017B72BEF7F0000:error:43000070:pkcs11:p11prov_rsasig_set_ctx_params:An invalid mechanism was specified to the cryptographic operation:../../src/src/signature.c:1508:CKM_RSA_PKCS_PSS unavailable
1436	    P11PROV_debug("rsasig set ctx params (ctx=%p, params=%p)", sigctx, params);
(gdb) n
1438	    if (params == NULL) {
(gdb) p params
$47 = (const OSSL_PARAM *) 0x0
(gdb) n
1439	        return RET_OSSL_OK;
(gdb) where
#0  p11prov_rsasig_set_ctx_params (ctx=0x5555556b6d90, params=0x0) at ../../src/src/signature.c:1439
#1  0x00007ffff7eb17f5 in p11prov_rsasig_digest_sign_init (ctx=0x5555556b6d90, digest=0x7fffffffe25c "sha384", provkey=0x5555556b7040, 
    params=0x0) at ../../src/src/signature.c:1191
#2  0x00007ffff79ff9ac in do_sigver_init (ctx=<optimized out>, pctx=pctx@entry=0x7fffffffdc00, type=type@entry=0x0, 
    mdname=mdname@entry=0x7fffffffe25c "sha384", libctx=<optimized out>, props=<optimized out>, props@entry=0x0, e=0x0, 
    pkey=0x55555569e1a0, ver=0, params=0x0) at ../openssl/crypto/evp/m_sigver.c:266
#3  0x00007ffff7a002f2 in EVP_DigestSignInit_ex (ctx=<optimized out>, pctx=pctx@entry=0x7fffffffdc00, 
    mdname=mdname@entry=0x7fffffffe25c "sha384", libctx=<optimized out>, props=props@entry=0x0, pkey=pkey@entry=0x55555569e1a0, 
    params=0x0) at ../openssl/crypto/evp/m_sigver.c:372
#4  0x00005555555b18aa in dgst_main (argc=1, argv=0x7fffffffdea0) at ../openssl/apps/dgst.c:355
#5  0x00005555555c1402 in do_cmd (prog=prog@entry=0x555555663870, argc=argc@entry=11, argv=argv@entry=0x7fffffffde50)
    at ../openssl/apps/openssl.c:418
#6  0x000055555559c5df in main (argc=11, argv=0x7fffffffde50) at ../openssl/apps/openssl.c:298

I could be wrong, but it looks like in OpenSSL dgst.c calls EVP_DigestSignInit_ex at:
https://github.com/openssl/openssl/blob/master/apps/dgst.c#L356

But does not process the PSS sigopts until: https://github.com/openssl/openssl/blob/master/apps/dgst.c#L365-L375
where pkey_ctrl_string(pctx, sigopt) adds then to the pctx.

Thus the provider does not have any of the PSS parameters during EVP_DigestSignInit_ex

This would only effect the provider when doing RSA with parameters, such as PSS.

I am going to try and move the code later today to see if that is a fix.

@simo5
Copy link
Member

simo5 commented May 1, 2023

I could be wrong, but it looks like in OpenSSL dgst.c calls EVP_DigestSignInit_ex at: https://github.com/openssl/openssl/blob/master/apps/dgst.c#L356

But does not process the PSS sigopts until: https://github.com/openssl/openssl/blob/master/apps/dgst.c#L365-L375 where pkey_ctrl_string(pctx, sigopt) adds then to the pctx.

Thus the provider does not have any of the PSS parameters during EVP_DigestSignInit_ex

This is normal, the provider does not do anything but retrieve the key at "digest_sign_init".
Parameters for PSS are passed later via the pkey_ctrl_string() function that will end up calling the appropriate "set_ctx_params" call in the provider.

The provider defers the pkcs#11 Sig Op initialization until the first "digest_sign_update" call is performed exactly to account for this OpenSSL behavior.

@simo5
Copy link
Member

simo5 commented May 1, 2023

The problem here is that it seems that there is no CKM_RSA_PKCS_PSS exposed as a valid mechanism by the token.

Can you run pkcs11-provide with level:2 debug to figure out the list of mechanisms exposed by the slot the key is on?

@mouse07410
Copy link
Author

The problem here is that it seems that there is no CKM_RSA_PKCS_PSS exposed as a valid mechanism by the token.

I am pretty sure Yubikeys (and other smartcards) can not do RSA-PSS on-board, and rely upon the supporting software/driver/etc to perform the PSS part.
Unlike YubiHSM2 (and other HSM devices) which (usually) refuse to do raw RSA, and insist on PSS and such.

@simo5
Copy link
Member

simo5 commented May 1, 2023

The problem here is that it seems that there is no CKM_RSA_PKCS_PSS exposed as a valid mechanism by the token.

I am pretty sure Yubikeys (and other smartcards) can not do RSA-PSS on-board, and rely upon the supporting software/driver/etc to perform the PSS part. Unlike YubiHSM2 (and other HSM devices) which (usually) refuse to do raw RSA, and insist on PSS and such.

As far as I know the OpenSC driver deals with that, but I may be wrong.

@dengert
Copy link
Contributor

dengert commented May 1, 2023

Here is something ...
OpenSC 0.22.0 pkcs11-tool -M | grep PSS
RSA-PKCS-PSS, keySize={1024,3072}, hw, sign, verify
SHA1-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
SHA224-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
SHA256-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
SHA384-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
SHA512-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify

OpenSC built from master does not list any of these!
Will look later...

@mouse07410
Copy link
Author

Current (master) OpenSC and YKCS11:

$ pkcs11-tool --module /Library/OpenSC/lib/opensc-pkcs11.so -M | grep PSS
Using slot 0 with a present token (0x0)
  RSA-PKCS-PSS, keySize={1024,3072}, hw, sign, verify
  SHA1-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
  SHA224-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
  SHA256-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
  SHA384-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
  SHA512-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
$ pkcs11-tool --module /usr/local/lib/libykcs11.dylib -M | grep PSS 
Using slot 0 with a present token (0x0)
  RSA-PKCS-PSS, keySize={1024,2048}, hw, sign, verify
  SHA1-RSA-PKCS-PSS, keySize={1024,2048}, hw, sign, verify
  SHA256-RSA-PKCS-PSS, keySize={1024,2048}, hw, sign, verify
  SHA384-RSA-PKCS-PSS, keySize={1024,2048}, hw, sign, verify
  SHA512-RSA-PKCS-PSS, keySize={1024,2048}, hw, sign, verify
$ 

I don't know whether the driver (opensc-pkcs11.so or libykcs11.dylib) does the PSS part, or OpenSSL does. My bet is on the driver.

@dengert
Copy link
Contributor

dengert commented May 1, 2023

PIV cards only do CKM_RSA-X-509 on the card i.e. RSA RAW. The rest is done in OpenSC.

Something has changes in OpenSC between 0.23.0 and master.

OpenSC 0.23.0 pkcs11-tool works:

gdb --args /opt/ossl-3.1.0/bin/openssl dgst -sign pkcs11:manufacturer=piv_II\;id=%02\;type=private -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig2 /tmp/pt.txt
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Enter pass phrase for PKCS#11 Token (Slot 0 - Yubico YubiKey OTP+FIDO+CCID 00 00):
[Inferior 1 (process 163969) exited normally

./pkcs11-tool -M | grep PSS
Using slot 0 with a present token (0x0)
  RSA-PKCS-PSS, keySize={1024,3072}, hw, sign, verify
  SHA1-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
  SHA224-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
  SHA256-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
  SHA384-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify
  SHA512-RSA-PKCS-PSS, keySize={1024,3072}, sign, verify

and here is level:2 log:

prov.log-opensc.0.23.0.txt

Starting git bisect...

@dengert
Copy link
Contributor

dengert commented May 2, 2023

OpenSC Commit 1d5c81e85baaa82973e1080dfb34876830bee067 appears to be the problem. Committed March 29.

Reverting it in OpenSC master causes test to work. The changes was for one specific card, but it looks like it causes problems with at least PSS and maybe other cards.

@mouse07410 try git revert 1d5c81e85baaa82973e1080dfb34876830bee067 and rebuild.

@mouse07410
Copy link
Author

mouse07410 commented May 2, 2023

@mouse07410 try git revert 1d5c81e85baaa82973e1080dfb34876830bee067 and rebuild.

Thank you! Reverting this commit did not fix p11-kit problem, but restored OpenSC to functioning correctly. First call to openssl dgst is with pkcs11-module-path = /opt/local/lib/p11-kit-proxy.dylib in openssl.cnf. For the second I'm forcing PKCS11_PROVIDER_MODULE away from p11-kit.

$ openssl dgst  -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig2 /tmp/pt.txt
Enter pass phrase for PKCS#11 Token (Slot 17 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
405BA0FA01000000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$ PKCS11_PROVIDER_MODULE=/Library/OpenSC/lib/opensc-pkcs11.so openssl dgst  -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig2 /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 0 - Yubico YubiKey OTP+FIDO+CCID):
$ 

So, how do we fix this p11-kit problem? Having different tokens, it's very convenient to have a switch that automatically figures which module to load for a given key URI... @neverpanic could you pitch in please?

Update

I wonder how pkcs11-provider differs in what it's doing from the engine libp11 - because the above works fine with the engine:

$ openssl dgst -engine pkcs11 -keyform engine  -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig2 /tmp/pt.txt
Engine "pkcs11" set.
Enter PKCS#11 token PIN for XXXXXXXXXX:
$ ll /tmp/pt.txt.sig2
-rw-r--r--  1 ur20980  wheel  256 May  1 22:30 /tmp/pt.txt.sig2
$ openssl dgst -engine pkcs11 -keyform engine  -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig3 /tmp/pt.txt
Engine "pkcs11" set.
Enter PKCS#11 token PIN for YubiKey PIV #xxxxxxxxx:
Enter PKCS#11 key PIN for Private key for Digital Signature:
$ ll /tmp/pt.txt.sig3
-rw-r--r--  1 ur20980  wheel  256 May  1 22:31 /tmp/pt.txt.sig3
$ 

Some kind of weird interaction between p11-kit and pkcs11-provider, which doesn't exist between p11-kit and libp11?

@simo5
Copy link
Member

simo5 commented May 2, 2023

I really do not see how interacting with PIN logins makes a difference ...
Would love to see a pkcs11-provider of the same operation with the problematic opensc and with the reverted version.
I wonder if we fail to login to the card when we can and end up w/o a login session?

@mouse07410 if you still have the problematic version available can you set pkcs11-module-login-behavior = always and see if that "fixes" the issue?

@mouse07410
Copy link
Author

mouse07410 commented May 2, 2023

if you still have the problematic version available can you set pkcs11-module-login-behavior = always and see if that "fixes" the issue?

First, I don't have the offending version anymore, sorry. But it doesn't seem to matter here.

Regarding fixing - alas, no:

openssl dgst  -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/derive.26838.text.sig /tmp/derive.26838.text
Enter pass phrase for PKCS#11 Token (Slot 21 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
405B10FD01000000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$
$ openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig /tmp/pt.txt
Enter pass phrase for PKCS#11 Token (Slot 17 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
405B10FD01000000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$

Something between pkcs11-provider and p11-kit, most likely. Because when I force PKCS11_PROVIDER_MODULE=/Library/OpenSC/lib/opensc-pkcs11.so (or equivalent for YKCS11), avoiding p11-kit, it works:

$ PKCS11_PROVIDER_MODULE=/Library/OpenSC/lib/opensc-pkcs11.so openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:48 -out /tmp/pt.txt.sig /tmp/pt.txt
Enter pass phrase for PKCS#11 Token (Slot 0 - Yubico YubiKey OTP+FIDO+CCID):
$ ll /tmp/pt.txt.sig
-rw-r--r--  1 ur20980  wheel  256 May  2 11:58 /tmp/pt.txt.sig
$ 

@simo5
Copy link
Member

simo5 commented May 2, 2023

@dengert what is odd from your log is that there is clearly a signature operation going though ... and then a second attempt at initializing a signature operation with a null key ..

I wonder if you reproduced the same error @mouse07410 has.

@simo5
Copy link
Member

simo5 commented May 2, 2023

@Jakuje I recall you told me that p11-kit-proxy may have had some limitation with some algorithms, can this be the case?

@simo5
Copy link
Member

simo5 commented May 2, 2023

@mouse07410 sounds to me like this is a p11-kit problem then.
If pkcs11-provider is working correctly by calling the correct driver directly, then the issues seems to be more of a p11-kit shortcoming than a pkcs11-provider one.

@mouse07410
Copy link
Author

@mouse07410 sounds to me like this is a p11-kit problem then.

p11-kit definitely contributes - but I doubt it's solely p11-kit's problem.

If pkcs11-provider is working correctly by calling the correct driver directly, then the issues seems to be more of a p11-kit shortcoming than a pkcs11-provider one.

I see the logic - however, please note that when p11-kit is invoked by the libp11 engine instead of pkcs11-provider, it works. So:

  • calling relevant driver directly works always for provider and engine;
  • calling driver via p11-kit from provider fails;
  • calling driver via from libp11 engine works.

I recall you told me that p11-kit-proxy may have had some limitation with some algorithms, can this be the case?

I think not, because it works when engine is used instead of provider.

@simo5
Copy link
Member

simo5 commented May 2, 2023

I think not, because it works when engine is used instead of provider.

The engine may be doing some emulation we do not want (yet) to do with pkcs11-provider.

@dengert
Copy link
Contributor

dengert commented May 3, 2023

@mouse07410 can you trying this untested patch to OpenSC src/pkcs11/framework-pkcs15.c
Instead of returning NULL and len=0xffffffff it should return NULL and 0.
It not perfect and is only for private keys.

diff --git a/src/pkcs11/framework-pkcs15.c b/src/pkcs11/framework-pkcs15.c
index 62bb9a7a9..e53f7d0fa 100644
--- a/src/pkcs11/framework-pkcs15.c
+++ b/src/pkcs11/framework-pkcs15.c
@@ -4022,6 +4022,11 @@ pkcs15_prkey_get_attribute(struct sc_pkcs11_session *session,
                check_attribute_buffer(attr, len);
                memcpy(attr->pValue, prkey->prv_p15obj->label, len);
                break;
+               /* test to partial support the attribute */
+       case CKA_ALLOWED_MECHANISMS:
+               attr->pValue = NULL;
+               attr->ulValueLen = 0;
+               break;
        case CKA_KEY_TYPE:
                check_attribute_buffer(attr, sizeof(CK_KEY_TYPE));
                switch (prkey->prv_p15obj->type) {

@mouse07410
Copy link
Author

mouse07410 commented May 3, 2023

I think the second driver may invalidate the login session with the card obtained by the first driver as it most probably call a C_Initialize on it ... so it makes perfect sense that it would fail in retrospect.

But in the last case the 2nd driver is for a different token altogether - it shouldn't even receive any calls. Why would it interfere? How does libp11 engine prevent it? And, more importantly, what can the provider do to prevent such interference?

an you trying this untested patch to OpenSC src/pkcs11/framework-pkcs15.c?

I've applied the patch, but it did not seem to make a difference:

openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
4083FE52F87F0000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$ 

prov-debug.txt
spy-out.txt
screen-log.txt


And here's the successful trace from the libp11 engine:

$ OPENSC_DEBUG=3 PKCS11SPY_OUTPUT=/tmp/spy-out.log PKCS11_PROVIDER_DEBUG="file:/tmp/prov-debug.txt,level:2" openssl dgst -engine pkcs11 -keyform engine -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Engine "pkcs11" set.
C_Initialize
  IN: pInitArgs = NULL
P:39531; T:0x140704521028416 17:22:44.227 [opensc-pkcs11] ctx.c:734:process_config_file: Used configuration file '/Library/OpenSC/etc/opensc.conf'
C_Initialize = CKR_OK
C_Initialize
  IN: pInitArgs = NULL
C_Initialize = CKR_OK
C_Initialize
  IN: pInitArgs = NULL
C_Initialize = CKR_OK
C_GetSlotList
.  .  .
C_FindObjectsFinal
  IN: hSession = S105553152921648
C_FindObjectsFinal = CKR_OK
Enter PKCS#11 token PIN for XXXXXXXXXXXXXXX:
C_GetSessionInfo
  IN: hSession = S105553152921648
 OUT: pInfo = {
	slotID: SL4
	state: CKS_RO_PUBLIC_SESSION
	flags: 4 = CKF_SERIAL_SESSION
	ulDeviceError: 0
      }
C_GetSessionInfo = CKR_OK
C_Login
  IN: hSession = S105553152921648
  IN: userType = CKU_USER
  IN: pPin = (8) "xxxxxxxx"
C_Login = CKR_OK
C_GetSessionInfo
  IN: hSession = S105553152921648
 OUT: pInfo = {
	slotID: SL4
	state: CKS_RO_USER_FUNCTIONS
	flags: 4 = CKF_SERIAL_SESSION
	ulDeviceError: 0
      }
C_GetSessionInfo = CKR_OK
.  .  .
C_GetSessionInfo = CKR_OK
C_SignInit
  IN: hSession = S105553152921648
  IN: pMechanism = {
	mechanism: CKM_RSA_PKCS_PSS
	pParameter: (24) "`\x02\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x000\x00\x00\x00\x00\x00\x00\x00"
      }
  IN: hKey = H105553164452032
C_SignInit = CKR_OK
C_Sign
  IN: hSession = S105553152921648
  IN: pData = (48) "\xA1\xC1Oa\x8CV\x10b\x86E~\xA3\xED@<\xD1\x976|\x96;q\xCB\x1A$\xAC\x98\xC2[\xB5\x9Dq(\xF8f+V\xF3\xF9\x0F\xFE\x05*\xB2\x7..."
 OUT: pSignature = (256) "F+Y\x01\xCEB\x8F\x8FZ\xD1\x94h\xA8\xC7\xB1J\xE7\x1A:\xF3K\x1Fu\x010ky\xE5/!\xFF\x1B\x97wv\xCE\x1A\xE1c\xC8\xD7T\xF3QL\x..."
C_Sign = CKR_OK
$ 

screen-log-engine.txt
(neither SPY not OPENSC_DEBUG output was produced, for reasons unclear to me)


Update

Maybe p11-kit is not handling the CKA_ALLOWED_MECHANISMS and/or not mapping the error correctly between provider and the loaded pkcs11 modules(s).

I've no idea. @neverpanic?

@mouse07410 are you using p11-kit remote or RPC?

I don't think so. Everything's local from the p11-kit's point of view. The fact that yubihsm_pkcs1.dylib employed HTTPS is transparent to p11-kit.

@simo5
Copy link
Member

simo5 commented May 3, 2023

But in the last case the 2nd driver is for a different token altogether - it shouldn't even receive any calls. Why would it interfere?

Hmm I thought it was implied the two drivers were talking to the same hardware?
If that is not the case then it is not as clear cut.

How does libp11 engine prevent it?

I do not think it does, I guess I misunderstood the problem.

And, more importantly, what can the provider do to prevent such interference?

It wouldn't be able to, the provider assumes it is talking to a single, coherent, driver.
The only thing the provider understand is that individual slots are somewhat independent from each other in terms of functionality.

I think we are back to p11-kit not properly handling something pkcs11-provider does that libp11 engine doesn't.
Possible the CKA_ALLOWED_MECHANISM indeed (although we used the p11-kit-proxy stuff for softhsm testing for a while and this has never been a problem there, so ... unclear).

@dengert please do not return 0 length CKA_ALLOWED_MECHANISM values, although I currently have a workaround in because softhsm does that I plan to remove or put it behind a quirk, as a 0 length value really means: no mechanism supported for this key, go away. And yubico's driver plans to use it that way.

If p11-kit really is choking on this value, I can add a configuration quirk (perhaps auto-detect it base on the token vendor/version even).

@mouse07410 would you be willing to try a provider patch that prevents asking for CKA_ALLOWED_MECHANISMS entirely?

@mouse07410
Copy link
Author

Hmm I thought it was implied the two drivers were talking to the same hardware?

Normally I have both opensc.module and ykcs11.module - so that regardless of whether the key URI is presented with manufactorer=piv_II (requiring OpenSC) or model=YubiKey%20YK4 (requiring YKCS11), the appropriate driver would be loaded.

But for the last tests, I put one module for Yubikey (the OpenSC one), and one for YubiHSM2. Completely different hardware.

If that is not the case then it is not as clear cut.

;-) It's never been clear-cut for me.

I think we are back to p11-kit not properly handling something pkcs11-provider does that libp11 engine doesn't.

Or the other way around? pkcs11-provider doesn't do something that libp11 engine does???

@dengert please do not return 0 length CKA_ALLOWED_MECHANISM values, although I currently have a workaround in because softhsm does that I plan to remove or put it behind a quirk, as a 0 length value really means: no mechanism supported for this key, go away. And yubico's driver plans to use it that way.

Noted. I'll revert this patch.

If p11-kit really is choking on this value, I can add a configuration quirk (perhaps auto-detect it base on the token vendor/version even).

Can't see how this could hurt - so let's do it anyway.

@mouse07410 would you be willing to try a provider patch that prevents asking for CKA_ALLOWED_MECHANISMS entirely?

Of course! Just post the patch.

@dengert
Copy link
Contributor

dengert commented May 4, 2023

Disagree with: "so it makes perfect sense that it would fail in retrospect."

Smartcards are accessed by PC/SC, which provides a locking mechanism to lock access to the card for one or more transactions (ADPUs) There are Microsoft, Linux and MacOS implementations. https://pcscworkgroup.com/

This locking should prevent any other process or other PKCS11 modules from accessing the same card at the same time. The OpenSC PIV driver goes to great lengths to make sure the card login state has not changed in between transactions.

Normally I have both opensc.module and ykcs11.module - so that regardless of whether the key URI is presented with manufactorer=piv_II (requiring OpenSC) or model=YubiKey%20YK4 (requiring YKCS11), the appropriate driver would be loaded.

PKCS11 modules requests a list of readers when they start and check which reader have tokens and if they can support the token or tokens and read a lot of data form the token. So both drivers would be loaded andboth look at all the tokens. But only one would be used to do the sign operation based on the the URI selecting the driver

I am not familiar with MacOS and how PC/SC is implemented, So it could be possible there are problems with locking. There should be only one system PC/SC daemon running.

@dengert
Copy link
Contributor

dengert commented May 4, 2023

@mouse07410 When I built p11-kit I used:
CPPFLAGS= -DDEBUG
CFLAGS= -g
LDFLAGS= -g -Wl,-rpath,/opt/ossl-3.1.0/lib
../src/configure --prefix=/opt/ossl-3.1.0 --without-bash-completion --without-systemd

233 configure: build options:
234
235 Host: x86_64-pc-linux-gnu
236 Debug build: default (-g, debug output)
237 Strict build: no
238 Build documentation: no (no manual or reference)
239 System global config: ${prefix}/etc/pkcs11/pkcs11.conf
240 System module config directory: ${prefix}/etc/pkcs11/modules
241 Package module config directory: ${pkgdatadir}/modules
242 User global config: ~/.config/pkcs11/pkcs11.conf
243 User module config directory: ~/.config/pkcs11/modules
244 Load relative module paths from: ${exec_prefix}/lib/pkcs11
245
246 With libtasn1 dependency: yes
247 With libffi: yes
248 With hash implementation: internal
249 With systemd: no
250
251 Build trust module: yes
252 Trust module paths: /etc/ssl/certs/ca-certificates.crt
253
254 RPC protocol versions: 0 upto 0
255

@simo5
Copy link
Member

simo5 commented May 4, 2023

Disagree with: "so it makes perfect sense that it would fail in retrospect."

Maybe "perfect sense" is an exaggeration, but if two drivers in the same process were to independently access pc/sc it may cause issues difficult to explain.

Apparently this is not the case anyway so let's ignore this line of thought for now.

@simo5
Copy link
Member

simo5 commented May 5, 2023

@mouse07410 can you test the patch in #237 ?

@simo5
Copy link
Member

simo5 commented May 5, 2023

Requires setting this line in openssl.conf:
pkcs11-module-quirks = no-allowed-mechanisms

@mouse07410
Copy link
Author

Current main with #237 applied - still fails:

$ openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
4083FE52F87F0000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
p11-kit: 'bound != NULL' not true at fixed3_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed3_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed3_C_Finalize
$ 

Excerpt from openssl.cnf:

[pkcs11_sect]
 module = /opt/local/libexec/openssl3/lib/ossl-modules/pkcs11.dylib
 pkcs11-module-quirks = no-deinit
 pkcs11-module-login-behavior = auto
 #pkcs11-module-login-behavior = always
 pkcs11-module-cache-pins = cache
 pkcs11-module-quirks = no-allowed-mechanisms
 #pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so
 #pkcs11-module-path = /usr/local/lib/libykcs11.dylib
 pkcs11-module-path = /opt/local/lib/p11-kit-proxy.dylib
 activate = 1

Should I try to provide "full debug" output, as before?

@dengert
Copy link
Contributor

dengert commented May 5, 2023

"Error setting context" appears 12 times in the issue, followed by "4083FE52F87F0000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:"

grep "Error setting" or grep "setting context" does not appear in any of packages involved accept OpenSSL in https://github.com/openssl/openssl/blob/master/apps/dgst.c#L354-L363 after the call to EVP_DigestSignInit_ex

I built yubico-piv-tool from github, and have not been able to cause the failure.

@mouse07410 you have the only test environment the has MacOS and 2 Yubikeys and some other PKCS11 modules. So getting a core dump or at least a stack trace would be very helpful.

@dengert
Copy link
Contributor

dengert commented May 6, 2023

One other thing that could happen is is if two libs or modules have that same routine, and some how the loader/linker resolves an external reference to the wrong library. I saw this same type of problem with PAM and Kerberos module may years ago.

@mouse07410
Copy link
Author

I built yubico-piv-tool from github, and have not been able to cause the failure.

I assume your ~/.config/pkcs11/modules/ has at least two modules defined - opensc.module and ykcs``.module? Otherwise, with only one physical token, and only one module configured - you won't see a failure.

@mouse07410 you have the only test environment the has MacOS and 2 Yubikeys and some other PKCS11 modules. So getting a core dump or at least a stack trace would be very helpful.

Core dump is next to impossible (unless the app actually crashes) - Macs are very comfortable to use, but darn inconvenient for debugging. Stack traces have also been problematic in the past. :-(

One other thing that could happen is is if two libs or modules have that same routine, and some how the loader/linker resolves an external reference to the wrong library. I saw this same type of problem with PAM and Kerberos module many years ago.

Hmm... This would be really unfortunate - as I'd expect every module to export pretty very similar (if not exactly the same!) API... Don't know what to say...


To keep me (and you ;) fully entertained, here are results from OpenSSL-3.2.0-dev:

$ openssl3 dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_Finalize
$
$ openssl3 dgst -verify "pkcs11:manufacturer=piv_II;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -signature /tmp/pt.txt.sig /tmp/pt.txt 
Verified OK
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_Finalize
$ 
$ openssl3 dgst -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 23 - Yubico YubiKey OTP+FIDO+CCID):
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_Finalize
$ openssl3 dgst -verify "pkcs11:manufacturer=piv_II;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -signature /tmp/pt.txt.sig /tmp/pt.txt 
Verified OK
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_Finalize
$ 
$
$ openssl3 dgst -sign "pkcs11:model=YubiHSM;id=%04%01;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sighsm /tmp/pt.txt
Enter pass phrase for PKCS#11 Token (Slot 21 - YubiHSM Connector 0.0.0.0):
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_Finalize
$ openssl3 dgst -verify "pkcs11:model=YubiHSM;id=%04%01;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -signature /tmp/pt.txt.sighsm /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 21 - YubiHSM Connector 0.0.0.0):
Verified OK
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_Finalize
$
$ $ ll ~/.config/pkcs11/modules
total 32
drwxr-xr-x  6 ur20980  staff  192 May  6 22:23 ./
drwxr-xr-x  4 ur20980  staff  128 May  3 15:39 ../
-rw-r--r--  1 ur20980  staff  157 Nov 14  2021 pkcs11.module
-rw-r--r--  1 ur20980  staff  174 Feb 14 08:37 softhsm2.module
-rw-r--r--  1 ur20980  staff  200 Nov 20  2021 yhsm2.module
-rw-r--r--  1 ur20980  staff  151 Nov 19  2021 ykcs11.module
$

Now - another trouble. Being quite annoyed by these apparently-useless assertions of the Macports-installed p11-kit

p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_CloseSession
p11-kit: 'bound != NULL' not true at fixed4_C_Finalize

I decided to try my luck on p11-kit master that I build from the source with

meson setup --prefix=/opt/p11kit -Dsystemd=disabled -Dbash_completion=disabled -Dclosures=0 _build

Here's how I switched from Macports-installed p11-kit to this:

[pkcs11_prov]
  module = /Users/ur20980/openssl-3/lib/ossl-modules/pkcs11.dylib
  pkcs1-module-quirks = no-deinit,no-allowed-mechanisms
  pkcs11-module-login-behavior = auto
  pkcs11-module-cache-pins = cache
  #pkcs11-module-path = /Library/OpenSC/lib/opensc-pkcs11.so
  #pkcs11-module-path = /usr/local/lib/libykcs11.dylib
  #pkcs11-module-path = /Library/OpenSC/lib/pkcs11-spy.so
  #pkcs11-module-path = /opt/local/lib/p11-kit-proxy.dylib
  pkcs11-module-path = /opt/p11kit/lib/p11-kit-proxy.dylib
  activate = 1

I got a crash - with apparently no-deinit being ignored?!

$ openssl3 dgst -sign "pkcs11:model=YubiKey%20YK4;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 23 - Yubico YubiKey OTP+FIDO+CCID):
Segmentation fault: 11

Crash report:

Exception Type:        EXC_BAD_ACCESS (SIGSEGV)
Exception Codes:       KERN_INVALID_ADDRESS at 0x0000000000000000
Exception Codes:       0x0000000000000001, 0x0000000000000000

Termination Reason:    Namespace SIGNAL, Code 11 Segmentation fault: 11
Terminating Process:   exc handler [85800]

VM Region Info: 0 is not in any region.  Bytes before following region: 4305735680
      REGION TYPE                    START - END         [ VSIZE] PRT/MAX SHRMOD  REGION DETAIL
      UNUSED SPACE AT START
--->  
      __TEXT                      100a45000-100add000    [  608K] r-x/r-x SM=COW  ...SER/*/openssl

Thread 0 Crashed::  Dispatch queue: com.apple.main-thread
0   ???                           	               0x0 ???
1   libp11-kit.0.dylib            	       0x100f4f615 binding_C_CloseSession + 21 (virtual.c:309)
2   libffi.8.dylib                	       0x100c44942 ffi_closure_unix64_inner + 545
3   libffi.8.dylib                	       0x100c44f4c ffi_closure_unix64 + 72
4   pkcs11.dylib                  	       0x100c062e5 p11prov_CloseSession + 101
5   pkcs11.dylib                  	       0x100c062e5 p11prov_CloseSession + 101
6   pkcs11.dylib                  	       0x100c062e5 p11prov_CloseSession + 101
.  .  .
509 pkcs11.dylib                  	       0x100c062e5 p11prov_CloseSession + 101
510 pkcs11.dylib                  	       0x100c062e5 p11prov_CloseSession + 101
511 pkcs11.dylib                  	       0x100c062e5 p11prov_CloseSession + 101

@dengert
Copy link
Contributor

dengert commented May 7, 2023

@mouse07410 can you run your tests using the Auth key( id=%01) rather then the Sign key (id=%02)

This will eliminate the following problem in testing with p11-kit:

The provider does not check private key for CKA_ALWAYS_AUTHENTICATE and does not then ask user for PIN again to do C_Login with CKU_CONTEXT_SPECIFIC i.e. acting like FireFox used too. (Caching the pin provider is not good enough unless C_Login with CKU_CONTEXT_SPECIFIC is used.)

OpenSC in opensc.conf can use_pin_caching = true; and pin_cache_ignore_user_consent = true; for older applications that do not support CKA_ALWAYS_AUTHENTICATE the pin caching is then done within OpenSC module. See: https://github.com/OpenSC/OpenSC/blob/master/etc/opensc.conf.example.in#L918-L923 or man opensc.conf

OpenSC was designed to work with PIN_PAD readers where the pin is never seen by the host computer and thus can never be cached thus requiring the user to prompted for PIN each time.

Also check if you have use_pin_caching and/or pin_cache_ignore_user_consent in any of you tests.

ykcs11 also supports CKA_ALWAYS_AUTHENTICATE and CKU_CONTEXT_SPECIFIC.

@simo5
PIV cards enforce this on the card: https://nvlpubs.nist.gov/nistpubs/specialpublications/nist.sp.800-73-4.pdf "3.2.1 X.509 Certificate for Digital Signature" "In other words, the PIN or OCC data must be submitted and verified every time immediately before a digital signature key operation. This ensures cardholder participation every time the private key is used for digital signature generation.5" The digital sign operation is done in C_Sign or C_SignFinal

May also be related to your: p11-glue/p11-kit#501

@mouse07410
Copy link
Author

mouse07410 commented May 7, 2023

@mouse07410 can you run your tests using the Auth key( id=%01) rather then the Sign key (id=%02)

Same thing:

openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%01;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
4083FE52F87F0000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$ 

This will eliminate the following problem in testing with p11-kit:

The provider does not check private key for CKA_ALWAYS_AUTHERNTICATE and does not then ask user for PIN again to do C_Login with CKU_CONTEXT_SPECIFIC i.e. acting like FireFox used too. (Caching the pin provider is not good enough unless C_Login with CKU_CONTEXT_SPECIFIC is used.)

I'm pretty sure it does not apply here. Also, for OpenSC I have use_pin_caching = true and pin_cache_ignore_user_consent. Because I find it rather stupid having to authenticate twice to the same token for the same operation.

"In other words, the PIN or OCC data must be submitted and verified every time immediately before a digital signature key operation. . ."

If nothing is done to the token between C_Login and C_SignInit+C_Sign, this is unnecessary, as the token maintains its "authenticated" status.

Also, it looks like after completing the signature and upon closing , provider gets into infinite loop on p11prov_CloseSession (ignoring pkcs11-module-quirks = no-deinit!), which causes seg-fault:

Exception Type:        EXC_BAD_ACCESS (SIGSEGV)
Exception Codes:       KERN_INVALID_ADDRESS at 0x0000000000000000
Exception Codes:       0x0000000000000001, 0x0000000000000000

Termination Reason:    Namespace SIGNAL, Code 11 Segmentation fault: 11
Terminating Process:   exc handler [68031]

VM Region Info: 0 is not in any region.  Bytes before following region: 4401274880
      REGION TYPE                    START - END         [ VSIZE] PRT/MAX SHRMOD  REGION DETAIL
      UNUSED SPACE AT START
--->  
      __TEXT                      106562000-1065fa000    [  608K] r-x/r-x SM=COW  ...SER/*/openssl

Thread 0 Crashed::  Dispatch queue: com.apple.main-thread
0   ???                           	               0x0 ???
1   libp11-kit.0.dylib            	       0x106a6b585 binding_C_CloseSession + 21
2   libffi.8.dylib                	       0x106761942 ffi_closure_unix64_inner + 545
3   libffi.8.dylib                	       0x106761f4c ffi_closure_unix64 + 72
4   pkcs11.dylib                  	       0x1067232e5 p11prov_CloseSession + 101
5   pkcs11.dylib                  	       0x1067232e5 p11prov_CloseSession + 101
6   pkcs11.dylib                  	       0x1067232e5 p11prov_CloseSession + 101
.  .  .
508 pkcs11.dylib                  	       0x1067232e5 p11prov_CloseSession + 101
509 pkcs11.dylib                  	       0x1067232e5 p11prov_CloseSession + 101
510 pkcs11.dylib                  	       0x1067232e5 p11prov_CloseSession + 101
511 pkcs11.dylib                  	       0x1067232e5 p11prov_CloseSession + 101

I observe it with OpenSSL-3.2.0-dev (not with OpenSSL-3.1.0) and master p11-kit.

@mouse07410
Copy link
Author

Using OpenSSL-3.2.0-dev and building with Macports-installed clang-16:


Crash report:

Exception Type:        EXC_BAD_ACCESS (SIGSEGV)
Exception Codes:       KERN_INVALID_ADDRESS at 0x0000000000000000
Exception Codes:       0x0000000000000001, 0x0000000000000000

Termination Reason:    Namespace SIGNAL, Code 11 Segmentation fault: 11
Terminating Process:   exc handler [88724]

VM Region Info: 0 is not in any region.  Bytes before following region: 4490051584
      REGION TYPE                    START - END         [ VSIZE] PRT/MAX SHRMOD  REGION DETAIL
      UNUSED SPACE AT START
--->  
      __TEXT                      10ba0c000-10baa4000    [  608K] r-x/r-x SM=COW  ...SER/*/openssl

Thread 0 Crashed::  Dispatch queue: com.apple.main-thread
0   ???                           	               0x0 ???
1   libp11-kit.0.dylib            	       0x10bf21f20 binding_C_CloseSession + 48
2   libffi.8.dylib                	       0x10bbbc942 ffi_closure_unix64_inner + 545
3   libffi.8.dylib                	       0x10bbbcf4c ffi_closure_unix64 + 72
4   pkcs11.dylib                  	       0x10bbd9c53 p11prov_CloseSession + 99 (interface.gen.c:235)
5   pkcs11.dylib                  	       0x10bbd9c53 p11prov_CloseSession + 99 (interface.gen.c:235)
6   pkcs11.dylib                  	       0x10bbd9c53 p11prov_CloseSession + 99 (interface.gen.c:235)
.  .  .
509 pkcs11.dylib                  	       0x10bbd9c53 p11prov_CloseSession + 99 (interface.gen.c:235)
510 pkcs11.dylib                  	       0x10bbd9c53 p11prov_CloseSession + 99 (interface.gen.c:235)
511 pkcs11.dylib                  	       0x10bbd9c53 p11prov_CloseSession + 99 (interface.gen.c:235)

@dengert
Copy link
Contributor

dengert commented May 7, 2023

I'm pretty sure it does not apply here. Also, for OpenSC I have use_pin_caching = true and pin_cache_ignore_user_consent. Because I find it rather stupid having to authenticate twice to the same token for the same operation.

Good to hear you are avoiding the problem. I test with use_pin_caching = false and without pin_cache_ignore_user_consent so as to follow the NIST specs and allow for using a PIN PAD reader. And I get failure because provider does not support CKA_ALWAYS_AUTHENTICATE.

@dengert
Copy link
Contributor

dengert commented May 7, 2023

The one other debugging tool we have not used is to run PCSCD (or what ever MacOS uses) in debug mode.
On unix one could do sudo /usr/sbin/pcscd -f -a --debug | tee /tmp/pcscd.log This will then show all the APDUs issued and responses.

Looks like provider or p11kit is sending C_Login to both cards found. (Has this been fixed?)

The log on Ubuntu 22.04 with provider seams to show both OpenSC and ykcs11 are quering login state to both cards as expected.
But then within 3 lies of log, verify wit pin is sent to both cards! (In may case with two test card they both have the same PIN.)

  (OpenSC   driver is client 13)
00000016 APDU: 00 CB 3F FF 03 5C 01 7E 00 
  (Checking using discovery object if PIV applet is selected. )
00000016 ifdhandler.c:1368:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/005 (lun: 0)
00001424 SW: 7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F 2F 02 40 00 90 00  
  (It is as PIV AID is retuned)
00000000 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000000 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 13
00001008 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 13
00000063 readerfactory.c:870:RFReaderInfoById() RefReader() count was: 1
00000016 winscard.c:1593:SCardTransmit() Send Protocol: T=1
00000015 APDU: 00 20 00 80 08 31 32 33 34 35 36 FF FF 
 (verify PIN)
00000015 ifdhandler.c:1368:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/005 (lun: 0)
00008891 SW: 90 00 
00000058 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000016 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 13
00000290 winscard_svc.c:361:ContextThread() Received command: END_TRANSACTION from client 13
00000061 readerfactory.c:870:RFReaderInfoById() RefReader() count was: 1
00000015 winscard.c:1232:SCardEndTransaction() Status: 0x00000000
00000014 winscard.c:1235:SCardEndTransaction() UnrefReader() count was: 2
00000015 winscard_svc.c:587:ContextThread() END_TRANSACTION rv=0x0 for client 13
 (end of current transaction i.e. lock on card)
00004351 winscard_svc.c:361:ContextThread() Received command: BEGIN_TRANSACTION from client 13
 (Starting new transaction)
00000042 readerfactory.c:870:RFReaderInfoById() RefReader() count was: 1
00000010 winscard.c:1080:SCardBeginTransaction() Status: 0x00000000
00000009 winscard.c:1083:SCardBeginTransaction() UnrefReader() count was: 2
00000009 winscard_svc.c:571:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 13
00000245 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 13
00000041 readerfactory.c:870:RFReaderInfoById() RefReader() count was: 1
00000010 winscard.c:1593:SCardTransmit() Send Protocol: T=1
00000009 APDU: 00 CB 3F FF 03 5C 01 7E 00
 (Checking if PIV is active applet since some other card driver could have interfered but note it is using a different USB!!) 
00000010 ifdhandler.c:1368:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/006 (lun: 10000)
00001314 SW: 7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F 2F 02 40 00 90 00 
 (PIV is active)
00000038 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000009 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 13
00000355 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 13
00000042 readerfactory.c:870:RFReaderInfoById() RefReader() count was: 1
00000010 winscard.c:1593:SCardTransmit() Send Protocol: T=1
00000009 APDU: 00 20 00 80 08 31 32 33 34 35 36 FF FF 
 (Sending PIN to the other card too!)
00000010 ifdhandler.c:1368:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/006 (lun: 10000)
00008863 SW: 90 00 
00000060 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000015 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 13
00000267 winscard_svc.c:361:ContextThread() Received command: END_TRANSACTION from client 13

opensc-debig.log shows it was called to twice to login in to both readers:

P:6524; T:0x139810064209728 15:41:27.896 [opensc-pkcs11] ../../../src/src/libopensc/reader-pcsc.c:325:pcsc_transmit: reader 'Yubico YubiKey OTP+FIDO+CCID 00 00'  
 (NOTE: 00 00)
7846 P:6524; T:0x139810064209728 15:41:27.896 [opensc-pkcs11] ../../../src/src/libopensc/reader-pcsc.c:326:pcsc_transmit: 
7847 Outgoing APDU (13 bytes):
7848 00 20 00 80 08 31 32 33 34 35 36 FF FF . ...123456..

P:6524; T:0x139810064209728 15:41:27.912 [opensc-pkcs11] ../../../src/src/libopensc/reader-pcsc.c:325:pcsc_transmit: reader 'Yubico YubiKey OTP+FIDO+CCID 01 00'
 (Note 01 00);
8120 P:6524; T:0x139810064209728 15:41:27.912 [opensc-pkcs11] ../../../src/src/libopensc/reader-pcsc.c:326:pcsc_transmit: 
8121 Outgoing APDU (13 bytes):
8122 00 20 00 80 08 31 32 33 34 35 36 FF FF . ...123456..

So something is wrong most likely provider it is calling C_Login for both cards it found.

But It only sent one signature operation as seen in pcscd log:

00000010 APDU: 00 CB 3F FF 03 5C 01 7E 00  (Checking id PIV is still active applet)
00000010 ifdhandler.c:1368:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/005 (lun: 0)
(using usb/001/005 (lun: 0)
00001090 SW: 7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F 2F 02 40 00 90 00 
(PIV is still active)
00000037 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000011 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 13
00000656 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 13
00000047 readerfactory.c:870:RFReaderInfoById() RefReader() count was: 1
00000010 winscard.c:1593:SCardTransmit() Send Protocol: T=1
00000018 APDU: 10 87 07 9A FF 7C 82 01 06 82 00 81 82 01 00 76 69 D5 28 05 28 C2 BA E2 FA 4E C8 AC 4C AE 0F C2 7D A2 1B 9B 32 EE 84 BF D5 B4 A9 5F 00 06 CE 7C D1 DD FE C6 C6 27 CA 2C 63 1E 5D 86 2E C3 9B 8C F9 29 22 26 99 DA 1E FE 66 84 2D 61 F4 21 73 EC ED 63 5E AA 2F A8 35 81 7C 3E D3 6F 01 75 C2 B6 1F DE 3C 2A EE 67 62 2C 5C DB D2 93 B5 82 CB EA 9C CF 87 60 74 2B 5B 97 90 65 15 CB 6C 07 C2 AB 20 01 2B 09 9A 95 E1 B3 CA FA CE C8 BE BE A7 FB 95 3F BA 59 97 3F 01 39 28 6D 7A 6F 3E 57 91 F5 6D 3E C1 5B B9 08 19 7E A5 CC 90 35 9E E9 50 F1 B9 AD 6E 90 48 15 A3 C9 57 B1 19 3F F2 BB 88 E2 DB C4 78 1A DD D4 83 6B 7B 5C CD B4 7D 9D 7F B0 F4 7C 29 74 92 1F 1F AF 2B ED 3A 9B 41 0C 11 5D 96 8F A8 D5 81 97 98 FB 8D 6B F1 E9 DF 03 AF C4 67 A3 FA 47 EF 49 D7 7B A8 66 03 C3 E4 AD FB B7 9B 36 7C 70 
(Above is first 255 bytes of signature datas)
00000010 ifdhandler.c:1368:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/005 (lun: 0)
00001652 SW: 90 00 

00000011 APDU: 00 87 07 9A 0B CB 2D 39 17 23 B0 B5 81 B6 AA BC 00 
 (Rest of signature data)
00000009 ifdhandler.c:1368:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/005 (lun: 0)
00135287 SW: 7C 82 01 04 82 82 01 00 3D 5E DD 0B 1F 4B 2A 47 65 2A 04 CF 77 0F F4 4D 00 98 DE 78 C6 84 A2 3D 46 EC 5C BB 5C 9B 6E A9 C5 86 22 F9 3B 24 B7 57 91 20 83 0B 80 08 80 A5 CA 60 BC 52 D7 0B B1 DA FB 58 25 64 AC B1 41 FF 8E 73 C6 49 6F 01 F4 41 91 5F 31 F6 88 81 88 FD 11 8B 4F 99 94 56 F1 46 E4 7F 29 EB 13 08 CC 8D E1 61 9F 
(First part of signature, with 9F more bytes to come)  
00000201 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000044 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 13
00000873 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 13
00000193 readerfactory.c:870:RFReaderInfoById() RefReader() count was: 1
00000042 winscard.c:1593:SCardTransmit() Send Protocol: T=1
00000041 APDU: 00 C0 00 00 9F 
00000043 ifdhandler.c:1368:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/005 (lun: 0)
00004919 SW: AC AE AB 8F 66 19 34 7F E2 95 89 9F 38 0D 99 05 E4 56 C1 10 A9 DF 95 C4 D4 A7 F8 5B 27 02 2C 98 2E 78 64 D7 FC D9 E8 B4 B9 F8 81 85 4F 10 FA 53 ED 84 1A 24 AB 59 59 0D F0 47 E9 E7 5E 15 38 39 47 DA 5D 35 9B B0 C6 59 14 16 83 44 44 60 23 58 88 ED 03 F8 EF 8E C3 D6 25 7F 87 7E 3E 02 28 4E 8C F7 95 64 BF BE F7 1B 2F E8 0F EF 7D 41 E8 C2 4D BC 5B AE 18 44 31 96 72 F4 BF 6D 0B 84 D1 9E E8 81 B9 05 8F E0 69 D0 14 90 A7 33 A4 AD 10 C0 A7 C6 90 8E BC 18 3D D7 04 7A CB 3F DA 65 B7 90 00 
(The  9F bytes and SW 90 00 as OK

@dengert
Copy link
Contributor

dengert commented May 8, 2023

CPPFLAGS=-DDEBUG
LDFLAGS=-g
CFLAGS=-g

@simo5
Copy link
Member

simo5 commented May 8, 2023

pkcs1-module-quirks = no-deinit,no-allowed-mechanisms

only space separated syntax is allowed

@mouse07410
Copy link
Author

mouse07410 commented May 8, 2023

OK, current state:

  • without HSM module present, it seems to work;
  • with HSM module present, only OpenSSL-3.2.0-dev seems to work, but it crashes the app after the signature is completed.

Without HSM module:

$ openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
$ openssl dgst -verify "pkcs11:model=YubiKey%20YK4;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -signature /tmp/pt.txt.sig /tmp/pt.txt 
Verified OK
$

With HSM module:

$ openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
4083FE52F87F0000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$ ll /tmp/pt.txt*
-rw-r--r--  1 ur20980  wheel  159 May  7 22:26 /tmp/pt.txt
-rw-r--r--  1 ur20980  wheel    0 May  8 09:29 /tmp/pt.txt.sig
$ openssl3 dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
Segmentation fault: 11
$ openssl dgst -verify "pkcs11:model=YubiKey%20YK4;id=%02;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -signature /tmp/pt.txt.sig /tmp/pt.txt 
Verified OK
$ 

Seg-fault above is infinite loop tha provider gets into on p11prov_CloseSession. I don't know what to do with/about it.

$ openssl version
OpenSSL 3.1.0 14 Mar 2023 (Library: OpenSSL 3.1.0 14 Mar 2023)
$ openssl3 version
OpenSSL 3.2.0-dev  (Library: OpenSSL 3.2.0-dev )
$ 

@dengert
Copy link
Contributor

dengert commented May 8, 2023

Sounds like progress. Is this the HSM module you are using: https://github.com/Yubico/yubihsm-shell/blob/master/pkcs11/README.adoc

It says is has debug options:
debug
libdebug
dinout

What do they show?

@mouse07410
Copy link
Author

With all of those (debug, libdebug. dinout) turned on:

$ openssl3 dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
[P11 - INF 15:40:19.834154] yubihsm_pkcs11.c:266 (C_Initialize): Found 1 configured connector(s)
[LIB - INF 15:40:19.834761] yubihsm.c:4430 (yh_init_connector): Loading http backend
[LIB - INF 15:40:19.849313] yubihsm_curl.c:87 (backend_create): backend_create
[LIB - INF 15:40:19.851164] yubihsm_curl.c:253 (backend_option): Successfully set CURLOPT_CAINFO.
[LIB - INF 15:40:19.851174] yubihsm_curl.c:92 (backend_connect): backend_connect
[LIB - INF 15:40:19.851180] yubihsm_curl.c:99 (backend_connect): Trying to connect to https://xxxxxxxxx.mit.edu:yyyyy/connector/status
[LIB - ERR 15:40:19.974685] lib_util.c:94 (parse_status_data): Unable to parse version string
[LIB - INF 15:40:19.974700] lib_util.c:139 (parse_status_data): response from connector
[LIB - INF 15:40:19.974705] lib_util.c:140 (parse_status_data): has device: yes
[LIB - INF 15:40:19.974710] lib_util.c:142 (parse_status_data): version: 0.0.0
[LIB - INF 15:40:19.974715] lib_util.c:143 (parse_status_data): pid: 2434
[LIB - INF 15:40:19.974719] lib_util.c:144 (parse_status_data): address: 0.0.0.0
[LIB - INF 15:40:19.974724] lib_util.c:145 (parse_status_data): port: yyyyy
[LIB - INF 15:40:19.974729] yubihsm_curl.c:144 (backend_connect): Found working connector
[P11 - INF 15:40:19.975279] yubihsm_pkcs11.c:362 (C_Initialize): Found 1 usable connector(s)
[P11 - INF 15:40:19.975291] yubihsm_pkcs11.c:365 (C_Initialize): Found 0 configured device public key(s)
[P11 - INF 15:40:19.975296] yubihsm_pkcs11.c:369 (C_Initialize): Out
[P11 - INF 15:40:19.977100] yubihsm_pkcs11.c:491 (C_GetSlotList): In
[P11 - INF 15:40:19.977115] yubihsm_pkcs11.c:520 (C_GetSlotList): Total number of slots is 1
[P11 - INF 15:40:19.977120] yubihsm_pkcs11.c:523 (C_GetSlotList): Can return 1 slot(s)
[P11 - INF 15:40:19.977125] yubihsm_pkcs11.c:527 (C_GetSlotList): Out
[P11 - INF 15:40:19.977129] yubihsm_pkcs11.c:491 (C_GetSlotList): In
[P11 - INF 15:40:19.977134] yubihsm_pkcs11.c:548 (C_GetSlotList): Returning slot 0
[P11 - INF 15:40:19.977138] yubihsm_pkcs11.c:565 (C_GetSlotList): Out
[P11 - INF 15:40:19.988875] yubihsm_pkcs11.c:491 (C_GetSlotList): In
[P11 - INF 15:40:19.988886] yubihsm_pkcs11.c:520 (C_GetSlotList): Total number of slots is 1
[P11 - INF 15:40:19.988892] yubihsm_pkcs11.c:523 (C_GetSlotList): Can return 1 slot(s)
[P11 - INF 15:40:19.988897] yubihsm_pkcs11.c:527 (C_GetSlotList): Out
[P11 - INF 15:40:19.988901] yubihsm_pkcs11.c:491 (C_GetSlotList): In
[P11 - INF 15:40:19.988906] yubihsm_pkcs11.c:548 (C_GetSlotList): Returning slot 0
[P11 - INF 15:40:19.988911] yubihsm_pkcs11.c:565 (C_GetSlotList): Out
[P11 - INF 15:40:19.991595] yubihsm_pkcs11.c:491 (C_GetSlotList): In
[P11 - INF 15:40:19.991606] yubihsm_pkcs11.c:520 (C_GetSlotList): Total number of slots is 1
[P11 - INF 15:40:19.991612] yubihsm_pkcs11.c:523 (C_GetSlotList): Can return 1 slot(s)
[P11 - INF 15:40:19.991616] yubihsm_pkcs11.c:527 (C_GetSlotList): Out
[P11 - INF 15:40:19.991621] yubihsm_pkcs11.c:491 (C_GetSlotList): In
[P11 - INF 15:40:19.991625] yubihsm_pkcs11.c:548 (C_GetSlotList): Returning slot 0
[P11 - INF 15:40:19.991630] yubihsm_pkcs11.c:565 (C_GetSlotList): Out
[P11 - INF 15:40:19.999031] yubihsm_pkcs11.c:572 (C_GetSlotInfo): In
[P11 - INF 15:40:19.999132] yubihsm_pkcs11.c:623 (C_GetSlotInfo): Out
[P11 - INF 15:40:19.999476] yubihsm_pkcs11.c:630 (C_GetTokenInfo): In
[LIB - NET 15:40:19.999586] yubihsm.c:289 (send_msg):  SEND >> (03 + 0000) 06 0000 
[LIB - NET 15:40:20.020867] yubihsm.c:296 (send_msg):  RECV << (03 + 0056) 86 0038 0200xxxxxxxxxxxx xxxxxxxxx xxxxxxxxx2b2c2d2e2f 
[P11 - INF 15:40:20.020951] yubihsm_pkcs11.c:723 (C_GetTokenInfo): Out
[P11 - INF 15:40:20.021184] yubihsm_pkcs11.c:861 (C_OpenSession): In
[P11 - INF 15:40:20.021209] yubihsm_pkcs11.c:906 (C_OpenSession): Allocated session 1
[P11 - INF 15:40:20.021215] yubihsm_pkcs11.c:908 (C_OpenSession): Out
[P11 - INF 15:40:20.021333] yubihsm_pkcs11.c:2283 (C_FindObjectsInit): In
[P11 - INF 15:40:20.021343] yubihsm_pkcs11.c:2321 (C_FindObjectsInit): Out
[P11 - INF 15:40:20.021425] yubihsm_pkcs11.c:2664 (C_FindObjects): In
[P11 - INF 15:40:20.021435] yubihsm_pkcs11.c:2688 (C_FindObjects): Can return 5 object(s)
[P11 - INF 15:40:20.021439] yubihsm_pkcs11.c:2735 (C_FindObjects): Returning 0 object(s)
[P11 - INF 15:40:20.021444] yubihsm_pkcs11.c:2737 (C_FindObjects): Out
[P11 - INF 15:40:20.021449] yubihsm_pkcs11.c:2748 (C_FindObjectsFinal): In
[P11 - INF 15:40:20.021454] yubihsm_pkcs11.c:2772 (C_FindObjectsFinal): Out
[P11 - INF 15:40:20.021461] yubihsm_pkcs11.c:919 (C_CloseSession): In
[P11 - ERR 15:40:20.021465] util_pkcs11.c:3805 (get_session): Session user not logged in
[P11 - INF 15:40:20.021472] yubihsm_pkcs11.c:962 (C_CloseSession): Closing session 1
[P11 - INF 15:40:20.021477] yubihsm_pkcs11.c:964 (C_CloseSession): Out
[P11 - INF 15:40:20.021483] yubihsm_pkcs11.c:749 (C_GetMechanismList): In
[LIB - NET 15:40:20.021490] yubihsm.c:289 (send_msg):  SEND >> (03 + 0000) 06 0000 
[LIB - NET 15:40:20.044335] yubihsm.c:296 (send_msg):  RECV << (03 + 0056) 86 0038 0xxxxxxxxxxxxxxxxxxxx 28292a2b2c2d2e2f 
[P11 - INF 15:40:20.044628] yubihsm_pkcs11.c:773 (C_GetMechanismList): Found 29 mechanisms
[P11 - INF 15:40:20.044639] yubihsm_pkcs11.c:775 (C_GetMechanismList): Out
[P11 - INF 15:40:20.044650] yubihsm_pkcs11.c:749 (C_GetMechanismList): In
[P11 - INF 15:40:20.044656] yubihsm_pkcs11.c:773 (C_GetMechanismList): Found 29 mechanisms
[P11 - INF 15:40:20.044661] yubihsm_pkcs11.c:775 (C_GetMechanismList): Out
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
Segmentation fault: 11
$ 

At this point, signature was correctly computed and stored, openssl3 process crashed because of infinite loop in the pkcs11-provider.

Crash report did not show up in console.app, for some reason. But this is the "standard":

Thread 0 Crashed::  Dispatch queue: com.apple.main-thread
0   ???                           	               0x0 ???
1   libp11-kit.0.dylib            	       0x107276f70 binding_C_CloseSession + 48
2   libffi.8.dylib                	       0x106f11942 ffi_closure_unix64_inner + 545
3   libffi.8.dylib                	       0x106f11f4c ffi_closure_unix64 + 72
4   pkcs11.dylib                  	       0x106f42220 p11prov_CloseSession + 288 (interface.gen.c:235)
5   pkcs11.dylib                  	       0x106f42220 p11prov_CloseSession + 288 (interface.gen.c:235)
.  .  .
510 pkcs11.dylib                  	       0x106f42220 p11prov_CloseSession + 288 (interface.gen.c:235)
511 pkcs11.dylib                  	       0x106f42220 p11prov_CloseSession + 288 (interface.gen.c:235)

With OpenSSL-3.1.0 - similar output from HSM debug trace, but signature failed:

$ openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
[P11 - INF 15:46:05.398383] yubihsm_pkcs11.c:266 (C_Initialize): Found 1 configured connector(s)
[LIB - INF 15:46:05.399089] yubihsm.c:4430 (yh_init_connector): Loading http backend
[LIB - INF 15:46:05.406389] yubihsm_curl.c:87 (backend_create): backend_create
[LIB - INF 15:46:05.406417] yubihsm_curl.c:253 (backend_option): Successfully set CURLOPT_CAINFO.
[LIB - INF 15:46:05.406423] yubihsm_curl.c:92 (backend_connect): backend_connect
[LIB - INF 15:46:05.406428] yubihsm_curl.c:99 (backend_connect): Trying to connect to https://xxxxxxxxxxxxxx.mit.edu:yyyyy/connector/status
[LIB - ERR 15:46:05.632883] lib_util.c:94 (parse_status_data): Unable to parse version string
[LIB - INF 15:46:05.632900] lib_util.c:139 (parse_status_data): response from connector
[LIB - INF 15:46:05.632905] lib_util.c:140 (parse_status_data): has device: yes
[LIB - INF 15:46:05.632910] lib_util.c:142 (parse_status_data): version: 0.0.0
.  .  .
[P11 - ERR 15:46:05.794664] util_pkcs11.c:3805 (get_session): Session user not logged in
[P11 - INF 15:46:05.794671] yubihsm_pkcs11.c:962 (C_CloseSession): Closing session 1
[P11 - INF 15:46:05.794677] yubihsm_pkcs11.c:964 (C_CloseSession): Out
[P11 - INF 15:46:05.794683] yubihsm_pkcs11.c:749 (C_GetMechanismList): In
[LIB - NET 15:46:05.794692] yubihsm.c:289 (send_msg):  SEND >> (03 + 0000) 06 0000 
[LIB - NET 15:46:05.816814] yubihsm.c:296 (send_msg):  RECV << (03 + 0056) 86 0038 020xxxxxxxx xxxxxxx xxxxxxxx2b2c2d2e2f 
[P11 - INF 15:46:05.817199] yubihsm_pkcs11.c:773 (C_GetMechanismList): Found 29 mechanisms
[P11 - INF 15:46:05.817213] yubihsm_pkcs11.c:775 (C_GetMechanismList): Out
[P11 - INF 15:46:05.817224] yubihsm_pkcs11.c:749 (C_GetMechanismList): In
[P11 - INF 15:46:05.817231] yubihsm_pkcs11.c:773 (C_GetMechanismList): Found 29 mechanisms
[P11 - INF 15:46:05.817236] yubihsm_pkcs11.c:775 (C_GetMechanismList): Out
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
Error setting context
4083FE52F87F0000:error:03000096:digital envelope routines:do_sigver_init:operation not supported for this keytype:crypto/evp/m_sigver.c:298:
$ 

And, of course, removing HSM module, makes signature succeed:

$ openssl dgst -sign "pkcs11:manufacturer=piv_II;id=%02;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:digest -out /tmp/pt.txt.sig /tmp/pt.txt 
Enter pass phrase for PKCS#11 Token (Slot 18 - Yubico YubiKey OTP+FIDO+CCID):
$ 

@dengert
Copy link
Contributor

dengert commented May 8, 2023

You might want to open an issue on https://github.com/Yubico/yubihsm-shell It looks like yubihsm_pkcs11.c is only called at the start and the failure appears to be when terminating and so logs are not flushed in the crash.

I see ffi_closure_unix64 is this on a X86_64 machine?

@mouse07410
Copy link
Author

mouse07410 commented May 8, 2023

You might want to open an issue on https://github.com/Yubico/yubihsm-shell It looks like yubihsm_pkcs11.c is only called at the start and the failure appears to be when terminating and so logs are not flushed in the crash.

When there is no crash but just failure to sign (OpenSSL-3.1.0) the logs also either not flushed or there's no more traffic to that device...

I see ffi_closure_unix64 is this on a X86_64 machine?

Yes.

Update

It looks like when there's more than one argument to pkcs11-module-quirks = in openssl.cnf, the first one (no-deinit) is being missed or ignored. That, in turn, causes this infinite loop <I don't know where>, because stack probably got too corrupted to actually determine the trace.

@simo5
Copy link
Member

simo5 commented Apr 2, 2024

This one has run out of steam and seem multiple issues were mixed.
I am going to close it, please open a new targeted issue if there is any remaining problem in current main.

@simo5 simo5 closed this as completed Apr 2, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants