Can not re-connect TLS when using PKCS #11

[dachrillz]

Version

v21.2.0 (However have tried with node 18,19,20)

Platform

Linux szabo 6.2.16-2-MANJARO #1 SMP PREEMPT_DYNAMIC Sun Jun 4 12:09:09 UTC 2023 x86_64 GNU/Linux

Subsystem

tls

What steps will reproduce the bug?

Background: I am using mqtt.js. I recently had flaky internet meaning that the client disconnected. I noticed that it fails to reconnect. Some debugging lead me to believe that the problem's entry point is somewhere in Node (but it has something to do with the interaction with the crypto engine)

All scripts are run as follows:

  "scripts": {
    "start": "PKCS11_MODULE_PATH='/usr/lib/libykcs11.so' node index.js"
  },

The most minimal example i managed to create of looks as follows

const tls = require("tls");

const config = {
  privateKeyIdentifier:
    "pkcs11:model=YubiKey%20YK5;manufacturer=Yubico%20%28www.yubico.com%29;serial=22484003;token=YubiKey%20PIV%20%2322484003;id=%04;object=Private%20key%20for%20Card%20Authentication;type=private;pin-value=123456",
  privateKeyEngine: "pkcs11",
};

tls.createSecureContext(config);
console.log("First time around ok!");
tls.createSecureContext(config);
console.log("We never get here");

This produces

npm start

> what@1.0.0 start
> PKCS11_MODULE_PATH='/usr/lib/libykcs11.so' node index.js

First time around ok!
node:internal/tls/secure-context:207
        context.setEngineKey(privateKeyIdentifier, privateKeyEngine);
                ^

Error: error:12800067:DSO support routines::could not load the shared library
    at configSecureContext (node:internal/tls/secure-context:207:17)
    at Object.createSecureContext (node:_tls_common:116:3)
    at Object.<anonymous> (/home/dachrillz/temp/minimal/index.js:11:5)
    at Module._compile (node:internal/modules/cjs/loader:1376:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1435:10)
    at Module.load (node:internal/modules/cjs/loader:1207:32)
    at Module._load (node:internal/modules/cjs/loader:1023:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:135:12)
    at node:internal/main/run_main_module:28:49 {
  opensslErrorStack: [
    'error:1300006D:engine routines::init failed',
    'error:13000074:engine routines::no such engine',
    'error:13000084:engine routines::dso not found',
    'error:12800067:DSO support routines::could not load the shared library'
  ]
}

To prove that it is not a timing issue i also ran

tls.createSecureContext(config1);

setTimeout(() => {
  tls.createSecureContext(config1);
}, 5000);

Which produces the same error.

I realize that a "normal" use case is not to fiddle with createContext, but to use something like tls.connect instead. Here is an example using that as well.

const configTLS = {
  privateKeyIdentifier:
    "pkcs11:model=YubiKey%20YK5;manufacturer=Yubico%20%28www.yubico.com%29;serial=22484003;token=YubiKey%20PIV%20%2322484003;id=%04;object=Private%20key%20for%20Card%20Authentication;type=private;pin-value=123456",
  privateKeyEngine: "pkcs11",
  rejectUnauthorized: false,
};

const a = tls.connect(443, "google.com", configTLS, () => {
  console.log("connected!");
  a.end(() => {
    console.log("ended");
    tls.connect(443, "google.com", configTLS, () => {
      console.log("connected again!");
      a.end();
    });
  });
});

This produces a similar error:

npm start

> what@1.0.0 start
> PKCS11_MODULE_PATH='/usr/lib/libykcs11.so' node index.js

connected!
ended
node:internal/tls/secure-context:207
        context.setEngineKey(privateKeyIdentifier, privateKeyEngine);
                ^

Error: error:12800067:DSO support routines::could not load the shared library
    at configSecureContext (node:internal/tls/secure-context:207:17)
    at Object.createSecureContext (node:_tls_common:116:3)
    at Object.connect (node:_tls_wrap:1759:48)
    at Array.<anonymous> (/home/dachrillz/temp/minimal/index.js:24:9)
    at callFinishedCallbacks (node:internal/streams/writable:972:25)
    at finish (node:internal/streams/writable:943:3)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
  opensslErrorStack: [
    'error:1300006D:engine routines::init failed',
    'error:13000074:engine routines::no such engine',
    'error:13000084:engine routines::dso not found',
    'error:12800067:DSO support routines::could not load the shared library'
  ]
}

My application that uses mqtt.js (which in turn uses tls.connect) itself works fine as long as the tls connection is not interrupted. Meaning that everything works as expected the first time around a tls connection is created using the pkcs11 device. It is the second time around that Node.js throws the exception.

How often does it reproduce? Is there a required condition?

Every time

What is the expected behavior? Why is that the expected behavior?

We expect Node to be able to create a tls connection.

What do you see instead?

Please see reproduce steps

Additional information

1. I have tried with different pkcs11 providers, and they seem to produce the same result.
2. I have not tried other platforms yet (E.g. Windows)

Please let me know if I should try some other configuration.

[dachrillz]

Seems to be related to (or same bug as) #41644
However I hope my reproduction steps provide some proof that it is not the mqtt.js library per se, but something with the tls module.

[dachrillz]

I did some further debugging. I cloned the node.js repo and build it (from head commit:ea88a3e1f2ba38531806fbd6fb5c668fa1cf0104) with some basic prints. Here is the C++ code i modified from crypto_util.cc

EnginePointer LoadEngineById(const char* id, CryptoErrorStore* errors) {
  MarkPopErrorOnReturn mark_pop_error_on_return;

  std::cout << id << " What is id\n";

  EnginePointer engine(ENGINE_by_id(id));

  std::cout << " Engine_by_id did not crash \n";
  if (!engine) {
    // Engine not found, try loading dynamically.
    std::cout << " inside did not find engine \n";
    engine = EnginePointer(ENGINE_by_id("dynamic"));
    if (engine) {
      std::cout << " loaded dynamic \n";
      auto SO_PATH = ENGINE_ctrl_cmd_string(engine.get(), "SO_PATH", id, 0);
      std::cout << SO_PATH << " SO PATH? \n";
      auto LOAD = ENGINE_ctrl_cmd_string(engine.get(), "LOAD", nullptr, 0);
      std::cout << LOAD << " LOAD? \n";
      if (!SO_PATH || !LOAD) {
        std::cout << " do we reset? \n";
        engine.reset();
      }
    }
  }

  if (!engine && errors != nullptr) {
    std::cout << " ERROR CAPTURE\n";
    errors->Capture();
    if (errors->Empty()) {
      errors->Insert(NodeCryptoError::ENGINE_NOT_FOUND, id);
    }
  }

  std::cout << " Do we get here?\n";
  return engine;
}

I'm still running the createSecureContext script twice. This produces the following.

############################## LOAD FIRST CONTEXT ##############################
pkcs11 What is id
 Engine_by_id did not crash 
 inside did not find engine 
 loaded dynamic 
1 SO PATH? 
1 LOAD? 
 Do we get here?
############################## LOAD SECOND CONTEXT ##############################
pkcs11 What is id
 Engine_by_id did not crash 
 inside did not find engine 
 loaded dynamic 
1 SO PATH? 
0 LOAD? 
 do we reset? 
 ERROR CAPTURE
 Do we get here?
node:internal/tls/secure-context:232
        context.setEngineKey(privateKeyIdentifier, privateKeyEngine);
                ^

Error: error:12800067:DSO support routines::could not load the shared library
    at configSecureContext (node:internal/tls/secure-context:232:17)
    at Object.createSecureContext (node:_tls_common:116:3)
    at Object.<anonymous> (/home/dachrillz/temp/working/index.js:22:5)
    at Module._compile (node:internal/modules/cjs/loader:1375:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1434:10)
    at Module.load (node:internal/modules/cjs/loader:1206:32)
    at Module._load (node:internal/modules/cjs/loader:1022:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:142:12)
    at node:internal/main/run_main_module:28:49 {
  opensslErrorStack: [
    'error:1300006D:engine routines::init failed',
    'error:13000074:engine routines::no such engine',
    'error:13000084:engine routines::dso not found',
    'error:12800067:DSO support routines::could not load the shared library'
  ]
}

Not entirely sure what is supposed to happen, but we are not allowed to LOAD a second time. I'm not too familiar with the internals of OpenSSL, but maybe it makes sense that you shouldn't really load an engine twice?

What surprises me however is that the first ENGINE_by_id returns nothing. I wrote a small c-program that uses the same function. It looks as follows

#include <openssl/engine.h>
#include <stdio.h>

int main()
{
    ENGINE *e;

    printf("############ Attempt to load first engine. #############\n");
    fflush(stdout);
    e = ENGINE_by_id("pkcs11");
    if (e == NULL)
    {
        printf("First attempt to load engine failed.\n");
        fflush(stdout);
        return 1;
    }

    char *engine_id = ENGINE_get_id(e);
    ENGINE_init(e);
    printf("engine id %s\n", engine_id);
    fflush(stdout);
}

When run with

gcc -o small_test small_test.c -lcrypto
PKCS11_MODULE_PATH='/usr/lib/libykcs11.so' ./small_test

It produces

############ Attempt to load first engine. #############
engine id pkcs11

Here we manage to succesfully load the pkcs11 engine immediately.

Noted that Node has its own OpenSSL implementation, but from what I can tell these parts should be very similar to the official OpenSSL implementation.

Is this a bug in how Node interacts with OpenSSL, or is there something wrong with my setup here?

The OpenSSL running on the machine that the C-program uses

openssl version
OpenSSL 3.1.3 19 Sep 2023 (Library: OpenSSL 3.1.3 19 Sep 2023)