Second execution of `swtpm` with `chardev --vtpm_proxy` hangs

[maugustosilva]

Describe the bug Whenever I attempt to re-execute sudo swtpm chardev --vtpm-proxy --tpmstate dir=/tmp/myvtpm --tpm2 --ctrl type=tcp,port=2322, after a CTRL+C, the command hangs and the device is not recreated on /dev

To Reproduce Steps to reproduce the behavior:

1. mkdir /tmp/myvtpm; sudo modprobe tpm_vtpm_proxy; sudo swtpm chardev --vtpm-proxy --tpmstate dir=/tmp/myvtpm --tpm2 --ctrl type=tcp,port=2322
2. (on a second term)ls -la /dev/tpm* shows /dev/tpm1 and /dev/tpmrm1 (machine already has a TPM device)
3. (on the first term)CTRL+C on running swtpm process
4. rmmod tpm_vtpm_proxy
5. mkdir /tmp/myvtpm; sudo modprobe tpm_vtpm_proxy; sudo swtpm chardev --vtpm-proxy --tpmstate dir=/tmp/myvtpm --tpm2 --ctrl type=tcp,port=2322
6. Virtual devices (/dev/tmp1) no longer appear (even after seemingly correct output) and process cannot be killed

Expected behavior We should be able to re-execute this command multiple times without any issue.

Desktop (please complete the following information):

• OS: Fedora
• Version: 33

Versions of relevant components

• swtpm: 0.5.2
• libtpms: 0.7.5-0.20210218gite271498466
• openssl: 1.1.1g-15
• gnutls: 3.6.15-1
• tpm2-tools: 4.3.0

Additional context Please note that I didn't actually test the functionality of the virtual TPM created. Instructions to interact with this VTPM via tpm2-tools would be welcome

[stefanberger]

I cannot recreate this issue on Fedora 33. I can do what you seem to do as many times as I want. I see /dev/tpm1 and /dev/tpmrm1 also being recreated every time in another terminal

[stefanb@sbct-5 ~]$ mkdir /tmp/myvtpm; sudo modprobe tpm_vtpm_proxy; sudo swtpm chardev --vtpm-proxy --tpmstate dir=/tmp/myvtpm --tpm2 --ctrl type=tcp,port=2322
New TPM device: /dev/tpm1 (major/minor = 253/1)
^C
[stefanb@sbct-5 ~]$ sudo rmmod tpm_vtpm_proxy
[stefanb@sbct-5 ~]$ mkdir /tmp/myvtpm; sudo modprobe tpm_vtpm_proxy; sudo swtpm chardev --vtpm-proxy --tpmstate dir=/tmp/myvtpm --tpm2 --ctrl type=tcp,port=2322
mkdir: cannot create directory ‘/tmp/myvtpm’: File exists
New TPM device: /dev/tpm1 (major/minor = 253/1)
^C
[stefanb@sbct-5 ~]$ sudo rmmod tpm_vtpm_proxy
[stefanb@sbct-5 ~]$ mkdir /tmp/myvtpm; sudo modprobe tpm_vtpm_proxy; sudo swtpm chardev --vtpm-proxy --tpmstate dir=/tmp/myvtpm --tpm2 --ctrl type=tcp,port=2322
mkdir: cannot create directory ‘/tmp/myvtpm’: File exists
New TPM device: /dev/tpm1 (major/minor = 253/1)
^C
[stefanb@sbct-5 ~]$ sudo rmmod tpm_vtpm_proxy
[stefanb@sbct-5 ~]$ mkdir /tmp/myvtpm; sudo modprobe tpm_vtpm_proxy; sudo swtpm chardev --vtpm-proxy --tpmstate dir=/tmp/myvtpm --tpm2 --ctrl type=tcp,port=2322
mkdir: cannot create directory ‘/tmp/myvtpm’: File exists
New TPM device: /dev/tpm1 (major/minor = 253/1)
^C
[stefanb@sbct-5 ~]$ rpm -q -a | grep swtpm
swtpm-libs-0.5.2-1.20201226gite59c0c1.fc33.x86_64
swtpm-0.5.2-1.20201226gite59c0c1.fc33.x86_64
swtpm-tools-0.5.2-1.20201226gite59c0c1.fc33.x86_64
[stefanb@sbct-5 ~]$ rpm -q -a | grep libtpms
libtpms-0.7.5-0.20210218gite271498466.fc33.x86_64
[stefanb@sbct-5 ~]$ uname -a
Linux sbct-5 5.10.19-200.fc33.x86_64 #1 SMP Fri Feb 26 16:21:30 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Do you see any error showing up in dmesg. I know there is a bug in the core TPM driver that's currently being fixed but this sequence here should not trigger it.

[stefanberger]

And regarding the tpm2_tools usage. In one terminal run swtpm with --log level=5 to see 'something':

[stefanb@sbct-5 ~]$ mkdir /tmp/myvtpm; sudo modprobe tpm_vtpm_proxy; sudo swtpm chardev --vtpm-proxy --tpmstate dir=/tmp/myvtpm --tpm2 --ctrl type=tcp,port=2322 --log level=5
mkdir: cannot create directory ‘/tmp/myvtpm’: File exists
New TPM device: /dev/tpm1 (major/minor = 253/1)
 SWTPM_IO_Read: length 11
 80 02 00 00 00 0B 20 00 10 00 00
[...]

In another terminal read the PCRs for example from the created /dev/tpm1:

[stefanb@sbct-5 ~]$ sudo tpm2_pcrread -T device:/dev/tpm1
sha1:
  0 : 0x0000000000000000000000000000000000000000
  1 : 0x0000000000000000000000000000000000000000
[...]
[stefanb@sbct-5 ~]$ sudo TPM2TOOLS_TCTI="device:/dev/tpm1" tpm2_pcrread
sha1:
  0 : 0x0000000000000000000000000000000000000000
  1 : 0x0000000000000000000000000000000000000000
[...]

[maugustosilva]

Yes, I see an error in /var/log/messages on the second execution:

Mar  8 15:35:12 hibinst kernel: BUG: unable to handle page fault for address: ffff9ac4c003c000
Mar  8 15:35:12 hibinst kernel: #PF: supervisor read access in kernel mode
Mar  8 15:35:12 hibinst kernel: #PF: error_code(0x0000) - not-present page
Mar  8 15:35:12 hibinst kernel: PGD 17b155067 P4D 17b155067 PUD 17b158067 PMD 17b159067 PTE 0
Mar  8 15:35:12 hibinst kernel: Oops: 0000 [#1] SMP PTI
Mar  8 15:35:12 hibinst kernel: CPU: 1 PID: 1212 Comm: kworker/1:5 Not tainted 5.8.15-301.fc33.x86_64 #1
Mar  8 15:35:12 hibinst kernel: Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015
Mar  8 15:35:12 hibinst kernel: Workqueue: tpm-vtpm vtpm_proxy_work [tpm_vtpm_proxy]
Mar  8 15:35:12 hibinst kernel: RIP: 0010:__memcpy+0x12/0x20
Mar  8 15:35:12 hibinst kernel: Code: 00 b8 01 00 00 00 85 d2 74 0a c7 05 44 7b ef 00 0f 00 00 00 c3 cc cc cc 66 66 90 66 90 48 89 f8 48 89 d1 48 c1 e9 03 83 e2 07 <f3> 48 a5 89 d1 f3 a4 c3 66 0f 1f 44 00 00 48 89 f8 48 89 d1 f3 a4
Mar  8 15:35:12 hibinst kernel: RSP: 0018:ffff9ac4c0fcfde0 EFLAGS: 00010206
Mar  8 15:35:12 hibinst kernel: RAX: ffff88f878cefed5 RBX: ffff88f878ce9000 RCX: 1ffffffffffffe0f
Mar  8 15:35:12 hibinst kernel: RDX: 0000000000000003 RSI: ffff9ac4c003bff9 RDI: ffff88f878cf0e4d
Mar  8 15:35:12 hibinst kernel: RBP: ffff9ac4c003b000 R08: 0000000000001000 R09: 000000007e9d6073
Mar  8 15:35:12 hibinst kernel: R10: ffff9ac4c003b000 R11: ffff88f879ad3500 R12: 0000000000000ed5
Mar  8 15:35:12 hibinst kernel: R13: ffff88f878ce9760 R14: 0000000000000002 R15: ffff88f77de7f018
Mar  8 15:35:12 hibinst kernel: FS:  0000000000000000(0000) GS:ffff88f87bd00000(0000) knlGS:0000000000000000
Mar  8 15:35:12 hibinst kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar  8 15:35:12 hibinst kernel: CR2: ffff9ac4c003c000 CR3: 00000001785a6004 CR4: 0000000000060ee0
Mar  8 15:35:12 hibinst kernel: Call Trace:
Mar  8 15:35:12 hibinst kernel: tpm_read_log_efi+0x152/0x1a7
Mar  8 15:35:12 hibinst kernel: tpm_bios_log_setup+0xc8/0x1c0
Mar  8 15:35:12 hibinst kernel: tpm_chip_register+0x8f/0x260
Mar  8 15:35:12 hibinst kernel: vtpm_proxy_work+0x16/0x60 [tpm_vtpm_proxy]
Mar  8 15:35:12 hibinst kernel: process_one_work+0x1b4/0x370
Mar  8 15:35:12 hibinst kernel: worker_thread+0x53/0x3e0
Mar  8 15:35:12 hibinst kernel: ? process_one_work+0x370/0x370

[stefanberger]

I see it now in a QEMU VM with UEFI as well. I do NOT see this issue on a host that has UEFI.

[maugustosilva]

Correct, this happens only inside a VM (UEFI booted)

[stefanberger]

@maugustosilva I sent the following patches to the mailing lists: https://lkml.org/lkml/2021/3/8/1512

They fix this issue and unfortunately also an issue with the disappearance of the TPM2 event log on UEFI when I introduced support for TPM2 event logs via ACPI. Affected kernels are 5.9 ... 5.12. I will have to see how I can have these patches backported, at least the one that fixes the UEFI TPM2 log disappearance issue.

[stefanberger]

If one can modify QEMU then the simplest work-around for the disappeared TPM 2 log is currently the following:

diff --git a/hw/acpi/aml-build.c b/hw/acpi/aml-build.c
index f6fbc9b95d..690b804676 100644
--- a/hw/acpi/aml-build.c
+++ b/hw/acpi/aml-build.c
@@ -1928,9 +1928,13 @@ void build_tpm2(GArray *table_data, BIOSLinker *linker, GArray *tcpalog)

     /* Log Area Start Address to be filled by Guest linker */
     build_append_int_noprefix(table_data, 0, 8);
+
+if (0) {
     bios_linker_loader_add_pointer(linker, ACPI_BUILD_TABLE_FILE,
                                    log_addr_offset, 8,
                                    ACPI_BUILD_TPMLOG_FILE, 0);
+}
+
     build_header(linker, table_data,
                  tpm2_ptr, "TPM2", table_data->len - tpm2_start, 4, NULL, NULL);
 }

This makes the log re-appear.

[stefanberger]

2nd version of the patches: https://lkml.org/lkml/2021/3/10/1548 This will hopefully go upstream soon and be applied to previous version of the kernel.

[maugustosilva]

The problem is solved in FC33 with the (newer) kernel 5.10.20-200. I will go ahead and close the issue. Thank you @stefanberger

[stefanberger]

I just tested it with 5.10.21-200 and the issue is still there...

I hope this all will be fixed in a few days/weeks especially the QEMU + TPM 2 EDK2/UEFI log disappearance.