On Wed, Jan 29, 2025 at 04:02:49PM +0000, Jonathan McDowell wrote: > On Wed, Jan 29, 2025 at 04:27:15PM +0100, Michal Suchánek wrote: > > there is a problem report that booting a specific type of system about > > 0.1% of the time encrypted volume (using a PCR to release the key) fails > > to unlock because of TPM operation timeout. > > > > Minimizing the test case failed so far. > > > > For example, booting into text mode as opposed to graphical desktop > > makes the problem unreproducible. > > > > The test is done with a frankenkernel that has TPM drivers about on par > > with Linux 6.4 but using actual Linux 6.4 the problem is not > > reproducible, either. > > > > However, given the problem takes up to a day to reproduce I do not have > > much confidence in the negative results. > > So. We see what look like similar timeouts in our fleet, but I haven't > managed to produce a reliable test case that gives me any confidence > about what the cause is. > > https://lore.kernel.org/linux-integrity/Zv1810ZfEBEhybmg@xxxxxxxx/ > > for my previous post about this. I see that's basically the same as the test patch I used: The time it takes for the TPM to become ready can exceed timeout_b Jan 28 07:09:21 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Timed out (2236 of 2000 ms) Jan 28 07:09:21 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Took (2236 of 2000 ms) --- drivers/char/tpm/tpm_tis_core.c | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/drivers/char/tpm/tpm_tis_core.c b/drivers/char/tpm/tpm_tis_core.c index fdef214b9f6b..c7a794a448af 100644 --- a/drivers/char/tpm/tpm_tis_core.c +++ b/drivers/char/tpm/tpm_tis_core.c @@ -432,19 +432,29 @@ static int tpm_tis_recv(struct tpm_chip *chip, u8 *buf, size_t count) static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len) { struct tpm_tis_data *priv = dev_get_drvdata(&chip->dev); + u32 ordinal = be32_to_cpu(*((__be32 *) (buf + 6))); int rc, status, burstcnt; size_t count = 0; bool itpm = test_bit(TPM_TIS_ITPM_WORKAROUND, &priv->flags); + unsigned long start, timed_out; status = tpm_tis_status(chip); if ((status & TPM_STS_COMMAND_READY) == 0) { tpm_tis_ready(chip); + timed_out = 0; start = jiffies; +retry_ready: if (wait_for_tpm_stat (chip, TPM_STS_COMMAND_READY, chip->timeout_b, &priv->int_queue, false) < 0) { + if (timed_out++ < 5) { + dev_err(&chip->dev, "%s: %u: ready: Timed out (%u of %u ms)\n", __func__, ordinal, jiffies_to_msecs(jiffies - start), jiffies_to_msecs(chip->timeout_b)); + goto retry_ready; + } rc = -ETIME; goto out_err; } + if (timed_out) + dev_err(&chip->dev, "%s: %u: ready: Took (%u of %u ms)\n", __func__, ordinal, jiffies_to_msecs(jiffies - start), jiffies_to_msecs(chip->timeout_b)); } while (count < len - 1) { > > > With some instrumentation it was determined that the problem happens > > here: > > > static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len) > > { > > struct tpm_tis_data *priv = dev_get_drvdata(&chip->dev); > > int rc, status, burstcnt; > > size_t count = 0; > > bool itpm = test_bit(TPM_TIS_ITPM_WORKAROUND, &priv->flags); > > > > status = tpm_tis_status(chip); > > if ((status & TPM_STS_COMMAND_READY) == 0) { > > tpm_tis_ready(chip); > > if (wait_for_tpm_stat > > (chip, TPM_STS_COMMAND_READY, chip->timeout_b, > > &priv->int_queue, false) < 0) { > > >>> rc = -ETIME; > > goto out_err; > > } > > } > > > localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Timed out (2236 of 2000 ms) > > localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Took (2236 of 2000 ms) > > Can you track down the actual command that's taking the time? Though I > guess that's the previous command rather than the one that hits the > timeout. Yes, 353 is supposed to be the command but it's likely the previous one that is causing the problem. I suppose this could be expanded to use a static variable to also save the last command. Thanks Michal
