On Wed, Jan 29, 2025 at 05:14:34PM +0000, Jonathan McDowell wrote:
> 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/[email protected]/
> > >
> > > 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?
No idea. I Initially put 10000 retries there and given it succeeded in
120% of the original timeout I cut the retries to 5 and promoted it to
'production ready' workaround.
I have only this one result with the patch applied available so far.
>
> > ---
> > 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.
That would agree with your previous result of not getting the problem
when using /dev/tpm0 instead.
Thanks
Michal
