"The specified key handle is not valid" error unless pkcs11-module-load-behavior = early

[a3f]

Describe the bug

qpid-proton uses client certificates/keys located in PEM files by default. When attempting to use a PKCS#11 URI for the private key instead, whether by encoding it into a PEM file or by patching Proton to use the PROVIDER API, the connect_config_test[^1] test in Proton fails, unless early loading is enabled. Other tests don't suffer from this issue.

The issue is similar to https://github.com/latchset/pkcs11-provider/issues/352 in that it disappears when pkcs11-module-load-behavior = early is set in the OpenSSL config.

To Reproduce

$ git clone --recursive https://github.com/a3f/pkcs11-provider-qpid-proton-bug-reproduction
$ cd pkcs11-provider-qpid-proton-bug-reproduction
$ make test
[...]
 Running test _with_ PKCS#11
===========================
TEST: test_default_file()
TEST: test_addr()
TEST: test_invalid_config()
TEST: test_invalid_json()
TEST: test_default_connect().run()
TEST: test_almost_default_connect().run()
TEST: test_tls().run()
TEST: test_tls_default_fail().run()
TEST: test_tls_external().run()
ERROR test_tls_external().run()
/ptx/work/user/afa/pkcs11-provider-qpid-proton-bug-reproduction/qpid-proton/cpp/src/connect_config_test.cpp:461: /ptx/work/user/afa/pkcs11-provider-qpid-proton-bug-reproduction/qpid-proton/cpp/src/connect_config_test.cpp:193: unexpected error amqp:connection:framing-error: SSL Failure: error:40800060:pkcs11::The specified key handle is not valid
===========================
FAILURE! Now try again with LOAD_BEHAVIOR=early
===========================

Expected behavior

The test should succeed like it does with early loading enabled:

$ LOAD_BEHAVIOR=early make test
[..]
Running test _with_ PKCS#11
===========================
TEST: test_default_file()
TEST: test_addr()
TEST: test_invalid_config()
TEST: test_invalid_json()
TEST: test_default_connect().run()
TEST: test_almost_default_connect().run()
TEST: test_tls().run()
TEST: test_tls_default_fail().run()
TEST: test_tls_external().run()
===========================
SUCCESS!
===========================

Operating environment:

• OS: Debian Bookworm

Token and application used:

• PKCS11 Driver version: SoftHSM 2.6.1, but also on ARM system with OP-TEE v4.0.0
• Application: qpid-proton 0.39.0

Additional Context:

A reproducer that builds both pkcs11-provider and qpid-proton and runs the test to trigger the issue is available at: https://github.com/a3f/pkcs11-provider-qpid-proton-bug-reproduction

[^1]: The test was modified to accept the certificate path or PKCS#11 URI via environment variable

[simo5]

Looks like a duplicate of #352 honestly, do you have any other data that would identify this as a different issue?

[a3f]

352 is supposed to be resolved by 81bedf428302cd9f95bd5c033a2543ecf8223045, which was first included in v0.4. My issue exists with 0.5 and master, so 81bedf428302cd9f95bd5c033a2543ecf8223045 doesn't seem sufficient as fix.

[simo5]

Could be related to issues we are investigating in #395 as well ..

[a3f]

I see no mention of the issue in #395 disappearing with early loading. You also seem to be not able to reproduce that other issue. Did you have the chance to try out the reproducer at https://github.com/a3f/pkcs11-provider-qpid-proton-bug-reproduction?

[simo5]

Sorry, vacation time robbed me of the bandwidth to follow-up on this.

[simo5]

qpid-proton seem to have huge dependencies, but even after installing everything ina rawhide container I get this when runnign make:

# make
git submodule update --init pkcs11-provider
meson setup build/pkcs11-provider pkcs11-provider
Directory already configured.

Just run your build command (e.g. ninja) and Meson will regenerate as necessary.
Run "meson setup --reconfigure to force Meson to regenerate.

If build failures persist, run "meson setup --wipe" to rebuild from scratch
using the same options as passed when configuring the build.
meson compile -C build/pkcs11-provider
INFO: autodetecting backend as ninja
INFO: calculating backend command to run: /usr/bin/ninja -C /devel/git/pkcs11-provider-qpid-proton-bug-reproduction/build/pkcs11-provider
ninja: Entering directory `/devel/git/pkcs11-provider-qpid-proton-bug-reproduction/build/pkcs11-provider'
ninja: no work to do.
DESTDIR=/devel/git/pkcs11-provider-qpid-proton-bug-reproduction/build/out meson install -C build/pkcs11-provider
ninja: Entering directory `/devel/git/pkcs11-provider-qpid-proton-bug-reproduction/build/pkcs11-provider'
ninja: no work to do.
Installing src/pkcs11.so to /devel/git/pkcs11-provider-qpid-proton-bug-reproduction/build/out/usr/lib64/ossl-modules
Installing /devel/git/pkcs11-provider-qpid-proton-bug-reproduction/pkcs11-provider/docs/provider-pkcs11.7 to /devel/git/pkcs11-provider-qpid-proton-bug-reproduction/build/out/usr/local/share/man/man7
git submodule update --init qpid-proton
Submodule path 'qpid-proton': checked out '0084354ba917f712ce293e06df5d300f9094d86e'
(cd qpid-proton; git am ../0001-HACK-PROTON-2594-cpp-connect_config_test-adapt-for-t.patch)
Applying: HACK: PROTON-2594: cpp: connect_config_test: adapt for testing PKCS#11 URIs
cmake -S qpid-proton -B build/qpid-proton -DCMAKE_INSTALL_PREFIX=/devel/git/pkcs11-provider-qpid-proton-bug-reproduction/build/out -DENABLE_WARNING_ERROR=OF
-- Build type is "RelWithDebInfo" (has debug symbols)
-- PN_VERSION: 0.40.0 (dev)
-- Building the epoll proactor
-- Found Doxygen: /usr/bin/doxygen (found version "1.12.0") found components: doxygen dot 
CMake Warning at c/tests/CMakeLists.txt:141 (message):
  No C++ compiler, some C library tests were not built

-- Configuring done (0.2s)
CMake Error at c/tests/fuzz/CMakeLists.txt:43 (add_executable):
  CMake doesn't support IPO for current compiler
Call Stack (most recent call first):
  c/tests/fuzz/CMakeLists.txt:74 (pn_add_fuzz_test)

CMake Error: Error required internal CMake variable not set, cmake may not be built correctly.
Missing variable is:
CMAKE_CXX_LINK_EXECUTABLE
CMake Error at c/tests/fuzz/CMakeLists.txt:43 (add_executable):
  CMake doesn't support IPO for current compiler
Call Stack (most recent call first):
  c/tests/fuzz/CMakeLists.txt:76 (pn_add_fuzz_test)

CMake Error: Error required internal CMake variable not set, cmake may not be built correctly.
Missing variable is:
CMAKE_CXX_LINK_EXECUTABLE
CMake Error at c/tests/fuzz/CMakeLists.txt:43 (add_executable):
  CMake doesn't support IPO for current compiler
Call Stack (most recent call first):
  c/tests/fuzz/CMakeLists.txt:80 (pn_add_fuzz_test)

CMake Error: Error required internal CMake variable not set, cmake may not be built correctly.
Missing variable is:
CMAKE_CXX_LINK_EXECUTABLE
CMake Error at c/tests/fuzz/CMakeLists.txt:43 (add_executable):
  CMake doesn't support IPO for current compiler
Call Stack (most recent call first):
  c/tests/fuzz/CMakeLists.txt:98 (pn_add_fuzz_test)

CMake Error: Error required internal CMake variable not set, cmake may not be built correctly.
Missing variable is:
CMAKE_CXX_LINK_EXECUTABLE
-- Generating done (0.0s)
CMake Generate step failed.  Build files cannot be regenerated correctly.
make: *** [Makefile:16: proton] Error 1

[simo5]

A smaller reproducer would be easier to deal with ...