search

latchset / pkcs11-provider

A pkcs#11 provider for OpenSSL 3.0+
Other
61 stars 39 forks source link

Fails HKDF test #387

Closed mouse07410 closed 2 months ago

mouse07410 commented 5 months ago

Describe the bug

=================================== 20/35 ====================================
test:         pkcs11-provider:softokn / hkdf
start time:   21:00:13
duration:     0.10s
result:       exit status 1
command:      TEST_PATH=/Users/ur20980/src/pkcs11-provider/tests ASAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1 TESTBLDDIR=/U
sers/ur20980/src/pkcs11-provider/build/tests UBSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 MALLOC_PERTUR
B_=96 /Users/ur20980/src/pkcs11-provider/tests/test-wrapper hkdf-softokn.t
----------------------------------- stdout -----------------------------------
Executing /Users/ur20980/src/pkcs11-provider/tests/thkdf

## HKDF Derivation
 openssl 
pkeyutl -derive -kdf HKDF -kdflen 48
                -pkeyopt md:SHA256
                -pkeyopt mode:EXTRACT_AND_EXPAND
                -pkeyopt hexkey:${HKDF_HEX_SECRET}
                -pkeyopt hexsalt:${HKDF_HEX_SALT}
                -pkeyopt hexinfo:${HKDF_HEX_INFO}
                -out ${TMPPDIR}/hkdf1-out-pkcs11.bin
                -propquery provider=pkcs11
----------------------------------- stderr -----------------------------------
pkeyutl: Error initializing context
00B1D253F87F0000:error:03000086:digital envelope routines:EVP_PKEY_derive_init_ex:initialization error:crypto/evp/exchange.c:338:
==============================================================================

To Reproduce Steps to reproduce the behavior:

Clone, configure, build, and run the tests. Observe the output.

Expected behavior All tests passed.

Operating environment (please complete the following information):

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

Additional context

simo5 commented 5 months ago

Please provide pkcs11 provider debug log.

mouse07410 commented 5 months ago

Correction to the above: OpenSSL-3.4.0-dev.

ninja: Entering directory `/Users/ur20980/src/pkcs11-provider/build'
ninja: no work to do.
 1/35 pkcs11-provider:softokn / setup_softokn OK              1.74s
 2/35 pkcs11-provider:softhsm / setup_softhsm OK              0.95s
 3/35 pkcs11-provider:softokn / basic         OK              3.91s
 4/35 pkcs11-provider:softhsm / basic         OK              4.01s
 5/35 pkcs11-provider:softokn / pubkey        OK              0.22s
 6/35 pkcs11-provider:softhsm / pubkey        OK              0.26s
 7/35 pkcs11-provider:softokn / certs         OK              0.20s
 8/35 pkcs11-provider:softhsm / certs         OK              0.21s
 9/35 pkcs11-provider:softokn / ecc           OK              0.70s
10/35 pkcs11-provider:softhsm / ecc           OK              0.51s
11/35 pkcs11-provider:softhsm / edwards       OK              0.37s
12/35 pkcs11-provider:softokn / ecdh          OK              0.08s
13/35 pkcs11-provider:softokn / democa        OK              2.17s
14/35 pkcs11-provider:softhsm / democa        OK              0.99s
15/35 pkcs11-provider:softokn / digest        OK              0.04s
16/35 pkcs11-provider:softhsm / digest        FAIL            0.05s   (exit status 139 or signal 11 SIGSEGV)
>>> TESTBLDDIR=/Users/ur20980/src/pkcs11-provider/build/tests UBSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 MALLOC_PERTURB_=51 TEST_PATH=/Users/ur20980/src/pkcs11-provider/tests ASAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1 /Users/ur20980/src/pkcs11-provider/tests/test-wrapper digest-softhsm.t

17/35 pkcs11-provider:softokn / fork          OK              0.46s
18/35 pkcs11-provider:softhsm / fork          OK              1.11s
19/35 pkcs11-provider:softokn / oaepsha2      OK              0.24s
20/35 pkcs11-provider:softokn / hkdf          FAIL            0.04s   exit status 1
>>> TESTBLDDIR=/Users/ur20980/src/pkcs11-provider/build/tests UBSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 MALLOC_PERTURB_=207 TEST_PATH=/Users/ur20980/src/pkcs11-provider/tests ASAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1 /Users/ur20980/src/pkcs11-provider/tests/test-wrapper hkdf-softokn.t

21/35 pkcs11-provider:softokn / rsapss        OK              0.27s
22/35 pkcs11-provider:softokn / genkey        OK              0.02s
23/35 pkcs11-provider:softhsm / genkey        OK              0.02s
24/35 pkcs11-provider:softokn / session       OK              0.30s
25/35 pkcs11-provider:softhsm / session       OK              0.08s
26/35 pkcs11-provider:softokn / rand          OK              0.06s
27/35 pkcs11-provider:softhsm / rand          OK              0.06s
28/35 pkcs11-provider:softokn / readkeys      OK              0.05s
29/35 pkcs11-provider:softhsm / readkeys      OK              0.04s
30/35 pkcs11-provider:softokn / tls           OK              0.32s
31/35 pkcs11-provider:softhsm / tls           OK              0.17s
32/35 pkcs11-provider:softokn / uri           OK              2.32s
33/35 pkcs11-provider:softhsm / uri           OK              0.96s
34/35 pkcs11-provider:softhsm / ecxc          OK              0.52s
35/35 pkcs11-provider:softokn / cms           OK              0.11s

Ok:                 33  
Expected Fail:      0   
Fail:               2   
Unexpected Pass:    0   
Skipped:            0   
Timeout:            0   

Full log written to /Users/ur20980/src/pkcs11-provider/build/meson-logs/testlog.txt

Is this what you're looking for? If not - what flags and/or env vars would you like me to set, and what exact command to run? testlog.txt

P.S. I'm not sure it's invoking the correct OpenSSL binary.

simo5 commented 5 months ago

Please provide /Users/ur20980/src/pkcs11-provider/build/tests/tmp.softokn/p11prov-debug.log

mouse07410 commented 5 months ago

Please provide /Users/ur20980/src/pkcs11-provider/build/tests/tmp.softokn/p11prov-debug.log

p11prov-debug.log.zip

simo5 commented 5 months ago

Thanks for providing the debug log, sadly it doesn't really help understanding what is going on. I see hat the hkdf goes through 2 of the 3 initiatilization stages, and then w/o error being returned from the provider it gets freed and the operation is terminated.

I will have to check if 3.4 has introduced some requirement the provider does not meet somehow, but I can't tell what that is for now.

mouse07410 commented 4 months ago

Perhaps, this might help:

Process:               tdigests [39628]
Path:                  /Users/USER/*/tdigests
Identifier:            tdigests
Version:               ???
Code Type:             ARM-64 (Native)
Parent Process:        Exited process [39625]
Responsible:           Terminal [836]
User ID:               501

Date/Time:             2024-05-14 21:12:35.6240 -0400
OS Version:            macOS 14.5 (23F79)
Report Version:        12
Anonymous UUID:        161C054B-E964-CDD3-5EBC-5A9DBE3E2AE2

Time Awake Since Boot: 4100 seconds

System Integrity Protection: enabled

Crashed Thread:        0  Dispatch queue: com.apple.main-thread

Exception Type:        EXC_BAD_ACCESS (SIGSEGV)
Exception Codes:       KERN_INVALID_ADDRESS at 0x000088fa34f7aa80 -> 0x000008fa34f7aa80 (possible pointer authentication failure)
Exception Codes:       0x0000000000000001, 0x000088fa34f7aa80

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

VM Region Info: 0x8fa34f7aa80 is not in any region.  Bytes after previous region: 9389687155329  Bytes before following region: 95682392774016
      REGION TYPE                    START - END         [ VSIZE] PRT/MAX SHRMOD  REGION DETAIL
      commpage (reserved)        1000000000-7000000000   [384.0G] ---/--- SM=NUL  reserved VM address space (unallocated)
--->  GAP OF 0x5f9000000000 BYTES
      MALLOC_NANO              600000000000-600020000000 [512.0M] rw-/rwx SM=PRV  

Thread 0 Crashed::  Dispatch queue: com.apple.main-thread
0   libsofthsm2.so                         0x102c83ae4 MutexFactory::recycleMutex(Mutex*) + 4
1   libsofthsm2.so                         0x102c88fd8 OSSLCryptoFactory::~OSSLCryptoFactory() + 168
2   libsofthsm2.so                         0x102c89018 OSSLCryptoFactory::~OSSLCryptoFactory() + 12
3   libsofthsm2.so                         0x102c62f80 std::__1::unique_ptr<OSSLCryptoFactory, std::__1::default_delete<OSSLCryptoFactory>>::~unique_ptr[abi:v160006]() + 40
4   libsystem_c.dylib                      0x189ad82e8 __cxa_finalize_ranges + 476
5   libsystem_c.dylib                      0x189ad8070 exit + 44
6   tdigests                               0x102a8fdac main + 796 (tdigests.c:85)
7   dyld                                   0x1898920e0 start + 2360

Thread 0 crashed with ARM Thread State (64-bit):
    x0: 0x0000600003ec8000   x1: 0x000088fa34f7aa80   x2: 0x0000000000000001   x3: 0x000000016d371020
    x4: 0x0000600001ec8080   x5: 0x0000000000000000   x6: 0x0000600003ee08d0   x7: 0x0000000000053100
    x8: 0x00006000032caa80   x9: 0x00000000000003ff  x10: 0x0000000000002200  x11: 0x0000000087ee72a9
   x12: 0x00000000000007fb  x13: 0x00000000000007fd  x14: 0x00000000880e7a21  x15: 0x0000000000000221
   x16: 0x0000000087ee72a9  x17: 0x00000000000e7800  x18: 0x0000000000000000  x19: 0x0000600003ec8060
   x20: 0x0000000102cd8000  x21: 0x0000000102cd8000  x22: 0x0000000102ee0030  x23: 0x0000000000000000
   x24: 0x0000000000000008  x25: 0x00000001f1a5d000  x26: 0x0000000000000007  x27: 0x0000000000000006
   x28: 0x0000000000000006   fp: 0x000000016d371090   lr: 0x0000000102c88fd8
    sp: 0x000000016d371070   pc: 0x0000000102c83ae4 cpsr: 0x60001000
   far: 0x000088fa34f7aa80  esr: 0x92000004 (Data Abort) byte read Translation fault

Binary Images:
       0x103058000 -        0x10310ffff gost.3.0.dylib (*) <7e052f6c-53cd-3c3b-a0bf-a75a4973b9dc> /opt/local/libexec/*/gost.3.0.dylib
       0x102c50000 -        0x102ccffff libsofthsm2.so (*) <dcca3c48-da05-3082-a93e-f1c5114f5d58> /opt/local/lib/*/libsofthsm2.so
       0x1039a4000 -        0x103c77fff libcrypto.3.dylib (*) <b9bb142d-cd20-3cef-a42a-a118d15ea0a4> /opt/local/libexec/*/libcrypto.3.dylib
       0x102f3c000 -        0x10302bfff libsqlite3.0.dylib (*) <4ab801c5-4386-3395-9a2e-01f100c7c6b5> /opt/local/lib/libsqlite3.0.dylib
       0x102ad0000 -        0x102adffff libz.1.3.1.dylib (*) <8a6bd02f-4f63-30ae-a288-681ec3508c87> /opt/local/lib/libz.1.3.1.dylib
       0x102b10000 -        0x102b5ffff pkcs11.dylib (*) <3a5789ff-2925-3e73-baf9-c382e4b93d40> /Users/USER/*/pkcs11.dylib
       0x103440000 -        0x103797fff libcrypto.3.dylib (*) <43fb30db-ac8a-3582-bd21-03d7fb729d34> /Users/USER/*/libcrypto.3.dylib
       0x102a8c000 -        0x102a8ffff tdigests (*) <7ae1e1e8-59c6-3728-8c36-8db9ced72e72> /Users/USER/*/tdigests
       0x189ab1000 -        0x189b2fff7 libsystem_c.dylib (*) <05b44e93-dffc-3bd8-90ab-fd97cb73f171> /usr/lib/system/libsystem_c.dylib
       0x18988c000 -        0x189914a17 dyld (*) <37bbc384-0755-31c7-a808-0ed49e44dd8e> /usr/lib/dyld
               0x0 - 0xffffffffffffffff ??? (*) <00000000-0000-0000-0000-000000000000> ???
simo5 commented 4 months ago

Ok this is the usual bug of softhsm screwing up things on shutdown as its C++ bindings get finalized before pkcs11-provider asks it to finalize. This is not the issue you are seeing with openssl pkeyutil -derive though.

simo5 commented 2 months ago

No activity so closing, please open a new bug with the requested info if this is still an issue.