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@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) 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 [] [
