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/zv1810zfebehy...@earth.li/
>
> 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
