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/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? 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
