[pve-devel] [PATCH-SERIES swtpm/qemu-server] Improve swtpm logging

[pve-devel] [PATCH-SERIES swtpm/qemu-server] Improve swtpm logging

[Fiona Ebner]

There was a recent failure when migrating a production VM
> kvm: tpm-emulator: Setting the stateblob (type 1) failed with a TPM error 0x3 a parameter is bad
> kvm: error while loading state for instance 0x0 of device 'tpm-emulator'
> kvm: load of migration failed: Input/output error
and it's not clear what exactly triggered it.

Start collecting logs in /run/qemu-server/<ID>-swtpm.log to have some
information available for any future swtpm failures.

Also add a few more logs in swtpm itself, to better see what exactly
triggers the TPM_BAD_PARAMETER (0x3) error in case such a migration
failure happens again.


swtpm:

Fiona Ebner (1):
  control channel: add error logs upon receiving short input

 src/swtpm/ctrlchannel.c | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)


qemu-server:

Fiona Ebner (2):
  swtpm: enable logging
  swtpm: use start time as prefix for logging

 PVE/QemuServer.pm | 5 +++++
 1 file changed, 5 insertions(+)

-- 
2.30.2

[pve-devel] [PATCH swtpm 1/1] control channel: add error logs upon receiving short input

[Fiona Ebner]

There was a recent failure when migrating a production VM
> kvm: tpm-emulator: Setting the stateblob (type 1) failed with a TPM error 0x3 a parameter is bad
> kvm: error while loading state for instance 0x0 of device 'tpm-emulator'
> kvm: load of migration failed: Input/output error
and it's not clear what exactly triggered it. Note that 0x3 is
TPM_BAD_PARAMETER.

The timeout check when receiving the command+body is a good candidate,
but since poll() is called with the remaining timeout, it seems hard
to trigger. In both cases with short input, QEMU would've not managed
to even send the full header (16 bytes for CMD_SET_STATEBLOB).

Another possibility is that the blob header got corrupted and the
TPM_BAD_PARAMETER error orignated from the SWTPM_NVRAM_SetStateBlob()
call. The checks there already have logging.

Signed-off-by: Fiona Ebner <f.ebner@proxmox.com>
---
 src/swtpm/ctrlchannel.c | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)

diff --git a/src/swtpm/ctrlchannel.c b/src/swtpm/ctrlchannel.c
index 7b77a04..6538a54 100644
--- a/src/swtpm/ctrlchannel.c
+++ b/src/swtpm/ctrlchannel.c
@@ -419,8 +419,16 @@ wait_chunk:
         clock_gettime(CLOCK_REALTIME, &now);
         timespec_diff(&deadline, &now, &timeout);
 
-        if (timeout.tv_sec < 0)
+        if (timeout.tv_sec < 0) {
+            const char *msg_start = "Error: ctrlchannel_recv_cmd: timed out waiting for chunk";
+            if (recvd >= offsetof(struct input, body)) {
+                logprintf(STDERR_FILENO, "%s for command 0x%08x\n", msg_start, be32toh(input->cmd));
+                SWTPM_PrintAll("Input body", "", input->body, recvd - offsetof(struct input, body));
+            } else {
+                logprintf(STDERR_FILENO, "%s before receiving full command\n", msg_start);
+            }
             break;
+        }
         to = timeout.tv_sec * 1000 + timeout.tv_nsec / 1E6;
 
         /* wait for the next chunk */
@@ -544,6 +552,7 @@ int ctrlchannel_process_fd(int fd,
     SWTPM_PrintAll(" Ctrl Cmd:", " ", msg.msg_iov->iov_base, min(n, 1024));
 
     if ((size_t)n < sizeof(input.cmd)) {
+        logprintf(STDERR_FILENO, "Error: ctrlchannel_process_fd: input too short\n");
         goto err_bad_input;
     }
 
@@ -780,8 +789,12 @@ int ctrlchannel_process_fd(int fd,
             goto err_io;
 
         pss = (ptm_setstate *)input.body;
-        if (n < (ssize_t)offsetof(ptm_setstate, u.req.data)) /* rw */
+        if (n < (ssize_t)offsetof(ptm_setstate, u.req.data)) { /* rw */
+            logprintf(STDERR_FILENO, "Error: ctrlchannel_process_fd: input too "
+                                     "short for CMD_SET_STATEBLOB\n");
+            SWTPM_PrintAll("Input body", "", input.body, n);
             goto err_bad_input;
+        }
 
         return ctrlchannel_receive_state(pss, n, fd);
 
-- 
2.30.2

[pve-devel] [PATCH qemu-server 1/2] swtpm: enable logging

[Fiona Ebner]

AFAICT, previously, errors from swtpm would not show up in any logs,
because they were just printed to the stderr of the daemonized
invocation here.

The 'truncate' option is not used, so that the log is not immediately
lost when a new instance is started. This increases the chance that
the relevant errors are still present when requesting the log from a
user.

Log level 1 contains the most relevant errors and seems to be quiet
for working-as-expected invocations. Log level 2 already includes
logging full TPM commands, some of which are 1024 bytes long. Thus,
log level 1 was chosen.

Signed-off-by: Fiona Ebner <f.ebner@proxmox.com>
---
 PVE/QemuServer.pm | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/PVE/QemuServer.pm b/PVE/QemuServer.pm
index c2f5726e..97d60e2d 100644
--- a/PVE/QemuServer.pm
+++ b/PVE/QemuServer.pm
@@ -3263,6 +3263,8 @@ sub start_swtpm {
 	"file=$paths->{pid}",
 	"--terminate", # terminate on QEMU disconnect
 	"--daemon",
+	"--log",
+	"file=/run/qemu-server/$vmid-swtpm.log,level=1",
     ];
     push @$emulator_cmd, "--tpm2" if $tpm->{version} eq 'v2.0';
     run_command($emulator_cmd, outfunc => sub { print $1; });
-- 
2.30.2

[pve-devel] [PATCH qemu-server 2/2] swtpm: use start time as prefix for logging

[Fiona Ebner]

to be able to distinguish different invocations.

Signed-off-by: Fiona Ebner <f.ebner@proxmox.com>
---
 PVE/QemuServer.pm | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/PVE/QemuServer.pm b/PVE/QemuServer.pm
index 97d60e2d..e6aa62eb 100644
--- a/PVE/QemuServer.pm
+++ b/PVE/QemuServer.pm
@@ -3252,6 +3252,9 @@ sub start_swtpm {
 	});
     }
 
+    # Used to distinguish different invocations in the log.
+    my $log_prefix = "[id=" . int(time()) . "] ";
+
     my $emulator_cmd = [
 	"swtpm",
 	"socket",
@@ -3264,7 +3267,7 @@ sub start_swtpm {
 	"--terminate", # terminate on QEMU disconnect
 	"--daemon",
 	"--log",
-	"file=/run/qemu-server/$vmid-swtpm.log,level=1",
+	"file=/run/qemu-server/$vmid-swtpm.log,level=1,prefix=$log_prefix",
     ];
     push @$emulator_cmd, "--tpm2" if $tpm->{version} eq 'v2.0';
     run_command($emulator_cmd, outfunc => sub { print $1; });
-- 
2.30.2

[pve-devel] applied-series: [PATCH-SERIES swtpm/qemu-server] Improve swtpm logging

[Thomas Lamprecht]

Am 18/01/2023 um 13:21 schrieb Fiona Ebner:
> There was a recent failure when migrating a production VM
>> kvm: tpm-emulator: Setting the stateblob (type 1) failed with a TPM error 0x3 a parameter is bad
>> kvm: error while loading state for instance 0x0 of device 'tpm-emulator'
>> kvm: load of migration failed: Input/output error
> and it's not clear what exactly triggered it.
> 
> Start collecting logs in /run/qemu-server/<ID>-swtpm.log to have some
> information available for any future swtpm failures.
> 
> Also add a few more logs in swtpm itself, to better see what exactly
> triggers the TPM_BAD_PARAMETER (0x3) error in case such a migration
> failure happens again.
> 
> 
> swtpm:
> 
> Fiona Ebner (1):
>   control channel: add error logs upon receiving short input
> 
>  src/swtpm/ctrlchannel.c | 17 +++++++++++++++--
>  1 file changed, 15 insertions(+), 2 deletions(-)
> 
> 
> qemu-server:
> 
> Fiona Ebner (2):
>   swtpm: enable logging
>   swtpm: use start time as prefix for logging
> 
>  PVE/QemuServer.pm | 5 +++++
>  1 file changed, 5 insertions(+)
> 


applied all three patches, thanks!