Re: TPM operation times out (very rarely)

[Jonathan McDowell <noodles@earth.li>]

On Wed, Jan 29, 2025 at 05:20:33PM +0100, Michal Suchánek wrote:
> 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@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)

Does it always complete immediately after the retry? Have you tried a
longer value (eg timeout_b * 2) and confirmed that makes the issue go
away?

> ---
>  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.

So TPM2_CC_CONTEXT_LOAD. I'm assuming you're using /dev/tpmrm0, so
that's the start of a fresh "load context, execute command, save
context" cycle. I'd expect the previous command to be the
TPM2_CC_CONTEXT_SAVE from the previous cycle.

> I suppose this could be expanded to use a static variable to also save
> the last command.

J.

-- 
] https://www.earth.li/~noodles/ [] Design a system any fool can use,  [
]  PGP/GPG Key @ the.earth.li    []  and only a fool will want to use  [
] via keyserver, web or email.   []                it.                 [
] RSA: 4096/0x94FA372B2DA8B985   []                                    [