search

tpm2-software / tpm2-pkcs11

A PKCS#11 interface for TPM2 hardware
https://tpm2-software.github.io
Other
277 stars 105 forks source link

Occasional crashes #705

Closed stefanberger closed 2 years ago

stefanberger commented 3 years ago 
rpm -q -a | grep tpm2
tpm2-tss-3.1.0-1.fc34.x86_64
clevis-pin-tpm2-0.3.0-1.fc34.x86_64
tpm2-pkcs11-tools-1.6.0-1.fc34.x86_64
tpm2-pkcs11-1.6.0-1.fc34.x86_64
tpm2-abrmd-selinux-2.3.1-3.fc34.noarch
tpm2-abrmd-2.4.0-3.fc34.x86_64
tpm2-tools-5.1.1-1.fc34.x86_64

I am using the GnuTLS p11tool to list tokens and I occasionally get crashes like this one:

(gdb) r
Starting program: /usr/bin/p11tool --list-tokens
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff62a1640 (LWP 905350)]
[New Thread 0x7ffff5aa0640 (LWP 905351)]

** (process:905338): WARNING **: 06:59:07.898: Failed to create connection with service: GDBus.Error:org.freedesktop.DBus.Error.NoReply: Remote peer disconnected
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-tabrmd.so.0 
ERROR:tcti:src/tss2-tcti/tcti-device.c:442:Tss2_Tcti_Device_Init() Failed to open specified TCTI device file /dev/tpmrm0: No such file or directory 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-device.so.0 
ERROR:tcti:src/tss2-tcti/tcti-device.c:442:Tss2_Tcti_Device_Init() Failed to open specified TCTI device file /dev/tpm0: Permission denied 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-device.so.0 
WARNING:tcti:src/util/io.c:252:socket_connect() Failed to connect to host 127.0.0.1, port 2321: errno 111: Connection refused 
ERROR:tcti:src/tss2-tcti/tcti-swtpm.c:591:Tss2_Tcti_Swtpm_Init() Cannot connect to swtpm TPM socket 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-swtpm.so.0 
WARNING:tcti:src/util/io.c:252:socket_connect() Failed to connect to host 127.0.0.1, port 2321: errno 111: Connection refused 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-mssim.so.0 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:254:tctildr_get_default() No standard TCTI could be loaded 
ERROR:tcti:src/tss2-tcti/tctildr.c:428:Tss2_TctiLdr_Initialize_Ex() Failed to instantiate TCTI 
ERROR:fapi:src/tss2-fapi/api/Fapi_Initialize.c:227:Fapi_Initialize_Finish() Initializing TCTI. ErrorCode (0x000a000a) 

(process:905338): GLib-WARNING **: 06:59:08.971: GError set over the top of a previous GError or uninitialized memory.
This indicates a bug in someone's code. You must ensure an error is NULL before it's set.
The overwriting error message was: Error receiving data: Connection reset by peer

Thread 1 "p11tool" received signal SIGSEGV, Segmentation fault.
0x00007ffff671018e in tcti_tabrmd_read () from /lib64/libtss2-tcti-tabrmd.so.0
(gdb) bt
#0  0x00007ffff671018e in tcti_tabrmd_read () at /lib64/libtss2-tcti-tabrmd.so.0
#1  0x00007ffff671041e in tss2_tcti_tabrmd_receive () at /lib64/libtss2-tcti-tabrmd.so.0
#2  0x00007ffff6c61be7 in Tss2_Sys_ExecuteFinish () at /lib64/libtss2-sys.so.1
#3  0x00007ffff6dfac0c in Esys_GetCapability_Finish () at /lib64/libtss2-esys.so.0
#4  0x00007ffff6dfb084 in Esys_GetCapability () at /lib64/libtss2-esys.so.0
#5  0x00007ffff6e8ebe8 in tpm_get_algorithms.part.0.constprop () at /usr/lib64/pkcs11/libtpm2_pkcs11.so
#6  0x00007ffff6e8749c in mech_init () at /usr/lib64/pkcs11/libtpm2_pkcs11.so
#7  0x00007ffff6e87975 in token_min_init.part.0.lto_priv () at /usr/lib64/pkcs11/libtpm2_pkcs11.so
#8  0x00007ffff6e79712 in C_Initialize () at /usr/lib64/pkcs11/libtpm2_pkcs11.so
#9  0x00007ffff7a948aa in initialize_module_inlock_reentrant () at /lib64/libp11-kit.so.0
#10 0x00007ffff7a94c89 in managed_C_Initialize () at /lib64/libp11-kit.so.0
#11 0x00007ffff7a9b019 in p11_kit_modules_initialize () at /lib64/libp11-kit.so.0
#12 0x00007ffff7a9b779 in p11_kit_modules_load_and_initialize () at /lib64/libp11-kit.so.0
#13 0x00007ffff7e3fdc6 in auto_load () at /lib64/libgnutls.so.30
#14 0x00007ffff7e41657 in gnutls_pkcs11_init () at /lib64/libgnutls.so.30
#15 0x00005555555640de in main ()

There's no token setup related to the TPM 2 so I would expect this output here:

(gdb) r
The program being debugged has been started already.
Start it from the beginning? (y or n) y
Starting program: /usr/bin/p11tool --list-tokens
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff62a1640 (LWP 905518)]
[New Thread 0x7ffff5aa0640 (LWP 905519)]

** (process:905516): WARNING **: 07:04:07.089: Failed to create connection with service: GDBus.Error:org.freedesktop.DBus.Error.NoReply: Remote peer disconnected
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-tabrmd.so.0 
ERROR:tcti:src/tss2-tcti/tcti-device.c:442:Tss2_Tcti_Device_Init() Failed to open specified TCTI device file /dev/tpmrm0: No such file or directory 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-device.so.0 
ERROR:tcti:src/tss2-tcti/tcti-device.c:442:Tss2_Tcti_Device_Init() Failed to open specified TCTI device file /dev/tpm0: Permission denied 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-device.so.0 
WARNING:tcti:src/util/io.c:252:socket_connect() Failed to connect to host 127.0.0.1, port 2321: errno 111: Connection refused 
ERROR:tcti:src/tss2-tcti/tcti-swtpm.c:591:Tss2_Tcti_Swtpm_Init() Cannot connect to swtpm TPM socket 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-swtpm.so.0 
WARNING:tcti:src/util/io.c:252:socket_connect() Failed to connect to host 127.0.0.1, port 2321: errno 111: Connection refused 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-mssim.so.0 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:254:tctildr_get_default() No standard TCTI could be loaded 
ERROR:tcti:src/tss2-tcti/tctildr.c:428:Tss2_TctiLdr_Initialize_Ex() Failed to instantiate TCTI 
ERROR:fapi:src/tss2-fapi/api/Fapi_Initialize.c:227:Fapi_Initialize_Finish() Initializing TCTI. ErrorCode (0x000a000a) 

** (process:905516): WARNING **: 07:04:08.474: Failed to create connection with service: GDBus.Error:org.freedesktop.DBus.Error.NoReply: Remote peer disconnected
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-tabrmd.so.0 
ERROR:tcti:src/tss2-tcti/tcti-device.c:442:Tss2_Tcti_Device_Init() Failed to open specified TCTI device file /dev/tpmrm0: No such file or directory 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-device.so.0 
ERROR:tcti:src/tss2-tcti/tcti-device.c:442:Tss2_Tcti_Device_Init() Failed to open specified TCTI device file /dev/tpm0: Permission denied 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-device.so.0 
WARNING:tcti:src/util/io.c:252:socket_connect() Failed to connect to host 127.0.0.1, port 2321: errno 111: Connection refused 
ERROR:tcti:src/tss2-tcti/tcti-swtpm.c:591:Tss2_Tcti_Swtpm_Init() Cannot connect to swtpm TPM socket 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-swtpm.so.0 
WARNING:tcti:src/util/io.c:252:socket_connect() Failed to connect to host 127.0.0.1, port 2321: errno 111: Connection refused 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:154:tcti_from_file() Could not initialize TCTI file: libtss2-tcti-mssim.so.0 
ERROR:tcti:src/tss2-tcti/tctildr-dl.c:254:tctildr_get_default() No standard TCTI could be loaded 
ERROR:tcti:src/tss2-tcti/tctildr.c:428:Tss2_TctiLdr_Initialize_Ex() Failed to instantiate TCTI 
ERROR: Could not initialize tpm ctx: 0x5
Token 0:
    URL: pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=System%20Trust
    Label: System Trust
    Type: Trust module
    Flags: uPIN uninitialized
    Manufacturer: PKCS#11 Kit
    Model: p11-kit-trust
    Serial: 1
    Module: p11-kit-trust.so

Token 1:
    URL: pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=Default%20Trust
    Label: Default Trust
    Type: Trust module
    Flags: uPIN uninitialized
    Manufacturer: PKCS#11 Kit
    Model: p11-kit-trust
    Serial: 1
    Module: p11-kit-trust.so

Token 2:
    URL: pkcs11:model=SoftHSM%20v2;manufacturer=SoftHSM%20project;serial=bd632b8894a39601;token=swtpm-test
    Label: swtpm-test
    Type: Generic token
    Flags: RNG, Requires login
    Manufacturer: SoftHSM project
    Model: SoftHSM v2
    Serial: bd632b8894a39601
    Module: /usr/lib64/pkcs11/libsofthsm2.so

[Thread 0x7ffff5aa0640 (LWP 905519) exited]
[Thread 0x7ffff62a1640 (LWP 905518) exited]
[Inferior 1 (process 905516) exited normally]

The easiest way to recreate it seems to be the following (softhsm need not be installed on the system):

while :; do p11tool --list-tokens || break; done

It will eventually terminate like this:

[...]
Token 1:
    URL: pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=Default%20Trust
    Label: Default Trust
    Type: Trust module
    Flags: uPIN uninitialized
    Manufacturer: PKCS#11 Kit
    Model: p11-kit-trust
    Serial: 1
    Module: p11-kit-trust.so

** (process:916658): WARNING **: 07:14:40.061: write_all: failed to write to ostream: Error sending data: Broken pipe
ERROR:esys:src/tss2-esys/api/Esys_Startup.c:125:Esys_Startup_Async() Finish (Execute Async) ErrorCode (0x000a000a) 
ERROR:esys:src/tss2-esys/api/Esys_Startup.c:55:Esys_Startup() Error in async function ErrorCode (0x000a000a) 
ERROR:fapi:src/tss2-fapi/api/Fapi_Initialize.c:236:Fapi_Initialize_Finish() Esys_Startup FAILED! Response Code : 0xa000a 

(process:916658): GLib-WARNING **: 07:14:41.087: GError set over the top of a previous GError or uninitialized memory.
This indicates a bug in someone's code. You must ensure an error is NULL before it's set.
The overwriting error message was: Error receiving data: Connection reset by peer
Segmentation fault (core dumped)
williamcroberts commented 3 years ago

I'll have to get a Fedora 34 machine configured, but I just ran this on my Ubuntu 20.04 machine and it seems fine:

I know FAPI has had some fixes... let me start by re-creating and see if it fails with master.

rvka commented 3 years ago

I'm suffering from this problem, too. The culprit seems to be that indeed the number of connections to tpm2-abrmd gets exhausted. I didn't look into detail, but looking at active connections

# sudo lsof -c tpm2-abrmd -E -a -U
COMMAND    PID USER   FD   TYPE             DEVICE SIZE/OFF   NODE NAME
...
tpm2-abrm 1608  tss   11u  unix 0x0000000047bff185      0t0  57631 type=STREAM ->INO=57630 3407,gsd-smart,14u (CONNECTED)
tpm2-abrm 1608  tss   12u  unix 0x000000000e4bce5d      0t0  57633 type=STREAM ->INO=57632 3407,gsd-smart,16u (CONNECTED)
tpm2-abrm 1608  tss   13u  unix 0x00000000c41b9cee      0t0  57657 type=STREAM ->INO=57656 3407,gsd-smart,17u (CONNECTED)
tpm2-abrm 1608  tss   14u  unix 0x0000000010b7faab      0t0  74469 type=STREAM ->INO=74468 5670,ssh-pkcs1,10u (CONNECTED)
tpm2-abrm 1608  tss   15u  unix 0x00000000bf4205f8      0t0  74471 type=STREAM ->INO=74470 5670,ssh-pkcs1,12u (CONNECTED)
tpm2-abrm 1608  tss   16u  unix 0x00000000f91f08cc      0t0  74473 type=STREAM ->INO=74472 5670,ssh-pkcs1,13u (CONNECTED)
tpm2-abrm 1608  tss   17u  unix 0x000000000a2345c7      0t0  90056 type=STREAM ->INO=90055 7483,seahorse,17u (CONNECTED)
tpm2-abrm 1608  tss   18u  unix 0x00000000948ab5d0      0t0  90058 type=STREAM ->INO=90057 7483,seahorse,19u (CONNECTED)
tpm2-abrm 1608  tss   19u  unix 0x00000000fede29aa      0t0  90060 type=STREAM ->INO=90059 7483,seahorse,20u (CONNECTED)
tpm2-abrm 1608  tss   20u  unix 0x00000000af52defa      0t0  90858 type=STREAM ->INO=90857 7709,firefox,111u (CONNECTED)
tpm2-abrm 1608  tss   21u  unix 0x000000008988bac8      0t0  95688 type=STREAM ->INO=95687 7709,firefox,113u (CONNECTED)
tpm2-abrm 1608  tss   22u  unix 0x00000000d595a6f4      0t0  95690 type=STREAM ->INO=95689 7709,firefox,114u (CONNECTED)
tpm2-abrm 1608  tss   23u  unix 0x00000000e65a4a47      0t0  94126 type=STREAM ->INO=94125 8020,Web Conte,24u (CONNECTED)
tpm2-abrm 1608  tss   24u  unix 0x0000000088230508      0t0  96159 type=STREAM ->INO=96158 8020,Web Conte,26u (CONNECTED)
tpm2-abrm 1608  tss   25u  unix 0x000000003180df6f      0t0  96161 type=STREAM ->INO=96160 8020,Web Conte,27u (CONNECTED)
tpm2-abrm 1608  tss   26u  unix 0x00000000dba782b5      0t0 102170 type=STREAM ->INO=102169 8682,Web Conte,22u (CONNECTED)
tpm2-abrm 1608  tss   27u  unix 0x00000000248cda07      0t0 102172 type=STREAM ->INO=102171 8682,Web Conte,24u (CONNECTED)
tpm2-abrm 1608  tss   28u  unix 0x00000000d5f93eb4      0t0 102174 type=STREAM ->INO=102173 8682,Web Conte,25u (CONNECTED)
tpm2-abrm 1608  tss   29u  unix 0x000000002e6a964e      0t0 111927 type=STREAM ->INO=111926 9060,Web Conte,22u (CONNECTED)
tpm2-abrm 1608  tss   30u  unix 0x00000000e1f94b0d      0t0 111929 type=STREAM ->INO=111928 9060,Web Conte,24u (CONNECTED)
tpm2-abrm 1608  tss   31u  unix 0x000000004db90aa8      0t0 111931 type=STREAM ->INO=111930 9060,Web Conte,25u (CONNECTED)
tpm2-abrm 1608  tss   32u  unix 0x0000000021423cd5      0t0 112324 type=STREAM ->INO=112323 9463,Web Conte,22u (CONNECTED)
tpm2-abrm 1608  tss   33u  unix 0x000000009a6c2af6      0t0 112326 type=STREAM ->INO=112325 9463,Web Conte,24u (CONNECTED)
tpm2-abrm 1608  tss   34u  unix 0x00000000b510de79      0t0 112328 type=STREAM ->INO=112327 9463,Web Conte,25u (CONNECTED)
tpm2-abrm 1608  tss   35u  unix 0x0000000018b9c85e      0t0 133594 type=STREAM ->INO=133593 10452,Web Conte,22u (CONNECTED)
tpm2-abrm 1608  tss   36u  unix 0x000000008b610b02      0t0 133596 type=STREAM ->INO=133595 10452,Web Conte,24u (CONNECTED)
tpm2-abrm 1608  tss   37u  unix 0x000000000931778e      0t0 131476 type=STREAM ->INO=131475 10452,Web Conte,25u (CONNECTED)

suggests that

  1. every client establishes and holds open 3 socket connections
  2. every tab in firefox, being a separate process, establishes a connection, even though it doesn't seem to immediately require PKCS11

With more than half a dozen open tabs (i.e. always) the limit is exhausted.

rvka commented 3 years ago 
1. every client establishes and holds open 3 socket connections

With a bit of tracing, indeed even a simple p11tool --list-tokens establishes 3 tarbmd connections on the following code paths:

backend_init
  backend_fapi_init
    Fapi_Initialize
      ... Tss2_TctiLdr_Initialize
        ... Tss2_Tcti_Tabrmd_Init

backend_get_tokens
  backend_esysdb_get_tokens
    db_get_tokens
      token_min_init
    backend_ctx_new
      backend_esysdb_ctx_new
        tpm_ctx_new
          Tss2_TctiLdr_Initialize
        ... Tss2_Tcti_Tabrmd_Init

backend_get_tokens
  token_min_init
    backend_ctx_new
      backend_esysdb_ctx_new
    tpm_ctx_new
      Tss2_TctiLdr_Initialize
        ... Tss2_Tcti_Tabrmd_Init

There are no matching *_Finalize calls at all.

rvka commented 3 years ago 
1. every client establishes and holds open 3 socket connections

With a bit of tracing, indeed even a simple p11tool --list-tokens establishes 3 tarbmd connections on the following code paths: [...] There are no matching *_Finalize calls at all.

Setting TPM2_PKCS11_BACKEND=fapi results in exactly one Tss2_TctiLdr_Initialize call via Fapi_Initialize, and a matching Fapi_Finalize -> Tss2_TctiLdr_Finalize.

My FAPI isn't properly provisioned though so it doesn't work (yet).

Also, without explicitly specifying the backend (i.e. using esysdb), but pruning ~/.tpm2_pkcs11/tpm2_pkcs11.sqlite3 results in only two tarbmd connections, but my previously set up key disappearing from the list. I.e. every token consumes a connection.

rvka commented 3 years ago

With a bit of tracing, indeed even a simple p11tool --list-tokens establishes 3 tarbmd connections on the following code paths: [...] There are no matching *_Finalize calls at all.

Setting TPM2_PKCS11_BACKEND=fapi results in exactly one Tss2_TctiLdr_Initialize call via Fapi_Initialize, and a matching Fapi_Finalize -> Tss2_TctiLdr_Finalize.

My FAPI isn't properly provisioned though so it doesn't work (yet).

Interestingly, after tss2_provision *_Finalize stopped appearing in the traces, and so did the log message at the top of backend_destroy. UPD: this appears to be an artifact of p11tool which doesn't call C_Finalize on loaded modules.

rvka commented 3 years ago

I just realized I misinterpreted the original issue; my comments aren't probably relevant for that problem.

I guess I should rather create a separate issue.

williamcroberts commented 3 years ago

So are their 3 problems here?

  1. gerror memory not initialized?
  2. Exhausting connections per store as each token uses connections (so we want to be more lazy about establishing connections)?
    • Each token can have a different TCTI, so reusing them not only causes contention between the tokens on send/recv but also can be tricky if they are configured to differing TCTI configs.
  3. Is the segfault a problem of #1, or is it a different issue when initialize fails?
stefanberger commented 3 years ago 
1. gerror memory not initialized?

Yes, seems to come from the pkcs11 module.

[Sorry for closing. Wrong button, due to too much or not enough coffee.]

williamcroberts commented 3 years ago 
1. gerror memory not initialized?

Yes, seems to come from the pkcs11 module.

[Sorry for closing. Wrong button, due to too much or not enough coffee.]

I think that's fixed here:

If you apply that patch do your segfaults go away?

williamcroberts commented 2 years ago

@stefanberger did the fix in the tpm2-abrmd TCTI code (https://github.com/tpm2-software/tpm2-abrmd/commit/6af641bfa46130670a8462d1031f9276aeb0af1f) fix your issue?

stefanberger commented 2 years ago

On Fedora 36 with tpm2-abrmd-2.4.1-1.fc36.x86_64 installed the loop, that previously caused the failure, now works fine.

while :; do p11tool --list-tokens || break; done
stefanberger commented 2 years ago

Thanks!