tests: Run more TLS tests when forcing all server operations on token

[Jakuje]

Description

This is rebase of previously closed PR #427, which adds also a test reproducer for #449.

This is trying to solve few issues:

• The standard error is not recorded in the log files, which makes them hard to use for debugging
• The expect script default does not catch eof, which makes some failures hidden
• One of these failures happens in the client, when the provider is forced to be used, but it dies on verification failure. This is TODO that needs to be fixed, but not the main issue we hunt here
• The error from reproducer from Passing CK_P11PROV_IMPORTED_HANDLE while creating mock public key #449 was also being hidden because the server closed the connection.
• The TLS tests when the provider is forced to be used were executing only one basic use case. This again attempts to run all of them.

Checklist

• Test suite updated with functionality tests
• Test suite updated with negative tests

Reviewer's checklist:

• Any issues marked for closing are addressed
• There is a test suite reasonably covering new functionality or modifications
• This feature/change has adequate documentation added
• Code conform to coding style that today cannot yet be enforced via the check style test
• Commits have short titles and sensible commit messages
• Coverity Scan has run if needed (code PR) and no new defects were found

[Jakuje]

ugh. In the CI it passes now, but locally it failed for me previously. After proper clean it works for me too locally. Edited the description.

Edit: Obviously, I forgot to run make before make check. This confirms the proposed change solves the issue for me

[simo5]

Largely LGTM, some comments.

That said maybe remove the last commit so we can see that CI fails, then I will merge the original PR, and then you can rebase on main and we ensure everything still works.

[simo5]

I am not sure we want this, we want to be able to test forcing both server an client.
If we do this then we'd have to add a test matrix where we try all combinations of forcing server and client.

[Jakuje]

Probably yes. But it does not work without this, even the basic case fails now with:

########################################
## Forcing the provider for all server operations


## Run sanity test with default values (RSA)
spawn openssl s_client -connect localhost:23456 -CAfile /home/jjelen/devel/pkcs11-provider/builddir/tests/softokn/CAcert.pem
Connecting to ::1
CONNECTED(00000004)
Can't use SSL_get_servername
depth=1 CN=Issuer
verify return:1
depth=0 O=PKCS11 Provider, CN=My Test Cert
verify return:1
80D25E0D127F0000:error:40800070:pkcs11:p11prov_rsasig_set_ctx_params:An invalid mechanism was specified to the cryptographic operation:../src/signature.c:1532:CKM_RSA_PKCS_PSS unavailable
80D25E0D127F0000:error:0A080006:SSL routines:tls_process_cert_verify:EVP lib:ssl/statem/statem_lib.c:560:
---
Certificate chain
 0 s:O=PKCS11 Provider, CN=My Test Cert
   i:CN=Issuer
   a:PKEY: rsaEncryption, 2048 (bit); sigalg: RSA-SHA256
   v:NotBefore: Oct 21 07:58:11 2024 GMT; NotAfter: Oct 21 07:58:11 2025 GMT
---
Server certificate
-----BEGIN CERTIFICATE-----
MIIDPzCCAiegAwIBAgIBAzANBgkqhkiG9w0BAQsFADARMQ8wDQYDVQQDEwZJc3N1
ZXIwHhcNMjQxMDIxMDc1ODExWhcNMjUxMDIxMDc1ODExWjAxMRgwFgYDVQQKEw9Q
S0NTMTEgUHJvdmlkZXIxFTATBgNVBAMTDE15IFRlc3QgQ2VydDCCASIwDQYJKoZI
hvcNAQEBBQADggEPADCCAQoCggEBAMyqHVpQB9mfrimSiIdV34EU8FyVc+o1SIRq
jRsoo3F93VLhhaOpje1EQ3I0bDOKSr8fT+pjReHENkOycnbzw2eE6eAeaDlNYU51
MRNp0eZY0/K9WRZDppkc+i/Z9G5jj+wyZgNSUS2EmYvz9vTXcdG8cPLdyTBm2/U3
JIQDZPJ9UmavFa0Ojr2MiDDTY/dWxXPUIoMf4dQ/ppKa4e++XUteh9LvONqMY6RU
P9JhkbXGGmQiLyVVkD3pwSDZG7M3g3AdDl4BQhU5/v/G0ETHWbKmKnzpDCJ2FJah
VBWx0jZgbwNiGQ9j8shs12lEX5YMezDu/NCE3ZgaVORDwdtbpWUCAwEAAaOBgTB/
MAwGA1UdEwEB/wQCMAAwHwYDVR0RBBgwFoEUdGVzdGNlcnRAZXhhbXBsZS5vcmcw
DgYDVR0PAQH/BAQDAgWgMB0GA1UdDgQWBBSP4+rrZTwRXWi4OdqhdTseOJC2FTAf
BgNVHSMEGDAWgBRgYl8qthze3R6sKMpf02knjzgH9DANBgkqhkiG9w0BAQsFAAOC
AQEAA9qDTCeoOQox2oOkq/XlIek4XcCMjvCkiJdGmuPkDLit4sExalldkMPkds5W
n+BMAYObkPK7QmuZVXWtQYnMSm62N2ejNdSD+Dc/uUEp8KkznFhC6wsuScrjEwOh
oacfvKUS8BslUhRrTgDGQ9cvvI4gjHRzkQmNagmoR1vkbZGJGcQE9tte1WD+OtCZ
9t1uXr6q2hvb30jlsb/EUbfLYBEvC0sTyQ/n/ucmCcTg9GSBy/IcaiWYxng2grNl
Ox6zIE21D/5PUtD+nZsakdDZPuxAe/nfbys8yb5pPMGJ5mZQfUgdxvkO0+iGBtTP
pJrlJI/9/0yU94guAgco1Nwdbg==
-----END CERTIFICATE-----
subject=O=PKCS11 Provider, CN=My Test Cert
issuer=CN=Issuer
---
No client certificate CA names sent
Peer signing digest: SHA256
Peer signature type: RSA-PSS
Server Temp Key: X25519, 253 bits
---
SSL handshake has read 1317 bytes and written 321 bytes
Verification: OK
---
New, TLSv1.3, Cipher is TLS_AES_256_GCM_SHA384
Server public key is 2048 bit
This TLS version forbids renegotiation.
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
Verify return code: 0 (ok)
---
/home/jjelen/devel/pkcs11-provider/tests/ttls: line 28: wait: pid 380444 is not a child of this shell
Server output:
spawn openssl s_server -accept 23456 -naccept 1 -key pkcs11:type=private;id=%00%01 -cert pkcs11:type=cert;object=testCert
Using default temp DH parameters
ACCEPT
ERROR
80D23BA1F87F0000:error:40800091:pkcs11:p11prov_GetOperationState:There is no active operation of appropriate type in the specified session:../src/interface.gen.c:335:Error returned by C_GetOperationState
80D23BA1F87F0000:error:0A000438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error:ssl/record/rec_layer_s3.c:909:SSL alert number 80
shutting down SSL
CONNECTION CLOSED
   0 items in the session cache
   0 client connects (SSL_connect())
   0 client renegotiates (SSL_connect())
   0 client connects that finished
   1 server accepts (SSL_accept())
   0 server renegotiates (SSL_accept())
   0 server accepts that finished
   0 session cache hits
   0 session cache misses
   0 session cache timeouts
   0 callback cache hits
   0 cache full overflows (128 allowed)

I am not sure which of the failures is the problem, but I assume the mechanism issue? The debug log shows the following issues:

[../src/interface.gen.c:950] p11prov_VerifyFinal(): Calling C_VerifyFinal
[../src/objects.c:435] p11prov_obj_free(): Free Object: 0x555a26466fa0 (handle:1)
[../src/objects.c:442] p11prov_obj_free(): object free: reference held
[../src/objects.c:435] p11prov_obj_free(): Free Object: 0x555a26466fa0 (handle:1)
[../src/objects.c:442] p11prov_obj_free(): object free: reference held
[../src/keymgmt.c:713] p11prov_rsa_has(): rsa has 0x555a264a76d0 4
[../src/signature.c:1257] p11prov_rsasig_digest_verify_init(): rsa digest verify init (ctx=0x555a264b9ee0, key=0x555a264a76d0, params=(nil))
[../src/objects.c:404] p11prov_obj_ref_no_cache(): Ref Object: 0x555a264a76d0 (handle:18446744073709551614)
[../src/provider.c:607] p11prov_ctx_cache_keys(): cache_keys = 1
[../src/signature.c:1460] p11prov_rsasig_set_ctx_params(): rsasig set ctx params (ctx=0x555a264b9ee0, params=(nil))
[../src/signature.c:1460] p11prov_rsasig_set_ctx_params(): rsasig set ctx params (ctx=0x555a264b9ee0, params=0x7ffd3e343650)
[../src/signature.c:1494] p11prov_rsasig_set_ctx_params(): Set OSSL_SIGNATURE_PARAM_PAD_MODE to 6
[../src/signature.c:1532] p11prov_rsasig_set_ctx_params(): Error: 0x00000070; CKM_RSA_PKCS_PSS unavailable

This error condition has the following code comment:

pkcs11-provider/src/signature.c

Lines 1521 to 1525 in c7fb177

	/* some modules do not support PSS so we need to return
	* an error early if we try to select this. Unfortunately
	* although openssl has separate keymgmt for PKCS vs PSS
	* padding, it consider RSA always capable to be performed
	* regardless, and this is not the case in PKCS#11 */

[simo5]

The GetOperationState failure is suspicious, sounds like we are simply not raising on the correct error, and that's the only thing left on the stack.

So the problem here is that OpenSSL is trying to do RSA PSS, can we change the options to force ECDSA and see if that makes it work?

Also all three tokens should support PSS, is this failing with on or all of them ?

[Jakuje]

I did not try kryoptic, but the same test fails on both softhsm and softokn. If I switch to the second test (ecdsa), it fails with the test same way, but I do not see any obvious error except for the operation state error.

[Jakuje]

Pushed without the commit from #449 to demonstrate the failure.