TPM operation times out (very rarely)
Subsystems (2)
Hello,
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.
With some instrumentation it was determined that the problem happens here:
/*
* If interrupts are used (signaled by an irq set in the vendor structure)
* tpm.c can skip polling for the data to be available as the interrupt is
* waited for 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) {Quoted 1 line
Quoted 1 line
Quoted 1 line
rc = -ETIME;
goto out_err;
}
}
while (count < len - 1) {
burstcnt = get_burstcount(chip);
if (burstcnt < 0) {
dev_err(&chip->dev, "Unable to read burstcount\n");
rc = burstcnt;
goto out_err;
}
burstcnt = min_t(int, burstcnt, len - count - 1);
rc = tpm_tis_write_bytes(priv, TPM_DATA_FIFO(priv->locality),
burstcnt, buf + count);
if (rc < 0)
goto out_err;
count += burstcnt;
if (wait_for_tpm_stat(chip, TPM_STS_VALID, chip->timeout_c,
&priv->int_queue, false) < 0) {
rc = -ETIME;
goto out_err;
}
status = tpm_tis_status(chip);
if (!itpm && (status & TPM_STS_DATA_EXPECT) == 0) {
rc = -EIO;
goto out_err;
}
}
/* write last byte */
rc = tpm_tis_write8(priv, TPM_DATA_FIFO(priv->locality), buf[count]);
if (rc < 0)
goto out_err;
if (wait_for_tpm_stat(chip, TPM_STS_VALID, chip->timeout_c,
&priv->int_queue, false) < 0) {
rc = -ETIME;
goto out_err;
}
status = tpm_tis_status(chip);
if (!itpm && (status & TPM_STS_DATA_EXPECT) != 0) {
rc = -EIO;
goto out_err;
}
rc = tpm_tis_verify_crc(priv, len, buf);
if (rc < 0) {
dev_err(&chip->dev, "CRC mismatch for command.\n");
goto out_err;
}
return 0;out_err:
tpm_tis_ready(chip); return rc; }
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)
200ms is a very long time for kernel space yet minor changes to the test setup avoid the problem.
I am wondering if this timeout is insufficient if eg. the previous operation can take up to TPM_LONG_LONG or perhaps if some of that time should have been consumed by the previous operation but because of insufficient locking somewhere the kernel got to waiting on the chip to become ready too early.
Note that these two volume unlocks are done by systemd services, and happen in parallel as much as possible.
The chip type:
tpm_tis IFX1522:00: 2.0 TPM (device-id 0x1D, rev-id 54)
Handle 0x0001, DMI type 43, 31 bytes
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 15.22
Description: SLB9672
Characteristics:
Family configurable via firmware update Family configurable via platform software support
OEM-specific Information: 0x00000000
Any idea what could be the cause of this problem?
Thanks
Michal
Quoted 9 lines · Michal Suchánek
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.
Quoted 6 lines
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.
Quoted 16 lines
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) {
Quoted 7 lines
Quoted 1 line
Quoted 1 line
Quoted 1 line
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.
Quoted 27 lines
200ms is a very long time for kernel space yet minor changes to the test setup avoid the problem.
I am wondering if this timeout is insufficient if eg. the previous operation can take up to
TPM_LONG_LONGor perhaps if some of that time should have been consumed by the previous operation but because of insufficient locking somewhere the kernel got to waiting on the chip to become ready too early.Note that these two volume unlocks are done by systemd services, and happen in parallel as much as possible.
The chip type:
tpm_tisIFX1522:00: 2.0 TPM (device-id0x1D, rev-id 54)Handle
0x0001, DMI type 43, 31 bytes
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 15.22
Description: SLB9672
Characteristics:
Family configurable via firmware update Family configurable via platform software support
OEM-specific Information:0x00000000
Quoted 1 line
Any idea what could be the cause of this problem?
We're using SLB9670 devices, so older than yours, but at least the same family.
J.
Signature · 4 lines
The end is nearer. | .''`. Debian GNU/Linux Developer
| : :' : Happy to accept PGP signed
| `. `' or encrypted mail - RSA
| `- key on the keyservers.Quoted 17 lines · Jonathan McDowell
Quoted 9 lines · Michal Suchánek
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.
Quoted 6 lines
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.
Quoted 7 lines
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) --- drivers/char/tpm/tpm_tis_core.c | 10 ++++++++++ 1 file changed, 10 insertions(+)
drivers/char/tpm/tpm_tis_core.c +10 -0
@@ -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 ) {
Quoted 22 lines
Quoted 21 lines
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) {Quoted 1 line
Quoted 1 line
Quoted 1 line
rc = -ETIME;goto out_err; } }
Quoted 6 lines
Quoted 2 lines
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
Quoted 24 lines · Michal Suchánek
Quoted 23 lines · Jonathan McDowell
Quoted 9 lines · Michal Suchánek
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.
Quoted 6 lines
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.
Quoted 8 lines
Quoted 1 line
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_bJan 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?
Quoted 65 lines
--- drivers/char/tpm/tpm_tis_core.c | 10 ++++++++++ 1 file changed, 10 insertions(+)drivers/char/tpm/tpm_tis_core.c +10
-0@@ -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 ) {Quoted 27 lines
Quoted 26 lines
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) {Quoted 1 line
Quoted 1 line
Quoted 1 line
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)
Quoted 6 lines
Quoted 3 lines
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.
Quoted 2 lines
I suppose this could be expanded to use a static variable to also save the last command.
J.
Signature · 4 lines
] 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 [] [
Quoted 29 lines · Jonathan McDowell
Quoted 28 lines · Michal Suchánek
Quoted 17 lines · Jonathan McDowell
Quoted 9 lines · Michal Suchánek
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.
Quoted 6 lines
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.
Quoted 7 lines
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:
Quoted 8 lines
Quoted 4 lines
The time it takes for the TPM to become ready can exceed
timeout_bJan 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.
Quoted 70 lines
Quoted 70 lines
--- drivers/char/tpm/tpm_tis_core.c | 10 ++++++++++ 1 file changed, 10 insertions(+)drivers/char/tpm/tpm_tis_core.c +10
-0@@ -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 ) {Quoted 30 lines
Quoted 19 lines
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) {Quoted 7 lines
Quoted 1 line
Quoted 1 line
Quoted 1 line
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.
Quoted 7 lines
Quoted 2 lines
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 theTPM2_CC_CONTEXT_SAVEfrom the previous cycle.
That would agree with your previous result of not getting the problem when using /dev/tpm0 instead.
Thanks
Michal
Jarkko Sakkinen
maintainerQuoted 17 lines · Jonathan McDowell
Quoted 9 lines · Michal Suchánek
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.
Quoted 6 lines
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.
Quoted 7 lines
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.
Ugh, this was my first week at new job, sorry.
2000 ms is like a spec value, which can be a bad idea. Please look at Table 18.
My guess is that GUI makes more stuff happening in the system, which could make latencies more shaky.
The most trivial candidate would be:
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, TPM_TIS_TIMEOUT_MAX /* e.g. 2250 ms */,
&priv->int_queue, false) < 0) {
rc = -ETIME;
goto out_err;
}
}On the other hand, for me tpm_tis_send_main() looked initially weird:
for (try = 0; try < TPM_RETRY; try++) {
rc = tpm_tis_send_data(chip, buf, len);
if (rc >= 0)
/* Data transfer done successfully */
break;
else if (rc != -EIO)
/* Data transfer failed, not recoverable */
return rc;
}I.e. no retry on -ETIME.
But I'd fixup instead tpm_common_write():
out:
mutex_unlock(&priv->buffer_mutex); if (ret == -ETIME) return -ERESTARTSYS; return ret; }
It still can be interrupted by a signal this way. Retry loop would block too much.
Not sure if only the increase in timeout value would be enough or should the both sites be fixed up.
BR, Jarkko
Hello,
Quoted 34 lines · Jarkko Sakkinen
Quoted 17 lines · Jonathan McDowell
Quoted 9 lines · Michal Suchánek
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.
Quoted 6 lines
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.
Quoted 7 lines
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.
Ugh, this was my first week at new job, sorry.
2000 ms is like a spec value, which can be a bad idea. Please look at Table 18.
My guess is that GUI makes more stuff happening in the system, which could make latencies more shaky.
Quoted 7 lines
The most trivial candidate would be:
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, TPM_TIS_TIMEOUT_MAX /* e.g. 2250 ms */,
2250 is more than the measured 2226 but I have no idea if that's random or in some way deterministic.
Quoted 31 lines
&priv->int_queue, false) < 0) { rc = -ETIME; goto out_err; } }On the other hand, for me
tpm_tis_send_main()looked initially weird:for (try = 0; try < TPM_RETRY; try++) { rc = tpm_tis_send_data(chip, buf, len); if (rc >= 0) /* Data transfer done successfully */ break; else if (rc != -EIO) /* Data transfer failed, not recoverable */ return rc; }I.e. no retry on
-ETIME.But I'd fixup instead
tpm_common_write():out:
mutex_unlock(&priv->buffer_mutex); if (ret == -ETIME) return -ERESTARTSYS; return ret; }
Quoted 2 lines
It still can be interrupted by a signal this way. Retry loop would block too much.
Not sure if this would help. As was noted in the discussion so far if the value is consumed by the kernel it will likely not retry in the upper layer code.
Also restarting the userspace cryptsetup service reportedly did not help addressing the problem which suggests that the consumer is indeed the kernel, and it marked something as defunct and gave up on getting the key from the TPM entirely.
Also the loop can already block for up to 2s. If blocking in the loop is a problem then it should be addressed in that loop.
Thanks
Michal
Quoted 7 lines
Not sure if only the increase in timeout value would be enough or should the both sites be fixed up.
BR, Jarkko
Jarkko Sakkinen
maintainerQuoted 39 lines · Michal Suchánek
Hello,
Quoted 36 lines · Jarkko Sakkinen
Quoted 17 lines · Jonathan McDowell
Quoted 9 lines · Michal Suchánek
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.
Quoted 6 lines
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.
Quoted 7 lines
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.
Ugh, this was my first week at new job, sorry.
2000 ms is like a spec value, which can be a bad idea. Please look at Table 18.
My guess is that GUI makes more stuff happening in the system, which could make latencies more shaky.
The most trivial candidate would be:
Quoted 8 lines
Quoted 5 lines
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, TPM_TIS_TIMEOUT_MAX /* e.g. 2250 ms */,2250 is more than the measured 2226 but I have no idea if that's random or in some way deterministic.
Your text vs GUI at least gives evidence of stochasticity while not a full-fledged proof. You can expect e.g. more IRQs happening when you run a GUI. I did not engineer that number. You could e.g. double the original number. The whole framework for timeout_b is ridiculous (if it is because of me it does not change that fact).
Or perhaps we could consider even wait_event_interruptible() inside wait_for_tpm_stat(), since it is interruptible.
BR, Jarkko
Quoted 46 lines · Jarkko Sakkinen
Quoted 45 lines · Michal Suchánek
Hello,
Quoted 41 lines · Jarkko Sakkinen
Quoted 17 lines · Jonathan McDowell
Quoted 9 lines · Michal Suchánek
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.
Quoted 6 lines
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.
Quoted 7 lines
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.
Ugh, this was my first week at new job, sorry.
2000 ms is like a spec value, which can be a bad idea. Please look at Table 18.
My guess is that GUI makes more stuff happening in the system, which could make latencies more shaky.
The most trivial candidate would be:
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, TPM_TIS_TIMEOUT_MAX /* e.g. 2250 ms */,
Quoted 8 lines
Quoted 2 lines
2250 is more than the measured 2226 but I have no idea if that's random or in some way deterministic.
Your text vs GUI at least gives evidence of stochasticity while not a full-fledged proof. You can expect e.g. more IRQs happening when you run a GUI. I did not engineer that number. You could e.g. double the original number. The whole framework for
timeout_bis ridiculous (if it is because of me it does not change that fact).
It looks like the timeout_b is used exclusively as the ready timeout *), with various sources of the value depending on chip type.
Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of timeout_b for TPM_STS_VALID in st33zp24_pm_resume.
Quoted 2 lines
Or perhaps we could consider even
wait_event_interruptible()insidewait_for_tpm_stat(), since it is interruptible.
It seems to be already interruptible, at least the implementation in tpm_tis_core. There is another one in xenfront, and a few more wait_for_stat() without _tpm_ in the middle.
Thanks
Michal
Jarkko Sakkinen
maintainerQuoted 8 lines · Michal Suchánek
It looks like the
timeout_bis used exclusively as the ready timeout *), with various sources of the value depending on chip type.Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of
timeout_bforTPM_STS_VALIDinst33zp24_pm_resume.
Possible for you to give a shot for patch and try it out for a while? I'm fine with 2x, or even 4x in this case.
BR, Jarkko
Quoted 4 lines · Jarkko Sakkinen
Quoted 3 lines · Michal Suchánek
It looks like the
timeout_bis used exclusively as the ready timeout *), with various sources of the value depending on chip type.
Quoted 8 lines
Quoted 5 lines
Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of
timeout_bforTPM_STS_VALIDinst33zp24_pm_resume.Possible for you to give a shot for patch and try it out for a while? I'm fine with 2x, or even 4x in this case.
I will see what I can do. It will definitely take a while.
How would you like to multiply it?
At the sime the timeout_b is assigned, or at the time it's used?
Any specific patch that you have in mind?
Thanks
Michal
Jarkko Sakkinen
maintainerQuoted 14 lines · Michal Suchánek
Quoted 4 lines · Jarkko Sakkinen
Quoted 3 lines · Michal Suchánek
It looks like the
timeout_bis used exclusively as the ready timeout *), with various sources of the value depending on chip type.Quoted 8 lines
Quoted 5 lines
Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of
timeout_bforTPM_STS_VALIDinst33zp24_pm_resume.Possible for you to give a shot for patch and try it out for a while? I'm fine with 2x, or even 4x in this case.
Quoted 7 lines
I will see what I can do. It will definitely take a while.
How would you like to multiply it?
At the sime the
timeout_bis assigned, or at the time it's used?Any specific patch that you have in mind?
I'll think about this a bit and send a patch with RFC tag. Might take to late next week.
BR, Jarkko
Quoted 17 lines · Jarkko Sakkinen
Quoted 16 lines · Michal Suchánek
Quoted 4 lines · Jarkko Sakkinen
Quoted 3 lines · Michal Suchánek
It looks like the
timeout_bis used exclusively as the ready timeout *), with various sources of the value depending on chip type.Quoted 8 lines
Quoted 5 lines
Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of
timeout_bforTPM_STS_VALIDinst33zp24_pm_resume.Possible for you to give a shot for patch and try it out for a while? I'm fine with 2x, or even 4x in this case.
I will see what I can do. It will definitely take a while.
Quoted 8 lines
Quoted 5 lines
How would you like to multiply it?
At the sime the
timeout_bis assigned, or at the time it's used?Any specific patch that you have in mind?
I'll think about this a bit and send a patch with RFC tag. Might take to late next week.
The ready timeout is not the only one exceeded:
Quoted 18 lines
Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2232 of 2000 ms) Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2232 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Timed out (2228 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Took (2228 of 2000 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (2224 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (2224 of 200 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2228 of 2000 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2228 of 2000 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (556 of 200 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (556 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Timed out (272 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Took (272 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms)
Quoted 8 lines
Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2236 of 2000 ms) Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2236 of 2000 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (540 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (540 of 200 ms)
While the ready timeout is quite consistently exceeded by around 230ms so far the stat timeout a few lines lower is less consistent.
Failure is observed with another chip type as well:
localhost kernel: tpm_tis MSFT0101:00: 2.0 TPM (device-id 0x1B, rev-id
22)
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 7.83
Description: TPM 2.0, ManufacturerID: IFX , Firmware Version: 7.83.3358.0 Characteristics:
Family configurable via firmware update
Family configurable via OEM proprietary mechanism
OEM-specific Information: 0x00000000
Thanks
Michal
Quoted 64 lines · Michal Suchánek
Quoted 17 lines · Jarkko Sakkinen
Quoted 16 lines · Michal Suchánek
Quoted 4 lines · Jarkko Sakkinen
Quoted 3 lines · Michal Suchánek
It looks like the
timeout_bis used exclusively as the ready timeout *), with various sources of the value depending on chip type.Quoted 8 lines
Quoted 5 lines
Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of
timeout_bforTPM_STS_VALIDinst33zp24_pm_resume.Possible for you to give a shot for patch and try it out for a while? I'm fine with 2x, or even 4x in this case.
I will see what I can do. It will definitely take a while.
Quoted 8 lines
Quoted 5 lines
How would you like to multiply it?
At the sime the
timeout_bis assigned, or at the time it's used?Any specific patch that you have in mind?
I'll think about this a bit and send a patch with RFC tag. Might take to late next week.
The ready timeout is not the only one exceeded:
Quoted 18 lines
Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2232 of 2000 ms) Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2232 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Timed out (2228 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Took (2228 of 2000 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (2224 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (2224 of 200 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2228 of 2000 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2228 of 2000 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (556 of 200 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (556 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Timed out (272 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Took (272 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms)Quoted 8 lines
Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2236 of 2000 ms) Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2236 of 2000 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (540 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (540 of 200 ms)While the ready timeout is quite consistently exceeded by around 230ms so far the stat timeout a few lines lower is less consistent.
Failure is observed with another chip type as well:
localhost kernel:
tpm_tisMSFT0101:00: 2.0 TPM (device-id0x1B, rev-id
22)
Quoted 9 lines
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 7.83
Description: TPM 2.0, ManufacturerID: IFX , Firmware Version: 7.83.3358.0 Characteristics:
Family configurable via firmware update
Family configurable via OEM proprietary mechanism
OEM-specific Information:0x00000000
Also adding the patch for reference.
Thanks
Michal
drivers/char/tpm/tpm_tis_core.c +18 -0
@@ -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++ <2 ) { +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 ) {
@@ -479,11 +489,19 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)if (rc <0 ) goto out_err; + timed_out =0 ; start = jiffies; +retry_stat:if (wait_for_tpm_stat (chip,TPM_STS_VALID , chip->timeout_c, &priv->int_queue, false) <0 ) { +if (timed_out++ <5 ) { +dev_err (&chip->dev,"%s: %u: stat: Timed out (%u of %u ms)\n" , __func__, ordinal,jiffies_to_msecs (jiffies - start),jiffies_to_msecs (chip->timeout_c)); + goto retry_stat; + } rc = -ETIME ; goto out_err; } +if (timed_out) +dev_err (&chip->dev,"%s: %u: stat: Took (%u of %u ms)\n" , __func__, ordinal,jiffies_to_msecs (jiffies - start),jiffies_to_msecs (chip->timeout_c)); status =tpm_tis_status (chip);if (!itpm && (status &TPM_STS_DATA_EXPECT ) !=0 ) { rc = -EIO ;
Signature · 1 line
2.47.1
Quoted 56 lines · Michal Suchánek
Quoted 17 lines · Jarkko Sakkinen
Quoted 16 lines · Michal Suchánek
Quoted 4 lines · Jarkko Sakkinen
Quoted 3 lines · Michal Suchánek
It looks like the
timeout_bis used exclusively as the ready timeout *), with various sources of the value depending on chip type.Quoted 8 lines
Quoted 5 lines
Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of
timeout_bforTPM_STS_VALIDinst33zp24_pm_resume.Possible for you to give a shot for patch and try it out for a while? I'm fine with 2x, or even 4x in this case.
I will see what I can do. It will definitely take a while.
Quoted 8 lines
Quoted 5 lines
How would you like to multiply it?
At the sime the
timeout_bis assigned, or at the time it's used?Any specific patch that you have in mind?
I'll think about this a bit and send a patch with RFC tag. Might take to late next week.
The ready timeout is not the only one exceeded:
Quoted 18 lines
Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2232 of 2000 ms) Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2232 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Timed out (2228 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Took (2228 of 2000 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (2224 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (2224 of 200 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2228 of 2000 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2228 of 2000 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (556 of 200 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (556 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Timed out (272 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Took (272 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms)Quoted 8 lines
Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2236 of 2000 ms) Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2236 of 2000 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (540 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (540 of 200 ms)
Quoted 2 lines
While the ready timeout is quite consistently exceeded by around 230ms so far the stat timeout a few lines lower is less consistent.
Interesting. TPM2_CC_CONTEXT_LOAD (353) / TPM2_CC_FLUSH_CONTEXT (357) / TPM2_CC_CONTEXT_SAVE (354) I kinda expect to maybe take a bit longer, but TPM2_CC_GET_RANDOM (379) is a little surprising.
Quoted 5 lines
Failure is observed with another chip type as well:
localhost kernel:
tpm_tisMSFT0101:00: 2.0 TPM (device-id0x1B, rev-id
22)
Quoted 9 lines
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 7.83
Description: TPM 2.0, ManufacturerID: IFX , Firmware Version: 7.83.3358.0 Characteristics:
Family configurable via firmware update
Family configurable via OEM proprietary mechanism
OEM-specific Information:0x00000000
That looks like an SLB9670, not running the latest firmware (7.85). I think that might have the errata I've been trying to work around; my current patch in testing (with logging to see how effective it is):
commit d8c680ec34e7f42f731e7d64605a670fb7b3b4d1
Author: Jonathan McDowell <[email protected]> Date: Mon Aug 19 09:22:46 2024 -0700
tpm: Workaround failed command reception on Infineon devices
Some Infineon devices have a issue where the status register will get stuck with a quick REQUEST_USE / COMMAND_READY sequence. The work around is to retry the command submission. Add appropriate logic to do this in the send path.
drivers/char/tpm/tpm_tis_core.c +22 -3
@@ -464,7 +464,12 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_VALID , chip->timeout_c, &priv->int_queue, false) <0 ) { - rc = -ETIME ; +if (test_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags)) { +dev_err (&chip->dev,"Timed out waiting for status valid in send, retrying\n" ); + rc = -EAGAIN ; + }else { + rc = -ETIME ; + } goto out_err; } status =tpm_tis_status (chip);
@@ -481,7 +486,13 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_VALID , chip->timeout_c, &priv->int_queue, false) <0 ) { - rc = -ETIME ; + +if (test_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags)) { +dev_err (&chip->dev,"Timed out waiting for status after send, retrying\n" ); + rc = -EAGAIN ; + }else { + rc = -ETIME ; + } goto out_err; } status =tpm_tis_status (chip);
@@ -546,10 +557,13 @@ static int tpm_tis_send_main(struct tpm_chip *chip, const u8 *buf, size_t len)if (rc >=0 )/* Data transfer done successfully */ break ; -else if (rc != -EIO ) +else if (rc != -EAGAIN && rc != -EIO )/* Data transfer failed, not recoverable */ return rc; } +if (try) +dev_info (&chip->dev, +"Took %d attempts to send command\n" , try +1 );/* go and do it */ rc =tpm_tis_write8 (priv,TPM_STS (priv->locality),TPM_STS_GO );
@@ -563,6 +577,8 @@ static int tpm_tis_send_main(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_DATA_AVAIL |TPM_STS_VALID , dur, &priv->read_queue, false) <0 ) { +dev_err (&chip->dev, +"Timed out waiting for command to complete after send\n" ); rc = -ETIME ; goto out_err; }
@@ -1144,6 +1160,9 @@ int tpm_tis_core_init(struct device *dev, struct tpm_tis_data *priv, int irq, priv->timeout_max =TIS_TIMEOUT_MAX_ATML ; } +if (priv->manufacturer_id ==TPM_VID_IFX ) +set_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags); +if (is_bsw ()) { priv->ilb_base_addr =ioremap (INTEL_LEGACY_BLK_BASE_ADDR ,ILB_REMAP_SIZE );
drivers/char/tpm/tpm_tis_core.h +1 -0
@@ -89,6 +89,7 @@ enum tpm_tis_flags {TPM_TIS_INVALID_STATUS =1 ,TPM_TIS_DEFAULT_CANCELLATION =2 ,TPM_TIS_IRQ_TESTED =3 , + TPM_TIS_STATUS_WORKAROUND = 4, }; struct tpm_tis_data {
include/linux/tpm.h +1 -0
@@ -335,6 +335,7 @@ enum tpm2_cc_attrs {#define TPM_VID_WINBOND 0x1050#define TPM_VID_STM 0x104A#define TPM_VID_ATML 0x1114 +#define TPM_VID_IFX 0x15D1enum tpm_chip_flags {TPM_CHIP_FLAG_BOOTSTRAPPED =BIT (0 ),
Signature · 3 lines
Web [ "A true friend knows who you are...but likes you anyway." ] site: https:// [ ] Made by www.earth.li/~noodles/ [ ] HuggieTag 0.0.24
Quoted 57 lines · Jonathan McDowell
Quoted 56 lines · Michal Suchánek
Quoted 17 lines · Jarkko Sakkinen
Quoted 16 lines · Michal Suchánek
Quoted 4 lines · Jarkko Sakkinen
Quoted 3 lines · Michal Suchánek
It looks like the
timeout_bis used exclusively as the ready timeout *), with various sources of the value depending on chip type.Quoted 8 lines
Quoted 5 lines
Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of
timeout_bforTPM_STS_VALIDinst33zp24_pm_resume.Possible for you to give a shot for patch and try it out for a while? I'm fine with 2x, or even 4x in this case.
I will see what I can do. It will definitely take a while.
Quoted 8 lines
Quoted 5 lines
How would you like to multiply it?
At the sime the
timeout_bis assigned, or at the time it's used?Any specific patch that you have in mind?
I'll think about this a bit and send a patch with RFC tag. Might take to late next week.
The ready timeout is not the only one exceeded:
Quoted 26 lines
Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2232 of 2000 ms) Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2232 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Timed out (2228 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Took (2228 of 2000 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (2224 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (2224 of 200 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2228 of 2000 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2228 of 2000 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (556 of 200 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (556 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Timed out (272 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Took (272 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms) Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2236 of 2000 ms) Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2236 of 2000 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (540 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (540 of 200 ms)
Quoted 6 lines
Quoted 2 lines
While the ready timeout is quite consistently exceeded by around 230ms so far the stat timeout a few lines lower is less consistent.
Interesting.
TPM2_CC_CONTEXT_LOAD(353) /TPM2_CC_FLUSH_CONTEXT(357) /TPM2_CC_CONTEXT_SAVE(354) I kinda expect to maybe take a bit longer, butTPM2_CC_GET_RANDOM(379) is a little surprising.
But it only takes extra 72ms, the context functions take about extra 350ms.
Quoted 16 lines
Quoted 6 lines
Failure is observed with another chip type as well:
localhost kernel:
tpm_tisMSFT0101:00: 2.0 TPM (device-id0x1B, rev-id
22)Quoted 9 lines
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 7.83
Description: TPM 2.0, ManufacturerID: IFX , Firmware Version: 7.83.3358.0 Characteristics:
Family configurable via firmware update
Family configurable via OEM proprietary mechanism
OEM-specific Information:0x00000000
Quoted 3 lines
That looks like an SLB9670, not running the latest firmware (7.85). I think that might have the errata I've been trying to work around; my current patch in testing (with logging to see how effective it is):
I don't have any result with timeout waiting for the valid state but all the results with the debug prints are from the newer chip revision.
Thanks
Michal
Quoted 109 lines
commit
d8c680ec34e7f42f731e7d64605a670fb7b3b4d1Author: Jonathan McDowell <[email protected]> Date: Mon Aug 19 09:22:46 2024 -0700tpm: Workaround failed command reception on Infineon devices
Some Infineon devices have a issue where the status register will get stuck with a quick
REQUEST_USE/COMMAND_READYsequence. The work around is to retry the command submission. Add appropriate logic to do this in the send path.drivers/char/tpm/tpm_tis_core.c +22
-3@@ -464,7 +464,12 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_VALID , chip->timeout_c, &priv->int_queue, false) <0 ) { - rc = -ETIME ; +if (test_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags)) { +dev_err (&chip->dev,"Timed out waiting for status valid in send, retrying\n" ); + rc = -EAGAIN ; + }else { + rc = -ETIME ; + } goto out_err; } status =tpm_tis_status (chip);@@ -481,7 +486,13 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_VALID , chip->timeout_c, &priv->int_queue, false) <0 ) { - rc = -ETIME ; + +if (test_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags)) { +dev_err (&chip->dev,"Timed out waiting for status after send, retrying\n" ); + rc = -EAGAIN ; + }else { + rc = -ETIME ; + } goto out_err; } status =tpm_tis_status (chip);@@ -546,10 +557,13 @@ static int tpm_tis_send_main(struct tpm_chip *chip, const u8 *buf, size_t len)if (rc >=0 )/* Data transfer done successfully */ break ; -else if (rc != -EIO ) +else if (rc != -EAGAIN && rc != -EIO )/* Data transfer failed, not recoverable */ return rc; } +if (try) +dev_info (&chip->dev, +"Took %d attempts to send command\n" , try +1 );/* go and do it */ rc =tpm_tis_write8 (priv,TPM_STS (priv->locality),TPM_STS_GO );@@ -563,6 +577,8 @@ static int tpm_tis_send_main(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_DATA_AVAIL |TPM_STS_VALID , dur, &priv->read_queue, false) <0 ) { +dev_err (&chip->dev, +"Timed out waiting for command to complete after send\n" ); rc = -ETIME ; goto out_err; }@@ -1144,6 +1160,9 @@ int tpm_tis_core_init(struct device *dev, struct tpm_tis_data *priv, int irq, priv->timeout_max =TIS_TIMEOUT_MAX_ATML ; } +if (priv->manufacturer_id ==TPM_VID_IFX ) +set_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags); +if (is_bsw ()) { priv->ilb_base_addr =ioremap (INTEL_LEGACY_BLK_BASE_ADDR ,ILB_REMAP_SIZE );drivers/char/tpm/tpm_tis_core.h +1
-0@@ -89,6 +89,7 @@ enum tpm_tis_flags {TPM_TIS_INVALID_STATUS =1 ,TPM_TIS_DEFAULT_CANCELLATION =2 ,TPM_TIS_IRQ_TESTED =3 , + TPM_TIS_STATUS_WORKAROUND = 4, }; struct tpm_tis_data {include/linux/tpm.h +1
-0@@ -335,6 +335,7 @@ enum tpm2_cc_attrs {#define TPM_VID_WINBOND 0x1050#define TPM_VID_STM 0x104A#define TPM_VID_ATML 0x1114 +#define TPM_VID_IFX 0x15D1enum tpm_chip_flags {TPM_CHIP_FLAG_BOOTSTRAPPED =BIT (0 ),Signature · 4 lines
-- Web [ "A true friend knows who you are...but likes you anyway." ] site: https:// [ ] Made by www.earth.li/~noodles/ [ ] HuggieTag 0.0.24
Jarkko Sakkinen
maintainerQuoted 3 lines · Jonathan McDowell
Interesting.
TPM2_CC_CONTEXT_LOAD(353) /TPM2_CC_FLUSH_CONTEXT(357) /TPM2_CC_CONTEXT_SAVE(354) I kinda expect to maybe take a bit longer, butTPM2_CC_GET_RANDOM(379) is a little surprising.
The whole arithmetic with timeout_a/b/c is mostly gibberish and could be replaced with a single "max" constant without issues (just set it large enough).
They could be all be replaced with let's say 3s timeout in a constant.
Quoted 35 lines
Quoted 5 lines
Failure is observed with another chip type as well:
localhost kernel:
tpm_tisMSFT0101:00: 2.0 TPM (device-id0x1B, rev-id
22)Quoted 9 lines
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 7.83
Description: TPM 2.0, ManufacturerID: IFX , Firmware Version: 7.83.3358.0 Characteristics:
Family configurable via firmware update
Family configurable via OEM proprietary mechanism
OEM-specific Information:0x00000000That looks like an SLB9670, not running the latest firmware (7.85). I think that might have the errata I've been trying to work around; my current patch in testing (with logging to see how effective it is):
commit
d8c680ec34e7f42f731e7d64605a670fb7b3b4d1Author: Jonathan McDowell <[email protected]> Date: Mon Aug 19 09:22:46 2024 -0700tpm: Workaround failed command reception on Infineon devices
Some Infineon devices have a issue where the status register will get stuck with a quick
REQUEST_USE/COMMAND_READYsequence. The work around is to retry the command submission. Add appropriate logic to do this in the send path.drivers/char/tpm/tpm_tis_core.c +0
-0
drivers/char/tpm/tpm_tis_core.c static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len) · line 469
Quoted 7 lines
drivers/char/tpm/tpm_tis_core.c +3
-1@@ -464,7 +464,12 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_VALID , chip->timeout_c, &priv->int_queue, false) <0 ) { - rc = -ETIME ; +if (test_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags)) { +dev_err (&chip->dev,"Timed out waiting for status valid in send, retrying\n" ); + rc = -EAGAIN ;
I'm not sure why wait_for_tpm_stat() return value is ignored but it should not be like that. E.g. it can return -ERESTARTSYS. Probably would be better to check all the call sites for it that they do same thing.
I.e. rc = wait_for_tpm_stat(...);
/* ... */
BR, Jarkko
Quoted 10 lines · Jarkko Sakkinen
Quoted 3 lines · Jonathan McDowell
Interesting.
TPM2_CC_CONTEXT_LOAD(353) /TPM2_CC_FLUSH_CONTEXT(357) /TPM2_CC_CONTEXT_SAVE(354) I kinda expect to maybe take a bit longer, butTPM2_CC_GET_RANDOM(379) is a little surprising.The whole arithmetic with timeout_a/b/c is mostly gibberish and could be replaced with a single "max" constant without issues (just set it large enough).
They could be all be replaced with let's say 3s timeout in a constant.
This appears to have come up before:
That patch was deemed overly complex and it was suggested to split it up; I can't find any indication that was ever done which I guess is why the discussion died off.
Quoted 49 lines
Quoted 35 lines
Quoted 5 lines
Failure is observed with another chip type as well:
localhost kernel:
tpm_tisMSFT0101:00: 2.0 TPM (device-id0x1B, rev-id
22)Quoted 9 lines
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 7.83
Description: TPM 2.0, ManufacturerID: IFX , Firmware Version: 7.83.3358.0 Characteristics:
Family configurable via firmware update
Family configurable via OEM proprietary mechanism
OEM-specific Information:0x00000000That looks like an SLB9670, not running the latest firmware (7.85). I think that might have the errata I've been trying to work around; my current patch in testing (with logging to see how effective it is):
commit
d8c680ec34e7f42f731e7d64605a670fb7b3b4d1Author: Jonathan McDowell <[email protected]> Date: Mon Aug 19 09:22:46 2024 -0700tpm: Workaround failed command reception on Infineon devices
Some Infineon devices have a issue where the status register will get stuck with a quick
REQUEST_USE/COMMAND_READYsequence. The work around is to retry the command submission. Add appropriate logic to do this in the send path.drivers/char/tpm/tpm_tis_core.c +0
-0drivers/char/tpm/tpm_tis_core.c static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len) · line 469
Quoted 7 lines
drivers/char/tpm/tpm_tis_core.c +3
-1@@ -464,7 +464,12 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_VALID , chip->timeout_c, &priv->int_queue, false) <0 ) { - rc = -ETIME ; +if (test_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags)) { +dev_err (&chip->dev,"Timed out waiting for status valid in send, retrying\n" ); + rc = -EAGAIN ;I'm not sure why
wait_for_tpm_stat()return value is ignored but it should not be like that. E.g. it can return-ERESTARTSYS. Probably would be better to check all the call sites for it that they do same thing.
Quoted 3 lines
I.e. rc =
wait_for_tpm_stat(...);/* ... */
So just to clarify, this more recent patch is working around a situation where the status register gets stuck and needs a complete retry of the command send - it's an Infineon errata, not something that would be fixed with a longer timeout.
We see what looks like Michal's issue with timeouts as well, I just haven't made the step of instrumenting it all the way he has.
J.
Signature · 4 lines
I have found the monster - the | .''`. Debian GNU/Linux Developer
monster is us. | : :' : Happy to accept PGP signed
| `. `' or encrypted mail - RSA
| `- key on the keyservers.Quoted 12 lines · Jonathan McDowell
Quoted 10 lines · Jarkko Sakkinen
Quoted 3 lines · Jonathan McDowell
Interesting.
TPM2_CC_CONTEXT_LOAD(353) /TPM2_CC_FLUSH_CONTEXT(357) /TPM2_CC_CONTEXT_SAVE(354) I kinda expect to maybe take a bit longer, butTPM2_CC_GET_RANDOM(379) is a little surprising.The whole arithmetic with timeout_a/b/c is mostly gibberish and could be replaced with a single "max" constant without issues (just set it large enough).
They could be all be replaced with let's say 3s timeout in a constant.
Quoted 7 lines
This appears to have come up before:
That patch was deemed overly complex and it was suggested to split it up; I can't find any indication that was ever done which I guess is why the discussion died off.
Also it comes before TPM_LONG_LONG, it sounds like that would still be special.
Quoted 54 lines
Quoted 50 lines
Quoted 36 lines
Quoted 6 lines
Failure is observed with another chip type as well:
localhost kernel:
tpm_tisMSFT0101:00: 2.0 TPM (device-id0x1B, rev-id
22)Quoted 9 lines
TPM Device
Vendor ID: IFX
Specification Version: 2.0
Firmware Revision: 7.83
Description: TPM 2.0, ManufacturerID: IFX , Firmware Version: 7.83.3358.0 Characteristics:
Family configurable via firmware update
Family configurable via OEM proprietary mechanism
OEM-specific Information:0x00000000That looks like an SLB9670, not running the latest firmware (7.85). I think that might have the errata I've been trying to work around; my current patch in testing (with logging to see how effective it is):
commit
d8c680ec34e7f42f731e7d64605a670fb7b3b4d1Author: Jonathan McDowell <[email protected]> Date: Mon Aug 19 09:22:46 2024 -0700tpm: Workaround failed command reception on Infineon devices
Some Infineon devices have a issue where the status register will get stuck with a quick
REQUEST_USE/COMMAND_READYsequence. The work around is to retry the command submission. Add appropriate logic to do this in the send path.drivers/char/tpm/tpm_tis_core.c +0
-0drivers/char/tpm/tpm_tis_core.c static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len) · line 469
Quoted 7 lines
drivers/char/tpm/tpm_tis_core.c +3
-1@@ -464,7 +464,12 @@ static int tpm_tis_send_data(struct tpm_chip *chip, const u8 *buf, size_t len)if (wait_for_tpm_stat (chip,TPM_STS_VALID , chip->timeout_c, &priv->int_queue, false) <0 ) { - rc = -ETIME ; +if (test_bit (TPM_TIS_STATUS_WORKAROUND , &priv->flags)) { +dev_err (&chip->dev,"Timed out waiting for status valid in send, retrying\n" ); + rc = -EAGAIN ;I'm not sure why
wait_for_tpm_stat()return value is ignored but it should not be like that. E.g. it can return-ERESTARTSYS. Probably would be better to check all the call sites for it that they do same thing.Quoted 3 lines
I.e. rc =
wait_for_tpm_stat(...);/* ... */
Quoted 7 lines
So just to clarify, this more recent patch is working around a situation where the status register gets stuck and needs a complete retry of the command send - it's an Infineon errata, not something that would be fixed with a longer timeout.
We see what looks like Michal's issue with timeouts as well, I just haven't made the step of instrumenting it all the way he has.
And I haven't seen the issue that needs re-sending the command so far.
Maybe it happens even less frequently than the excessive processing time.
Fully restarting the syscall would fix both issues but manual restart of the userspace task reportedly did not work so I have my doubts that this method with returning from the syscall would be effective.
Thanks
Michal
Quoted 10 lines · Michal Suchánek
Quoted 7 lines · Jonathan McDowell
So just to clarify, this more recent patch is working around a situation where the status register gets stuck and needs a complete retry of the command send - it's an Infineon errata, not something that would be fixed with a longer timeout.
We see what looks like Michal's issue with timeouts as well, I just haven't made the step of instrumenting it all the way he has.
And I haven't seen the issue that needs re-sending the command so far.
Your SLB9672 is on the latest firmware, which I believe fixes the problem.
Quoted 6 lines
Maybe it happens even less frequently than the excessive processing time.
Fully restarting the syscall would fix both issues but manual restart of the userspace task reportedly did not work so I have my doubts that this method with returning from the syscall would be effective.
Hmmm. I wonder if e3aaebcbb7c6b403416f442d1de70d437ce313a7 (tpm: Clean up TPM space after command failure) would help the userspace restart work. We saw problems with the timeouts affecting the kernel doing the cleanup of the transient handles, meaning we'd then run out of transient slots in the TPM.
If you can reproduce the problem then
tpm2_getcap -T device:/dev/tpm0 handles-transient
will show if that is the case - if it doesn't output anything this isn't what you're hitting.
J.
Signature · 1 line
Inside every living person there's a dead person trying to get out.
Quoted 18 lines · Jonathan McDowell
Quoted 10 lines · Michal Suchánek
Quoted 7 lines · Jonathan McDowell
So just to clarify, this more recent patch is working around a situation where the status register gets stuck and needs a complete retry of the command send - it's an Infineon errata, not something that would be fixed with a longer timeout.
We see what looks like Michal's issue with timeouts as well, I just haven't made the step of instrumenting it all the way he has.
And I haven't seen the issue that needs re-sending the command so far.
Your SLB9672 is on the latest firmware, which I believe fixes the problem.
Quoted 3 lines
Maybe it happens even less frequently than the excessive processing time.
Quoted 6 lines
Quoted 3 lines
Fully restarting the syscall would fix both issues but manual restart of the userspace task reportedly did not work so I have my doubts that this method with returning from the syscall would be effective.
Hmmm. I wonder if
e3aaebcbb7c6b403416f442d1de70d437ce313a7(tpm: Clean up TPM space after command failure) would help the userspace restart
It's backported to the frankenkernel already so it would not help this particular case.
Unfortunately, it's not clear what the userspace task does, and why it would not complete after the first failure.
Would need to come up with some way of tracing it.
Thanks
Michal
Quoted 26 lines · Michal Suchánek
Quoted 18 lines · Jonathan McDowell
Quoted 10 lines · Michal Suchánek
Quoted 7 lines · Jonathan McDowell
So just to clarify, this more recent patch is working around a situation where the status register gets stuck and needs a complete retry of the command send - it's an Infineon errata, not something that would be fixed with a longer timeout.
We see what looks like Michal's issue with timeouts as well, I just haven't made the step of instrumenting it all the way he has.
And I haven't seen the issue that needs re-sending the command so far.
Your SLB9672 is on the latest firmware, which I believe fixes the problem.
Quoted 3 lines
Maybe it happens even less frequently than the excessive processing time.
Quoted 6 lines
Quoted 3 lines
Fully restarting the syscall would fix both issues but manual restart of the userspace task reportedly did not work so I have my doubts that this method with returning from the syscall would be effective.
Hmmm. I wonder if
e3aaebcbb7c6b403416f442d1de70d437ce313a7(tpm: Clean up TPM space after command failure) would help the userspace restart
Quoted 7 lines
It's backported to the frankenkernel already so it would not help this particular case.
Unfortunately, it's not clear what the userspace task does, and why it would not complete after the first failure.
Would need to come up with some way of tracing it.
FWIW bpftrace is great for this. I'm using the attached script as a basis for investigations. Obviously the timings it reports are the whole command rather than just the wait for status, but over a long period it can then show you the latency histogram. (Run it in one terminal, do TPM stuff elsewhere, hit Ctrl-C when you're done and it dumps the histogram.)
J.
Signature · 1 line
101 things you can't have too much of : 47 - More coffee.
#!/usr/bin/bpftrace
struct tpm_header {
uint8_t tag[2];
uint8_t length[4];
uint8_t ordinal[4];
}
struct tpm_buf {
uint32_t flags;
uint32_t length;
struct tpm_header *hdr;
}kprobe:tpm_transmit_cmd
{
$buf = (struct tpm_buf *) arg1;
printf("%s (0x%02X%02X%02X%02X) (%s)\n", comm,
$buf->hdr->ordinal[0],
$buf->hdr->ordinal[1],
$buf->hdr->ordinal[2],
$buf->hdr->ordinal[3],
str(arg3));
}kprobe:tpm_transmit
{
$hdr = (struct tpm_header *) arg1;
$cmd = $hdr->ordinal[0] << 24 | $hdr->ordinal[1] << 16 |
$hdr->ordinal[2] << 8 | $hdr->ordinal[3];
@start[tid] = nsecs;
@tpmcmd[tid] = $cmd;
}kretprobe:tpm_transmit
/@start[tid]/ {
$dur = nsecs - @start[tid];
@cmdhist[@tpmcmd[tid]] = hist($dur);
printf("%s (0x%08X): %d (%d ns)\n", comm, @tpmcmd[tid], retval, $dur);
delete(@start[tid]);
delete(@tpmcmd[tid]);
}Jarkko Sakkinen
maintainerQuoted 8 lines · Jonathan McDowell
FWIW bpftrace is great for this. I'm using the attached script as a basis for investigations. Obviously the timings it reports are the whole command rather than just the wait for status, but over a long period it can then show you the latency histogram. (Run it in one terminal, do TPM stuff elsewhere, hit Ctrl-C when you're done and it dumps the histogram.)
J.
Yes, I used that to trace and spot issues with HMAC integrity protection in the near past.
BR, Jarkko
Jarkko Sakkinen
maintainerQuoted 6 lines · Jonathan McDowell
Quoted 5 lines
The whole arithmetic with timeout_a/b/c is mostly gibberish and could be replaced with a single "max" constant without issues (just set it large enough).
They could be all be replaced with let's say 3s timeout in a constant.
Quoted 7 lines
This appears to have come up before:
That patch was deemed overly complex and it was suggested to split it up; I can't find any indication that was ever done which I guess is why the discussion died off.
Looking back I suggest splitting timeouts and durations into separate patches:
https://lore.kernel.org/linux-integrity/[email protected]/
Quoted 4 lines
So just to clarify, this more recent patch is working around a situation where the status register gets stuck and needs a complete retry of the command send - it's an Infineon errata, not something that would be fixed with a longer timeout.
Hmm... please shout if I ignore something but if we could -ERESTARTSYS semantics here that should ignite completely new transmit flow, wouldn't it?
I'm not seeing this locally so far unfortunately.
BR, Jarkko
Quoted 11 lines · Jarkko Sakkinen
Quoted 10 lines · Jonathan McDowell
Quoted 5 lines
The whole arithmetic with timeout_a/b/c is mostly gibberish and could be replaced with a single "max" constant without issues (just set it large enough).
They could be all be replaced with let's say 3s timeout in a constant.
This appears to have come up before:
Quoted 8 lines
Quoted 3 lines
That patch was deemed overly complex and it was suggested to split it up; I can't find any indication that was ever done which I guess is why the discussion died off.
Looking back I suggest splitting timeouts and durations into separate patches:
Yup, that seems to be where it all died out from what I could find.
Quoted 8 lines
Quoted 4 lines
So just to clarify, this more recent patch is working around a situation where the status register gets stuck and needs a complete retry of the command send - it's an Infineon errata, not something that would be fixed with a longer timeout.
Hmm... please shout if I ignore something but if we could
-ERESTARTSYSsemantics here that should ignite completely new transmit flow, wouldn't it?
Who then handles the ERESTARTSYS though? Part of the issues we've seen is the failure happens in a context save or load, which is all within the kernel rather than directly under the control of userspace. I'm guessing the HMAC changes are likely to hit similar problems. I think some level of timeout improvement in tpm_transmit is appropriate, if we can work out what it should be.
Likewise for the Infineon errata I think an internal retry makes sense, because it could happen for a number of internally generated kernel reasons as well as a userspace sent command.
J.
Signature · 1 line
How I wish, how I wish you were here.
Jarkko Sakkinen
maintainerQuoted 6 lines · Jonathan McDowell
Who then handles the ERESTARTSYS though? Part of the issues we've seen is the failure happens in a context save or load, which is all within the kernel rather than directly under the control of userspace. I'm guessing the HMAC changes are likely to hit similar problems. I think some level of timeout improvement in
tpm_transmitis appropriate, if we can work out what it should be.
Right I get what you mean, not all transmits initiate from syscalls And obviously this can happen without hmac too with tpmrm0.
Hmm... so I'm open for a patch that radically simplifies the state change timeouts, i.e. sort of part of that old patch.
BR, Jarkko
Quoted 8 lines · Jarkko Sakkinen
Quoted 6 lines · Jonathan McDowell
Who then handles the ERESTARTSYS though? Part of the issues we've seen is the failure happens in a context save or load, which is all within the kernel rather than directly under the control of userspace. I'm guessing the HMAC changes are likely to hit similar problems. I think some level of timeout improvement in
tpm_transmitis appropriate, if we can work out what it should be.
Quoted 5 lines
Right I get what you mean, not all transmits initiate from syscalls And obviously this can happen without hmac too with tpmrm0.
Hmm... so I'm open for a patch that radically simplifies the state change timeouts, i.e. sort of part of that old patch.
There is also another aspect to this:
What happens when the context save/load result is dropped on the floor?
There was other call that can take a very long time: get random number. And while dropping a random number that took a long time ito fabricate on the floor is wasteful it does not cause any real problem.
With the context save/load, however, the context state gets desynchronized between TPM and kernel when the result of the call is ignored.
If the kernel cannot correct the state by examining return value from later calls the TPM can effectively become defunct because the kernel will call the wrong context operation, it will return unexpected value which the kernel interprets as failure, and no operation can be performed.
Thanks
Michal
Jarkko Sakkinen
maintainerQuoted 12 lines · Michal Suchánek
Quoted 11 lines · Jarkko Sakkinen
Quoted 6 lines · Jonathan McDowell
Who then handles the ERESTARTSYS though? Part of the issues we've seen is the failure happens in a context save or load, which is all within the kernel rather than directly under the control of userspace. I'm guessing the HMAC changes are likely to hit similar problems. I think some level of timeout improvement in
tpm_transmitis appropriate, if we can work out what it should be.Right I get what you mean, not all transmits initiate from syscalls And obviously this can happen without hmac too with tpmrm0.
Quoted 6 lines
Quoted 2 lines
Hmm... so I'm open for a patch that radically simplifies the state change timeouts, i.e. sort of part of that old patch.
There is also another aspect to this:
What happens when the context save/load result is dropped on the floor?
Trying to understand what are you meaning by this. Are you speaking about scenario where after the operation context operations fail inside kernel?
Quoted 9 lines
There was other call that can take a very long time: get random number. And while dropping a random number that took a long time ito fabricate on the floor is wasteful it does not cause any real problem.
With the context save/load, however, the context state gets desynchronized between TPM and kernel when the result of the call is ignored.
Quoted 5 lines
If the kernel cannot correct the state by examining return value from later calls the TPM can effectively become defunct because the kernel will call the wrong context operation, it will return unexpected value which the kernel interprets as failure, and no operation can be performed.
I got lost in the beginning so not yet sure about this (not same as rejecting, also I'm responding from holiday).
Not really sure if this related but I'll just this here.
We could possibly identify some expensive TPM commands that fill these requirements:
1. Don't run in a session.
2. Don't cause handles to be created (neither sessions nor objects).
and executed as they were put to /dev/tpm0. At least we might be able to do this for TPM2_GetRandom.
Quoted 4 lines
Thanks
Michal
BR, Jarkko
Quoted 16 lines · Jarkko Sakkinen
Quoted 15 lines · Michal Suchánek
Quoted 13 lines · Jarkko Sakkinen
Quoted 6 lines · Jonathan McDowell
Who then handles the ERESTARTSYS though? Part of the issues we've seen is the failure happens in a context save or load, which is all within the kernel rather than directly under the control of userspace. I'm guessing the HMAC changes are likely to hit similar problems. I think some level of timeout improvement in
tpm_transmitis appropriate, if we can work out what it should be.Right I get what you mean, not all transmits initiate from syscalls And obviously this can happen without hmac too with tpmrm0.
Hmm... so I'm open for a patch that radically simplifies the state change timeouts, i.e. sort of part of that old patch.
Quoted 7 lines
Quoted 3 lines
There is also another aspect to this:
What happens when the context save/load result is dropped on the floor?
Trying to understand what are you meaning by this. Are you speaking about scenario where after the operation context operations fail inside kernel?
I am speaking about the scenario when the opration succeeds but the kernel declares it a failure because it did not happen within the timeout.
Thanks
Michal
Jarkko Sakkinen
maintainerQuoted 21 lines · Michal Suchánek
Quoted 20 lines · Jarkko Sakkinen
Quoted 18 lines · Michal Suchánek
Quoted 8 lines · Jarkko Sakkinen
Quoted 6 lines · Jonathan McDowell
Who then handles the ERESTARTSYS though? Part of the issues we've seen is the failure happens in a context save or load, which is all within the kernel rather than directly under the control of userspace. I'm guessing the HMAC changes are likely to hit similar problems. I think some level of timeout improvement in
tpm_transmitis appropriate, if we can work out what it should be.Quoted 5 lines
Right I get what you mean, not all transmits initiate from syscalls And obviously this can happen without hmac too with tpmrm0.
Hmm... so I'm open for a patch that radically simplifies the state change timeouts, i.e. sort of part of that old patch.
There is also another aspect to this:
What happens when the context save/load result is dropped on the floor?
Quoted 7 lines
Quoted 3 lines
Trying to understand what are you meaning by this. Are you speaking about scenario where after the operation context operations fail inside kernel?
I am speaking about the scenario when the opration succeeds but the kernel declares it a failure because it did not happen within the timeout.
OK got it, thanks.
I guess theoretically we could even never do timeout and let the caller SIGINT.
Quoted 4 lines
Thanks
Michal
BR, Jarkko
Hello,
Quoted 48 lines · Jonathan McDowell
Quoted 47 lines · Michal Suchánek
Quoted 17 lines · Jarkko Sakkinen
Quoted 16 lines · Michal Suchánek
Quoted 4 lines · Jarkko Sakkinen
Quoted 3 lines · Michal Suchánek
It looks like the
timeout_bis used exclusively as the ready timeout *), with various sources of the value depending on chip type.Quoted 8 lines
Quoted 5 lines
Then increasing it should not cause any problem other than the kernel waiting longer when the TPM chip is really stuck.
* There is one instance of use of
timeout_bforTPM_STS_VALIDinst33zp24_pm_resume.Possible for you to give a shot for patch and try it out for a while? I'm fine with 2x, or even 4x in this case.
I will see what I can do. It will definitely take a while.
Quoted 8 lines
Quoted 5 lines
How would you like to multiply it?
At the sime the
timeout_bis assigned, or at the time it's used?Any specific patch that you have in mind?
I'll think about this a bit and send a patch with RFC tag. Might take to late next week.
The ready timeout is not the only one exceeded:
Quoted 18 lines
Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2232 of 2000 ms) Jan 29 19:01:55 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2232 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Timed out (2228 of 2000 ms) Jan 30 09:08:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: ready: Took (2228 of 2000 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Jan 30 14:26:16 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (2224 of 200 ms) Jan 30 23:25:13 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (2224 of 200 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2228 of 2000 ms) Feb 01 05:25:33 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2228 of 2000 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (556 of 200 ms) Feb 01 07:02:53 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (556 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 01 09:26:22 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Timed out (272 of 200 ms) Feb 02 02:45:35 localhost kernel: tpm tpm0: tpm_tis_send_data: 379: stat: Took (272 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 03:40:04 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms)
Quoted 8 lines
Quoted 8 lines
Quoted 8 lines
Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Timed out (2236 of 2000 ms) Feb 02 04:09:50 localhost kernel: tpm tpm0: tpm_tis_send_data: 357: ready: Took (2236 of 2000 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (540 of 200 ms) Feb 02 09:57:41 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (540 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Timed out (536 of 200 ms) Feb 02 10:59:00 localhost kernel: tpm tpm0: tpm_tis_send_data: 353: stat: Took (536 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Timed out (540 of 200 ms) Feb 03 03:58:09 localhost kernel: tpm tpm0: tpm_tis_send_data: 354: stat: Took (540 of 200 ms)
Another new failure:
Mar 25 23:06:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 305: valid: Timed out (212 of 200 ms) Mar 25 23:06:20 localhost kernel: tpm tpm0: tpm_tis_send_data: 305: valid: Took (212 of 200 ms)
which is CREATE PRIMARY, and happens on
tpm_tis MSFT0101:00: 2.0 TPM (device-id 0x1A, rev-id 16)
TPM Device
Vendor ID:
Specification Version: 2.0
Firmware Revision: 5.63
Description: INFINEON
Characteristics:
Family configurable via platform software support
OEM-specific Information: 0x00000000
With this we have ready timoeout which is 2000ms but the TPM takes up to 2236ms, stat timeout which is 200ms and the TPM takes up to 2224ms, and valid timeout which is 200 ms and the TPM takes up to 212ms.
Given that I think it makes sense to replace all these timeouts with one timeout that is something like 4 or 5s.
This does not address the other problem that when the rimeout triggers on something like LOAD CONTEXT then the kernel and the TPM don't agree on what the state of the context is.
Thanks
Michal
Jarkko Sakkinen
maintainerQuoted 3 lines · Michal Suchánek
This does not address the other problem that when the rimeout triggers on something like LOAD CONTEXT then the kernel and the TPM don't agree on what the state of the context is.
In the case of tpm2-sessions, and in-kernel callers, we could try to improve the situation in some of the edge cases.
Out-of-my sleeve ideas:
1. E.g., tpm2_load_null() could potentially have retries instead of single trial.
2. Perhaps timeout in tpm_tis should be adaptive? It could be by defaault 2s and would grow on trials.
Quoted 4 lines
Thanks
Michal
BR, Jarkko
Quoted 11 lines · Michal Suchánek
Hello,
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.
Quoted 6 lines
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.
Michal, can you possibly try the below and see if it helps out? There seems to be a timing bug introduced in 6.4+ that I think might be related, and matches up with some of our internal metrics that showed an increase in timeouts in 6.4 onwards.
commit 79041fba797d0fe907e227012767f56dd93fac32
Author: Jonathan McDowell <[email protected]> Date: Wed Feb 19 16:20:44 2025 -0600
tpm, tpm_tis: Fix timeout handling when waiting for TPM status
The change to only use interrupts to handle supported status changes, then switch to polling for the rest, inverted the status test and sleep such that we can end up sleeping beyond our timeout and not actually checking the status. This can result in spurious TPM timeouts, especially on a more loaded system. Fix by switching the order back so we sleep *then* check. We've done a up front check when we enter the function so this won't cause an additional delay when the status is already what we're looking for.
drivers/char/tpm/tpm_tis_core.c +2 -2
@@ -114,11 +114,11 @@ static int wait_for_tpm_stat(struct tpm_chip *chip, u8 mask,return 0 ;/* process status changes without irq support */ do { +usleep_range (priv->timeout_min, + priv->timeout_max); status = chip->ops->status (chip);if ((status & mask) == mask)return 0 ; -usleep_range (priv->timeout_min, - priv->timeout_max); }while (time_before (jiffies, stop));return -ETIME ; }
Hello,
Quoted 16 lines · Jonathan McDowell
Quoted 15 lines · Michal Suchánek
Hello,
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.
Quoted 7 lines
Quoted 2 lines
However, given the problem takes up to a day to reproduce I do not have much confidence in the negative results.
Michal, can you possibly try the below and see if it helps out? There seems to be a timing bug introduced in 6.4+ that I think might be related, and matches up with some of our internal metrics that showed an increase in timeouts in 6.4 onwards.
Thanks for looking into this
Quoted 25 lines
commit
79041fba797d0fe907e227012767f56dd93fac32Author: Jonathan McDowell <[email protected]> Date: Wed Feb 19 16:20:44 2025 -0600tpm,
tpm_tis: Fix timeout handling when waiting for TPM statusThe change to only use interrupts to handle supported status changes, then switch to polling for the rest, inverted the status test and sleep such that we can end up sleeping beyond our timeout and not actually checking the status. This can result in spurious TPM timeouts, especially on a more loaded system. Fix by switching the order back so we sleep *then* check. We've done a up front check when we enter the function so this won't cause an additional delay when the status is already what we're looking for.
Cc [email protected] # v6.4+Fixes e87fcf0dc2b4 ("tpm, tpm_tis: Only handle supported interrupts")Signed-off-by Jonathan McDowell <[email protected]>drivers/char/tpm/tpm_tis_core.c +0
-0
drivers/char/tpm/tpm_tis_core.c static int wait_for_tpm_stat(struct tpm_chip *chip, u8 mask, · line 118
Quoted 5 lines
drivers/char/tpm/tpm_tis_core.c +2
-0@@ -114,11 +114,11 @@ static int wait_for_tpm_stat(struct tpm_chip *chip, u8 mask,return 0 ;/* process status changes without irq support */ do { + usleep_range(priv->timeout_min, + priv->timeout_max);
What would be the priv->timeout_min and priv->timeout_max here?
Note that there are timeouts that are 200ms, and are overblown by 2s.
If the 200ms timeout relies on the sleep during the wait for the timeout being much longer than the timeout itself then the timeout is arguably bogus regardless of this change helping.
Thanks
Michal
Quoted 8 lines
drivers/char/tpm/tpm_tis_core.c +0
-2status = chip->ops->status (chip);if ((status & mask) == mask)return 0 ; -usleep_range (priv->timeout_min, - priv->timeout_max); }while (time_before (jiffies, stop));return -ETIME ; }
Quoted 20 lines · Michal Suchánek
Quoted 19 lines · Jonathan McDowell
Quoted 17 lines · Michal Suchánek
Hello,
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.
Quoted 6 lines
Quoted 4 lines
Michal, can you possibly try the below and see if it helps out? There seems to be a timing bug introduced in 6.4+ that I think might be related, and matches up with some of our internal metrics that showed an increase in timeouts in 6.4 onwards.
Thanks for looking into this
No problem. It's something we've seen in our fleet and I've been trying to get to the bottom of, so having some additional data from someone else is really helpful.
Quoted 32 lines
Quoted 24 lines
commit
79041fba797d0fe907e227012767f56dd93fac32Author: Jonathan McDowell <[email protected]> Date: Wed Feb 19 16:20:44 2025 -0600tpm,
tpm_tis: Fix timeout handling when waiting for TPM statusThe change to only use interrupts to handle supported status changes, then switch to polling for the rest, inverted the status test and sleep such that we can end up sleeping beyond our timeout and not actually checking the status. This can result in spurious TPM timeouts, especially on a more loaded system. Fix by switching the order back so we sleep *then* check. We've done a up front check when we enter the function so this won't cause an additional delay when the status is already what we're looking for.
Cc [email protected] # v6.4+Fixes e87fcf0dc2b4 ("tpm, tpm_tis: Only handle supported interrupts")Signed-off-by Jonathan McDowell <[email protected]>drivers/char/tpm/tpm_tis_core.c +0
-0drivers/char/tpm/tpm_tis_core.c static int wait_for_tpm_stat(struct tpm_chip *chip, u8 mask, · line 118
Quoted 5 lines
drivers/char/tpm/tpm_tis_core.c +2
-0@@ -114,11 +114,11 @@ static int wait_for_tpm_stat(struct tpm_chip *chip, u8 mask,return 0 ;/* process status changes without irq support */ do { + usleep_range(priv->timeout_min, + priv->timeout_max);What would be the
priv->timeout_minandpriv->timeout_maxhere?
Quoted 5 lines
Note that there are timeouts that are 200ms, and are overblown by 2s.
If the 200ms timeout relies on the sleep during the wait for the timeout being much longer than the timeout itself then the timeout is arguably bogus regardless of this change helping.
Ah, I thought your major issue was the 2s timeout that was only slightly exceeded.
However in my initial tracing I've seen wait_for_tpm_stat take much longer than the timeout that's passed in, which is what caused me to go and investigate this code path and note it had been changed in 6.4. It seems like a bug either way, but I've been at the TCG meeting this week and not had time to do further instrumentation and confirmation. Given you seem to have a more reliable reproducer I thought it might be easy enough for you to see if it made any difference.
J.
Signature · 1 line
Why do I get the feeling I'm going to regret this?
Quoted 73 lines · Jonathan McDowell
Quoted 20 lines · Michal Suchánek
Quoted 19 lines · Jonathan McDowell
Quoted 17 lines · Michal Suchánek
Hello,
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.
Quoted 6 lines
Quoted 4 lines
Michal, can you possibly try the below and see if it helps out? There seems to be a timing bug introduced in 6.4+ that I think might be related, and matches up with some of our internal metrics that showed an increase in timeouts in 6.4 onwards.
Thanks for looking into this
No problem. It's something we've seen in our fleet and I've been trying to get to the bottom of, so having some additional data from someone else is really helpful.
Quoted 32 lines
Quoted 24 lines
commit
79041fba797d0fe907e227012767f56dd93fac32Author: Jonathan McDowell <[email protected]> Date: Wed Feb 19 16:20:44 2025 -0600tpm,
tpm_tis: Fix timeout handling when waiting for TPM statusThe change to only use interrupts to handle supported status changes, then switch to polling for the rest, inverted the status test and sleep such that we can end up sleeping beyond our timeout and not actually checking the status. This can result in spurious TPM timeouts, especially on a more loaded system. Fix by switching the order back so we sleep *then* check. We've done a up front check when we enter the function so this won't cause an additional delay when the status is already what we're looking for.
Cc [email protected] # v6.4+Fixes e87fcf0dc2b4 ("tpm, tpm_tis: Only handle supported interrupts")Signed-off-by Jonathan McDowell <[email protected]>drivers/char/tpm/tpm_tis_core.c +0
-0drivers/char/tpm/tpm_tis_core.c static int wait_for_tpm_stat(struct tpm_chip *chip, u8 mask, · line 118
Quoted 5 lines
drivers/char/tpm/tpm_tis_core.c +2
-0@@ -114,11 +114,11 @@ static int wait_for_tpm_stat(struct tpm_chip *chip, u8 mask,return 0 ;/* process status changes without irq support */ do { + usleep_range(priv->timeout_min, + priv->timeout_max);What would be the
priv->timeout_minandpriv->timeout_maxhere?Quoted 5 lines
Note that there are timeouts that are 200ms, and are overblown by 2s.
If the 200ms timeout relies on the sleep during the wait for the timeout being much longer than the timeout itself then the timeout is arguably bogus regardless of this change helping.
Ah, I thought your major issue was the 2s timeout that was only slightly exceeded.
Quoted 7 lines
However in my initial tracing I've seen
wait_for_tpm_stattake much longer than the timeout that's passed in, which is what caused me to go and investigate this code path and note it had been changed in 6.4. It seems like a bug either way, but I've been at the TCG meeting this week and not had time to do further instrumentation and confirmation. Given you seem to have a more reliable reproducer I thought it might be easy enough for you to see if it made any difference.
The problem is no longer reproducible, probably due to some other hcange in the test environment. So much for reliable reproducer.
Yes, I think this is a bug either way and should be addressed although the effect on this problem is minor at best.
Thanks
Michal
Michal Suchánek
Reviewed-byQuoted 39 lines · Jonathan McDowell
Quoted 11 lines · Michal Suchánek
Hello,
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.
Quoted 6 lines
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.
Michal, can you possibly try the below and see if it helps out? There seems to be a timing bug introduced in 6.4+ that I think might be related, and matches up with some of our internal metrics that showed an increase in timeouts in 6.4 onwards.
commit
79041fba797d0fe907e227012767f56dd93fac32Author: Jonathan McDowell <[email protected]> Date: Wed Feb 19 16:20:44 2025 -0600tpm,
tpm_tis: Fix timeout handling when waiting for TPM statusThe change to only use interrupts to handle supported status changes, then switch to polling for the rest, inverted the status test and sleep such that we can end up sleeping beyond our timeout and not actually checking the status. This can result in spurious TPM timeouts, especially on a more loaded system. Fix by switching the order back so we sleep *then* check. We've done a up front check when we enter the function so this won't cause an additional delay when the status is already what we're looking for.
Quoted 3 lines
Cc [email protected] # v6.4+Fixes e87fcf0dc2b4 ("tpm, tpm_tis: Only handle supported interrupts")Signed-off-by Jonathan McDowell <[email protected]>
Thanks
Quoted 19 lines
drivers/char/tpm/tpm_tis_core.c +2
-2@@ -114,11 +114,11 @@ static int wait_for_tpm_stat(struct tpm_chip *chip, u8 mask,return 0 ;/* process status changes without irq support */ do { +usleep_range (priv->timeout_min, + priv->timeout_max); status = chip->ops->status (chip);if ((status & mask) == mask)return 0 ; -usleep_range (priv->timeout_min, - priv->timeout_max); }while (time_before (jiffies, stop));return -ETIME ; }
Jarkko Sakkinen
maintainerQuoted 40 lines · Michal Suchánek
Quoted 39 lines · Jonathan McDowell
Quoted 11 lines · Michal Suchánek
Hello,
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.
Quoted 6 lines
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.
Michal, can you possibly try the below and see if it helps out? There seems to be a timing bug introduced in 6.4+ that I think might be related, and matches up with some of our internal metrics that showed an increase in timeouts in 6.4 onwards.
commit
79041fba797d0fe907e227012767f56dd93fac32Author: Jonathan McDowell <[email protected]> Date: Wed Feb 19 16:20:44 2025 -0600tpm,
tpm_tis: Fix timeout handling when waiting for TPM statusThe change to only use interrupts to handle supported status changes, then switch to polling for the rest, inverted the status test and sleep such that we can end up sleeping beyond our timeout and not actually checking the status. This can result in spurious TPM timeouts, especially on a more loaded system. Fix by switching the order back so we sleep *then* check. We've done a up front check when we enter the function so this won't cause an additional delay when the status is already what we're looking for.
Quoted 5 lines
Quoted 3 lines
Cc [email protected] # v6.4+Fixes e87fcf0dc2b4 ("tpm, tpm_tis: Only handle supported interrupts")Signed-off-by Jonathan McDowell <[email protected]>Reviewed-by Michal Suchánek <[email protected]>
Send as a proper patch. I've this month mostly on holiday but will be back at work on Monday.
BR, Jarkko