[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 at 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