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.

Sign up for GitHub

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

Jump to bottom

Yubihsm ran out of session after a while when using with pkcs11 module #379

Open
ktrinh-anduril opened this issue Jan 5, 2024 · 10 comments
Open

Yubihsm ran out of session after a while when using with pkcs11 module #379

ktrinh-anduril opened this issue Jan 5, 2024 · 10 comments

Comments

@ktrinh-anduril
Copy link

Hi,

Currently, I'm using yubihsm with the openssl commandline through the pkcs11 module and the signing works for a bit but then gradually we run into the error: "Failed to create session: All sessions are allocated".

I think this is because the sessions are not closed by pkcs11 but I'm not sure how to force it to close or whether I'm using it incorrectly. For example this is the command that we would run:

openssl pkeyutl -engine pkcs11 -keyform engine -sign -pkeyopt rsa_padding_mode:pss -pkeyopt rsa_pss_saltlen:-1 -pkeyopt digest:sha256 -in tmp_sha256.hash -out tmp_rsa_pss.sig -inkey pkcs11:model=YubiHSM;token=YubiHSM;type=private;object=b71279f135f23d703b4ade76f04b3c7cbbc0978f

And it works for a bit but if we do it too frequently then it ran out of session. If I add some delays then it doesn't break.

This is our openssl config file:

      openssl_conf = openssl_init

      [openssl_init]
      engines = engine_section

      [engine_section]
      pkcs11 = pkcs11_section

      [pkcs11_section]
      engine_id = pkcs11
      dynamic_path = /path/to/lib/engines/libpkcs11.so
      MODULE_PATH = /path/to/lib/pkcs11/yubihsm_pkcs11.so
      PIN = "001something"
      INIT_ARGS = connector=http://127.0.0.1:12345 debug
      init = 0
@qpernil
Copy link
Contributor

qpernil commented Jan 5, 2024

Would you kindly provide the versions of the yubihsm_pkcs11 module, the libpkcs11 engine and openssl ? The OS version would also be helpful. Thank you.

As a side I can comment that the password needs to start with 4 hex digits, but maybe this was just an example.
It was previously a known error that the pkcs11 module (actually the underlying library) would leak sessions if authentication failed, by not closing them. The yubihhsm itself has a timeout for sessions, that is why it works again if you wait.
But if the password was correct this is not the issue here. Also, if the version is current it should not be the issue even with and incorrect password.

@ktrinh-anduril
Copy link
Author

Thanks for the quick replies! Here are the version info:

  • libp11(pkcs11 engine): 0.4.12
  • yubihsm: 2.4.2
  • openssl: 1.1.1

We are currently running NixOS 23.05

Yeah for the password, it's definitely 4 numbers, I just didn't type it in correctly

@qpernil
Copy link
Contributor

qpernil commented Jan 8, 2024

Also,could you set the YUBIHSM_PKCS11_DINOUT and YUBIHSM_PKCS11_DBG env variables and re-run the command, and then show the end parts of the log, so we can see if C_CloseSession (or possibly C_CloseAllSessions) is called. If it isn't then there is something wrong outside yubihsm_pkcs11.

@ktrinh-anduril
Copy link
Author

This is the log, I don't see the C_CloseSession which makes sense why things are not closing.

stage4> engine "pkcs11" set.
stage4> [P11 - INF 22:45:16.770429] yubihsm_pkcs11.c:446 (C_GetFunctionList): In
stage4> [P11 - INF 22:45:16.770533] yubihsm_pkcs11.c:455 (C_GetFunctionList): Out
stage4> [P11 - INF 22:45:16.770547] yubihsm_pkcs11.c:107 (C_Initialize): In
stage4> [P11 - INF 22:45:16.770586] yubihsm_pkcs11.c:213 (C_Initialize): Now parsing supplied init args as '--connector=http://127.0.0.1:12345 --debug '
stage4> [P11 - INF 22:45:16.770620] yubihsm_pkcs11.c:257 (C_Initialize): Found 1 configured connector(s)
stage4> [P11 - INF 22:45:16.781030] yubihsm_pkcs11.c:336 (C_Initialize): Found 1 usable connector(s)
stage4> [P11 - INF 22:45:16.781054] yubihsm_pkcs11.c:338 (C_Initialize): Found 0 configured device public key(s)
stage4> [P11 - INF 22:45:16.781065] yubihsm_pkcs11.c:343 (C_Initialize): Out
stage4> [P11 - INF 22:45:16.781077] yubihsm_pkcs11.c:412 (C_GetInfo): In
stage4> [P11 - INF 22:45:16.781089] yubihsm_pkcs11.c:438 (C_GetInfo): Out
stage4> [P11 - INF 22:45:16.781103] yubihsm_pkcs11.c:464 (C_GetSlotList): In
stage4> [P11 - INF 22:45:16.781112] yubihsm_pkcs11.c:493 (C_GetSlotList): Total number of slots is 1
stage4> [P11 - INF 22:45:16.781122] yubihsm_pkcs11.c:496 (C_GetSlotList): Can return 1 slot(s)
stage4> [P11 - INF 22:45:16.781130] yubihsm_pkcs11.c:500 (C_GetSlotList): Out
stage4> [P11 - INF 22:45:16.781140] yubihsm_pkcs11.c:464 (C_GetSlotList): In
stage4> [P11 - INF 22:45:16.781149] yubihsm_pkcs11.c:521 (C_GetSlotList): Returning slot 0
stage4> [P11 - INF 22:45:16.781159] yubihsm_pkcs11.c:538 (C_GetSlotList): Out
stage4> [P11 - INF 22:45:16.781170] yubihsm_pkcs11.c:545 (C_GetSlotInfo): In
stage4> [P11 - INF 22:45:16.781181] yubihsm_pkcs11.c:596 (C_GetSlotInfo): Out
stage4> [P11 - INF 22:45:16.781193] yubihsm_pkcs11.c:603 (C_GetTokenInfo): In
stage4> [P11 - INF 22:45:16.782637] yubihsm_pkcs11.c:694 (C_GetTokenInfo): Out
stage4> [P11 - INF 22:45:16.782661] yubihsm_pkcs11.c:841 (C_OpenSession): In
stage4> [P11 - INF 22:45:16.782690] yubihsm_pkcs11.c:886 (C_OpenSession): Allocated session 1
stage4> [P11 - INF 22:45:16.782701] yubihsm_pkcs11.c:888 (C_OpenSession): Out
stage4> [P11 - INF 22:45:16.782818] yubihsm_pkcs11.c:1945 (C_FindObjectsInit): In
stage4> [P11 - INF 22:45:16.782834] yubihsm_pkcs11.c:1982 (C_FindObjectsInit): Out
stage4> [P11 - INF 22:45:16.782844] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.782854] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.782864] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 0 object(s)
stage4> [P11 - INF 22:45:16.782874] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.782886] yubihsm_pkcs11.c:2344 (C_FindObjectsFinal): In
stage4> [P11 - INF 22:45:16.782896] yubihsm_pkcs11.c:2368 (C_FindObjectsFinal): Out
stage4> [P11 - INF 22:45:16.782909] yubihsm_pkcs11.c:1110 (C_Login): In
stage4> [P11 - INF 22:45:16.804887] yubihsm_pkcs11.c:1233 (C_Login): Out
stage4> [P11 - INF 22:45:16.804929] yubihsm_pkcs11.c:1945 (C_FindObjectsInit): In
stage4> [P11 - INF 22:45:16.804955] yubihsm_pkcs11.c:1998 (C_FindObjectsInit): find with 1 attributes
stage4> [P11 - INF 22:45:16.810446] yubihsm_pkcs11.c:2243 (C_FindObjectsInit): Out
stage4> [P11 - INF 22:45:16.810464] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.810477] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.810491] yubihsm_pkcs11.c:2327 (C_FindObjects): Returning object 0 as 03030012
stage4> [P11 - INF 22:45:16.810503] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 1 object(s)
stage4> [P11 - INF 22:45:16.810516] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.810529] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.810541] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 03030012
stage4> [P11 - INF 22:45:16.816278] util_pkcs11.c:4026 (populate_template): Getting attribute 0x0
stage4> [P11 - INF 22:45:16.816310] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.816324] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.816337] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.816348] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.816356] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 03030012
stage4> [P11 - INF 22:45:16.816367] util_pkcs11.c:4026 (populate_template): Getting attribute 0x100
stage4> [P11 - INF 22:45:16.816378] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.816390] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.816403] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.816416] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.816428] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 03030012
stage4> [P11 - INF 22:45:16.816440] util_pkcs11.c:4026 (populate_template): Getting attribute 0x102
stage4> [P11 - INF 22:45:16.816453] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 2
stage4> [P11 - INF 22:45:16.816465] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 2
stage4> [P11 - INF 22:45:16.816476] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.816488] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.816499] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 03030012
stage4> [P11 - INF 22:45:16.816508] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.816518] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 40
stage4> [P11 - INF 22:45:16.816531] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.816544] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.816554] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.816563] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 03030012
stage4> [P11 - INF 22:45:16.816573] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.816585] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 40
stage4> [P11 - INF 22:45:16.816598] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.816611] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.816622] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.816631] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 03030012
stage4> [P11 - INF 22:45:16.816640] util_pkcs11.c:4026 (populate_template): Getting attribute 0x202
stage4> [P11 - INF 22:45:16.816653] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 1
stage4> [P11 - INF 22:45:16.816665] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 1
stage4> [P11 - INF 22:45:16.816679] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.816693] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.816704] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.816716] yubihsm_pkcs11.c:2327 (C_FindObjects): Returning object 1 as 00030013
stage4> [P11 - INF 22:45:16.816730] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 1 object(s)
stage4> [P11 - INF 22:45:16.816741] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.816752] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.816761] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030013
stage4> [P11 - INF 22:45:16.822914] util_pkcs11.c:4026 (populate_template): Getting attribute 0x0
stage4> [P11 - INF 22:45:16.822945] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.822963] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.822985] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.823023] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.823039] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030013
stage4> [P11 - INF 22:45:16.823055] util_pkcs11.c:4026 (populate_template): Getting attribute 0x100
stage4> [P11 - INF 22:45:16.823073] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.823089] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.823104] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.823118] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.823129] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030013
stage4> [P11 - INF 22:45:16.823140] util_pkcs11.c:4026 (populate_template): Getting attribute 0x102
stage4> [P11 - INF 22:45:16.823153] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 2
stage4> [P11 - INF 22:45:16.823164] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 2
stage4> [P11 - INF 22:45:16.823171] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.823181] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.823193] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030013
stage4> [P11 - INF 22:45:16.823206] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.823217] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 40
stage4> [P11 - INF 22:45:16.823225] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.823237] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.823249] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.823259] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030013
stage4> [P11 - INF 22:45:16.823267] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.823280] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 40
stage4> [P11 - INF 22:45:16.823292] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.823305] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.823316] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.823324] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030013
stage4> [P11 - INF 22:45:16.823334] util_pkcs11.c:4026 (populate_template): Getting attribute 0x202
stage4> [P11 - INF 22:45:16.823347] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 1
stage4> [P11 - INF 22:45:16.823356] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 1
stage4> [P11 - INF 22:45:16.823366] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.823377] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.823388] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.823401] yubihsm_pkcs11.c:2327 (C_FindObjects): Returning object 2 as 01030014
stage4> [P11 - INF 22:45:16.823413] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 1 object(s)
stage4> [P11 - INF 22:45:16.823425] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.823436] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.823447] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030014
stage4> [P11 - INF 22:45:16.829281] util_pkcs11.c:4026 (populate_template): Getting attribute 0x0
stage4> [P11 - INF 22:45:16.829310] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.829322] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.829334] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.829346] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.829358] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030014
stage4> [P11 - INF 22:45:16.829368] util_pkcs11.c:4026 (populate_template): Getting attribute 0x100
stage4> [P11 - INF 22:45:16.829377] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.829389] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.829402] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.829415] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.829423] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030014
stage4> [P11 - INF 22:45:16.829435] util_pkcs11.c:4026 (populate_template): Getting attribute 0x102
stage4> [P11 - INF 22:45:16.829447] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 2
stage4> [P11 - INF 22:45:16.829457] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 2
stage4> [P11 - INF 22:45:16.829465] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.829478] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.829487] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030014
stage4> [P11 - INF 22:45:16.829496] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.829504] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 40
stage4> [P11 - INF 22:45:16.829513] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.829523] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.829532] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.829540] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030014
stage4> [P11 - INF 22:45:16.829551] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.829563] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 40
stage4> [P11 - INF 22:45:16.829576] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.829588] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.829599] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.829612] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030014
stage4> [P11 - INF 22:45:16.829622] util_pkcs11.c:4026 (populate_template): Getting attribute 0x202
stage4> [P11 - INF 22:45:16.829631] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 1
stage4> [P11 - INF 22:45:16.829641] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 1
stage4> [P11 - INF 22:45:16.829652] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.829663] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.829673] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.829682] yubihsm_pkcs11.c:2327 (C_FindObjects): Returning object 3 as 00030015
stage4> [P11 - INF 22:45:16.829695] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 1 object(s)
stage4> [P11 - INF 22:45:16.829707] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.829719] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.829728] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030015
stage4> [P11 - INF 22:45:16.835670] util_pkcs11.c:4026 (populate_template): Getting attribute 0x0
stage4> [P11 - INF 22:45:16.835688] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.835699] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.835711] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.835725] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.835736] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030015
stage4> [P11 - INF 22:45:16.835744] util_pkcs11.c:4026 (populate_template): Getting attribute 0x100
stage4> [P11 - INF 22:45:16.835754] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.835766] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.835779] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.835790] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.835799] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030015
stage4> [P11 - INF 22:45:16.835810] util_pkcs11.c:4026 (populate_template): Getting attribute 0x102
stage4> [P11 - INF 22:45:16.835820] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 2
stage4> [P11 - INF 22:45:16.835829] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 2
stage4> [P11 - INF 22:45:16.835841] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.835852] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.835864] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030015
stage4> [P11 - INF 22:45:16.835875] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.835886] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 40
stage4> [P11 - INF 22:45:16.835899] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.835912] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.835923] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.835934] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030015
stage4> [P11 - INF 22:45:16.835947] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.835958] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 40
stage4> [P11 - INF 22:45:16.835967] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.835976] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.835986] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.835996] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030015
stage4> [P11 - INF 22:45:16.836005] util_pkcs11.c:4026 (populate_template): Getting attribute 0x202
stage4> [P11 - INF 22:45:16.836014] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 1
stage4> [P11 - INF 22:45:16.836024] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 1
stage4> [P11 - INF 22:45:16.836035] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.836044] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.836054] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.836063] yubihsm_pkcs11.c:2327 (C_FindObjects): Returning object 4 as 00030016
stage4> [P11 - INF 22:45:16.836071] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 1 object(s)
stage4> [P11 - INF 22:45:16.836083] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.836095] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.836107] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030016
stage4> [P11 - INF 22:45:16.842146] util_pkcs11.c:4026 (populate_template): Getting attribute 0x0
stage4> [P11 - INF 22:45:16.842174] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.842196] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.842215] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.842235] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.842256] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030016
stage4> [P11 - INF 22:45:16.842279] util_pkcs11.c:4026 (populate_template): Getting attribute 0x100
stage4> [P11 - INF 22:45:16.842305] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.842317] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.842329] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.842341] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.842352] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030016
stage4> [P11 - INF 22:45:16.842363] util_pkcs11.c:4026 (populate_template): Getting attribute 0x102
stage4> [P11 - INF 22:45:16.842373] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 2
stage4> [P11 - INF 22:45:16.842384] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 2
stage4> [P11 - INF 22:45:16.842396] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.842410] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.842420] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030016
stage4> [P11 - INF 22:45:16.842432] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.842442] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 40
stage4> [P11 - INF 22:45:16.842453] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.842468] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.842477] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.842487] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030016
stage4> [P11 - INF 22:45:16.842498] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.842510] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 40
stage4> [P11 - INF 22:45:16.842522] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.842534] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.842546] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.842557] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030016
stage4> [P11 - INF 22:45:16.842568] util_pkcs11.c:4026 (populate_template): Getting attribute 0x202
stage4> [P11 - INF 22:45:16.842580] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 1
stage4> [P11 - INF 22:45:16.842592] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 1
stage4> [P11 - INF 22:45:16.842604] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.842617] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.842629] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.842641] yubihsm_pkcs11.c:2327 (C_FindObjects): Returning object 5 as 01030020
stage4> [P11 - INF 22:45:16.842653] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 1 object(s)
stage4> [P11 - INF 22:45:16.842666] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.842682] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.842693] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.848834] util_pkcs11.c:4026 (populate_template): Getting attribute 0x0
stage4> [P11 - INF 22:45:16.848863] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.848882] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.848903] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.848920] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.848930] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.848946] util_pkcs11.c:4026 (populate_template): Getting attribute 0x100
stage4> [P11 - INF 22:45:16.848955] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.848965] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.848976] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.848987] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.848997] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.849009] util_pkcs11.c:4026 (populate_template): Getting attribute 0x102
stage4> [P11 - INF 22:45:16.849021] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 2
stage4> [P11 - INF 22:45:16.849034] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 2
stage4> [P11 - INF 22:45:16.849043] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.849053] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.849063] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.849078] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.849089] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 40
stage4> [P11 - INF 22:45:16.849098] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.849110] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.849121] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.849132] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.849141] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.849149] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 40
stage4> [P11 - INF 22:45:16.849158] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.849168] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.849179] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.849192] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.849203] util_pkcs11.c:4026 (populate_template): Getting attribute 0x202
stage4> [P11 - INF 22:45:16.849215] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 1
stage4> [P11 - INF 22:45:16.849224] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 1
stage4> [P11 - INF 22:45:16.849234] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.849244] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.849253] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.849263] yubihsm_pkcs11.c:2327 (C_FindObjects): Returning object 6 as 00030021
stage4> [P11 - INF 22:45:16.849271] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 1 object(s)
stage4> [P11 - INF 22:45:16.849283] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.849294] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.849303] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030021
stage4> [P11 - INF 22:45:16.855128] util_pkcs11.c:4026 (populate_template): Getting attribute 0x0
stage4> [P11 - INF 22:45:16.855144] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.855154] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.855167] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.855181] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.855190] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030021
stage4> [P11 - INF 22:45:16.855198] util_pkcs11.c:4026 (populate_template): Getting attribute 0x100
stage4> [P11 - INF 22:45:16.855211] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 8
stage4> [P11 - INF 22:45:16.855222] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 8
stage4> [P11 - INF 22:45:16.855232] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.855242] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.855254] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030021
stage4> [P11 - INF 22:45:16.855267] util_pkcs11.c:4026 (populate_template): Getting attribute 0x102
stage4> [P11 - INF 22:45:16.855276] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 2
stage4> [P11 - INF 22:45:16.855288] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 2
stage4> [P11 - INF 22:45:16.855299] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.855312] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.855323] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030021
stage4> [P11 - INF 22:45:16.855335] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.855347] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 40
stage4> [P11 - INF 22:45:16.855360] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.855371] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.855379] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.855390] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030021
stage4> [P11 - INF 22:45:16.855401] util_pkcs11.c:4026 (populate_template): Getting attribute 0x3
stage4> [P11 - INF 22:45:16.855411] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 40
stage4> [P11 - INF 22:45:16.855420] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 40
stage4> [P11 - INF 22:45:16.855431] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.855443] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.855454] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 00030021
stage4> [P11 - INF 22:45:16.855463] util_pkcs11.c:4026 (populate_template): Getting attribute 0x202
stage4> [P11 - INF 22:45:16.855473] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 1
stage4> [P11 - INF 22:45:16.855483] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 1
stage4> [P11 - INF 22:45:16.855494] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.855504] yubihsm_pkcs11.c:2261 (C_FindObjects): In
stage4> [P11 - INF 22:45:16.855516] yubihsm_pkcs11.c:2285 (C_FindObjects): Can return 1 object(s)
stage4> [P11 - INF 22:45:16.855529] yubihsm_pkcs11.c:2331 (C_FindObjects): Returning 0 object(s)
stage4> [P11 - INF 22:45:16.855540] yubihsm_pkcs11.c:2333 (C_FindObjects): Out
stage4> [P11 - INF 22:45:16.855552] yubihsm_pkcs11.c:2344 (C_FindObjectsFinal): In
stage4> [P11 - INF 22:45:16.855563] yubihsm_pkcs11.c:2368 (C_FindObjectsFinal): Out
stage4> [P11 - INF 22:45:16.855578] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.855588] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.855597] util_pkcs11.c:4026 (populate_template): Getting attribute 0x120
stage4> [P11 - INF 22:45:16.871860] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 512
stage4> [P11 - INF 22:45:16.871889] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 512
stage4> [P11 - INF 22:45:16.871908] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.871921] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.871932] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.871943] util_pkcs11.c:4026 (populate_template): Getting attribute 0x120
stage4> [P11 - INF 22:45:16.888154] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 512
stage4> [P11 - INF 22:45:16.888169] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 512
stage4> [P11 - INF 22:45:16.888179] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.888195] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.888205] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.888215] util_pkcs11.c:4026 (populate_template): Getting attribute 0x122
stage4> [P11 - INF 22:45:16.888226] util_pkcs11.c:4042 (populate_template): Retrieving only length which is 3
stage4> [P11 - INF 22:45:16.888235] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 3
stage4> [P11 - INF 22:45:16.888244] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.888256] yubihsm_pkcs11.c:1779 (C_GetAttributeValue): In
stage4> [P11 - INF 22:45:16.888268] yubihsm_pkcs11.c:1797 (C_GetAttributeValue): For object 01030020
stage4> [P11 - INF 22:45:16.888277] util_pkcs11.c:4026 (populate_template): Getting attribute 0x122
stage4> [P11 - INF 22:45:16.888286] util_pkcs11.c:4049 (populate_template): Retrieving attribute value, length is 3
stage4> [P11 - INF 22:45:16.888298] util_pkcs11.c:4069 (populate_template): Attribute/length successfully returned with length 3
stage4> [P11 - INF 22:45:16.888307] yubihsm_pkcs11.c:1841 (C_GetAttributeValue): Out
stage4> [P11 - INF 22:45:16.888459] yubihsm_pkcs11.c:3480 (C_SignInit): In
stage4> [P11 - INF 22:45:16.888473] yubihsm_pkcs11.c:3505 (C_SignInit): Trying to sign data with mechanism 0x0001 and key 01030020
stage4> [P11 - INF 22:45:16.889688] yubihsm_pkcs11.c:3548 (C_SignInit): RSA signature requested
stage4> [P11 - INF 22:45:16.889703] yubihsm_pkcs11.c:3640 (C_SignInit): Out
stage4> [P11 - INF 22:45:16.889713] yubihsm_pkcs11.c:3653 (C_Sign): In
stage4> [P11 - INF 22:45:16.889724] yubihsm_pkcs11.c:3678 (C_Sign): The size of the signature will be 512
stage4> [P11 - INF 22:45:16.889734] yubihsm_pkcs11.c:3701 (C_Sign): Sending 48 bytes to sign
stage4> [P11 - INF 22:45:16.889742] yubihsm_pkcs11.c:3715 (C_Sign): Using key 0020
stage4> [P11 - INF 22:45:16.889752] yubihsm_pkcs11.c:3716 (C_Sign): After padding and transformation there are 48 bytes
stage4> [P11 - INF 22:45:17.757315] yubihsm_pkcs11.c:3726 (C_Sign): Got 512 bytes back
stage4> [P11 - INF 22:45:17.757337] yubihsm_pkcs11.c:3728 (C_Sign): Out

@qpernil
Copy link
Contributor

qpernil commented Jan 9, 2024

So it would seem yubihsm_pkcs11 is not getting deinitialized in any way, and hence cannot know that it should close the session(s). This will leave a session open in the yubihsm, which will then after 15 seconds time out.

@ktrinh-anduril
Copy link
Author

Gotcha, any special config needed to deinitialize it? I have been following the tutorial from the yubihsm site here: https://developers.yubico.com/YubiHSM2/Usage_Guides/OpenSSL_with_pkcs11_engine.html and I didn't see mention of special cleanup

@ktrinh-anduril
Copy link
Author

Okay I think I understand why things are not playing well with each other. So libp11 will wait for a new session forever as specified here by checking for if the C_OpenSession call returns CKR_SESSION_COUNT, however, it looks like on the yubihsm, C_OpenSession doesn't actually reserve a session with the physical yubikey so this always succeed. After that success though, libp11 will call C_Login which will trigger yubihsm to actually reserve a session with a physical device and return the too many session error, however, by this point, libp11 already exits its wait loop for available session so it just errors out

I think a possible fix would be for yubihsm to actually reserve the session with the physical yubikey itself in C_OpenSession so that if we don't have enought session, libp11 knows to wait

@qpernil
Copy link
Contributor

qpernil commented Jan 10, 2024

C_OpenSession doesn't open a physical session because with the yubihsm a session is always encrypted, so we can't open one until we have a password. Secondly, since login state is global (per process) in pkcs#11 there is no need for a separate physical session per logical (pkcs#11) session. In fact it would make things complicated, as per the pkcs#11 standard all (pkcs#11) sessions transition between logged in and not logged in (and a third SO state) simultaneously. We have no set upper limit on pkcs#11 sessions that can be opened as they only represent some memory which is dynamically allocated. (A pkcs#11 session does however represent a RO or RW state, which we keep track of in the library)

Having said all that I don't think this has any bearing on the fundamental problem, which is that as the openssl command / process dies it does not tell yubihsm_pkcs11 to clean up (either openssl doesn't tell the libp11 engine or the libp11 engine doesn't tell yubihsm_pkcs11), and thus we leave a session open on the yubihsm device. As that process dies it forgets the session keys and hence the session is now useless, but the yubihsm device can't know that. And we can't clean the session up in a new instance of yubihsm_pkcs11 since we can't know if there is a client still using it.

I would say the next step might be to try to debug the libp11 engine and see if it gets a cleanup, and what it does with it.

@ktrinh-anduril
Copy link
Author

okay I went down the blackhole and it looks like there is a reference counting bug in openssl that's why clean up wasn't called. Fixing that bug results in another deadlocking bug though so I think for now I will just use our delay workaround

@qpernil
Copy link
Contributor

qpernil commented Jan 11, 2024

Maybe this could be useful https://github.com/latchset/pkcs11-provider

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@qpernil @ktrinh-anduril