Problems with TPM timeouts

Problems with TPM timeouts

[Jonathan McDowell]

We have been seeing a large number of TPM transmit problems across our
fleet, with frequent

tpm tpm0: tpm_try_transmit: send(): error -62

errors being logged. I don't have an on-demand reproducer, which makes
diagnosis difficult. In almost all cases it's a transient issue, and a
subsequent attempt to execute a command succeeds, but especially when
the kernel resource broker is involved that can still cause problems, as
the kernel is not doing retries here.  Uptime does not seem to be a
factor.

This is not yet using the new HMAC session bits; kernels affected range
from at least 6.9 back to 5.12. Historically we've not paid attention to
TPMs long after initial boot, these days we're now looking at them
throughout the uptime of the machine so perhaps discovering something
that's been latent for a while.

I have a few things to try, which I'll describe below, but running
through them will take several months due to the difficulties in trying
to track the issue down over a production fleet. I'm posting here in
case anyone has any insight or ideas I might have missed.

First, I've seen James' post extending the TPM timeouts back in 2018
(https://lore.kernel.org/linux-integrity/1531329074.3260.9.camel@HansenPartnership.com/),
which doesn't seem to have been picked up. Was an alternative resolution
found, or are you still using this, James?

That was for a Nuvoton device; ours our Infineon devices. The behaviour
is not firmware specific; we see the problem with the latest 7.85
firmware as well as the older 7.62.

Things we are going to try:

 * Direct usage of /dev/tpm0 rather than /dev/tpmrm0. This is not a long
   term solution as we want multiple processes to be able to access the
   TPM, but is easier to deploy. The expectation is this will lower the
   number of issues due to fewer TPM commands being executed, but that
   this is not the root cause.

 * Retrying command submission on status timeout. We've had details of
   an errata where the status register can become stuck, with the work
   around being command resubmission. I've got a patch for this ready to
   test - I'll follow up to this mail with it, but need to actually roll
   it out and test before I'll submit it for inclusion.

 * Instrumenting other timeout points to see if we're hitting a
   different timeout.

J.

-- 
101 things you can't have too much of : 8 - Hard drive space.

[RFC PATCH] tpm: Workaround failed command reception on Infineon devices

[Jonathan McDowell]

(I'm still in the process of testing this to confirm it fixes the
errata I've seen, but I wanted to send it out for comments to make sure
it's a reasonable approach.)

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.

Signed-off-by: Jonathan McDowell <noodles@meta.com>
---
 drivers/char/tpm/tpm_tis_core.c | 24 +++++++++++++++++++-----
 drivers/char/tpm/tpm_tis_core.h |  1 +
 include/linux/tpm.h             |  1 +
 3 files changed, 21 insertions(+), 5 deletions(-)

diff --git a/drivers/char/tpm/tpm_tis_core.c b/drivers/char/tpm/tpm_tis_core.c
index f6aa0dfadb93..940abd1a868e 100644
--- a/drivers/char/tpm/tpm_tis_core.c
+++ b/drivers/char/tpm/tpm_tis_core.c
@@ -432,16 +432,27 @@ 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);
-	int rc, status, burstcnt;
+	int rc, status, burstcnt, retry;
+	bool status_fix = test_bit(TPM_TIS_STATUS_WORKAROUND, &priv->flags);
 	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) {
+		retry = status_fix ? 3 : 1;
+
+		while (retry > 0) {
+			tpm_tis_ready(chip);
+			if (wait_for_tpm_stat
+			    (chip, TPM_STS_COMMAND_READY, chip->timeout_b,
+			     &priv->int_queue, false) >= 0) {
+				break;
+			}
+
+			retry--;
+		}
+
+		if (retry == 0) {
 			rc = -ETIME;
 			goto out_err;
 		}
@@ -1147,6 +1158,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);
diff --git a/drivers/char/tpm/tpm_tis_core.h b/drivers/char/tpm/tpm_tis_core.h
index 13e99cf65efe..f888da57535d 100644
--- a/drivers/char/tpm/tpm_tis_core.h
+++ b/drivers/char/tpm/tpm_tis_core.h
@@ -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 {
diff --git a/include/linux/tpm.h b/include/linux/tpm.h
index 4ee9d13749ad..5f4998626a98 100644
--- a/include/linux/tpm.h
+++ b/include/linux/tpm.h
@@ -272,6 +272,7 @@ enum tpm2_cc_attrs {
 #define TPM_VID_WINBOND  0x1050
 #define TPM_VID_STM      0x104A
 #define TPM_VID_ATML     0x1114
+#define TPM_VID_IFX      0x15D1
 
 enum tpm_chip_flags {
 	TPM_CHIP_FLAG_BOOTSTRAPPED		= BIT(0),
-- 
2.39.5

Re: Problems with TPM timeouts

[James Bottomley]

On Wed, 2024-10-02 at 18:03 +0100, Jonathan McDowell wrote:
[...]
> First, I've seen James' post extending the TPM timeouts back in 2018
> (
> https://lore.kernel.org/linux-integrity/1531329074.3260.9.camel@Hansen
> Partnership.com/), which doesn't seem to have been picked up. Was an
> alternative resolution found, or are you still using this, James?

No, because I've got a newer laptop.  The problem was seen on a 2015
XPS-13 with a Nuvoton TPM that was software upgraded to 2.0 (and had
several other problems because of this).  I assumed, based on the lack
of reports from others, that this was a problem specific to my TPM and
so didn't push it.

The annoying thing for me was that the TPM didn't seem to recover. 
Once it started giving timeouts it carried on timing out until machine
reset, which really caused problems because all my keys are TPM
resident.

Is yours a permanent problem like mine, or is it transient (TPM
recovers and comes back)?

Regards,

James

Re: Problems with TPM timeouts

[Jonathan McDowell]

On Wed, Oct 02, 2024 at 10:31:34AM -0700, James Bottomley wrote:
> On Wed, 2024-10-02 at 18:03 +0100, Jonathan McDowell wrote:
> [...]
> > First, I've seen James' post extending the TPM timeouts back in 2018
> > (
> > https://lore.kernel.org/linux-integrity/1531329074.3260.9.camel@Hansen
> > Partnership.com/), which doesn't seem to have been picked up. Was an
> > alternative resolution found, or are you still using this, James?
> 
> No, because I've got a newer laptop.  The problem was seen on a 2015
> XPS-13 with a Nuvoton TPM that was software upgraded to 2.0 (and had
> several other problems because of this).  I assumed, based on the lack
> of reports from others, that this was a problem specific to my TPM and
> so didn't push it.

Yes, there's somewhat a lack of reports of TPM issues but I can't tell
if that's because people aren't using them in anger, or if they're just
not having any issues.

This is seen across thousands of machines, so it's not a specific TPM
issue.

> The annoying thing for me was that the TPM didn't seem to recover. 
> Once it started giving timeouts it carried on timing out until machine
> reset, which really caused problems because all my keys are TPM
> resident.
> 
> Is yours a permanent problem like mine, or is it transient (TPM
> recovers and comes back)?

Ah. So the problem I've described is transient; we get a timeout, that
sometimes causes problems (e.g. the transient space leakage I've
previously sent a patch for), but ultimately the TPM responds just fine
next time.

We _do_ have a separate issue where the TPM returns 0xFFFF for STS, the
kernel does the "invalid TPM_STS.x" with stack thing, then the TPM never
responds to a command again until a machine reboot. However in that
instance it _does_ still respond to reading the TPM_DID_VID register,
and allowing entering/leaving locality, so that looks like it's firmly a
TPM problem of some sort.

J.

-- 
/-\                             | No thanks, I'm already having one.
|@/  Debian GNU/Linux Developer |
\-                              |

Re: [RFC PATCH] tpm: Workaround failed command reception on Infineon devices

[Stefan Berger]

On 10/2/24 1:04 PM, Jonathan McDowell wrote:
> (I'm still in the process of testing this to confirm it fixes the
> errata I've seen, but I wanted to send it out for comments to make sure
> it's a reasonable approach.)
> 
> Some Infineon devices have a issue where the status register will get
> stuck with a quick REQUEST_USE / COMMAND_READY sequence. The work around

Did you tell Infineon about it? Maybe they should have a look at their 
firmware.

What are the TPMs in your fleet doing? I heared that some TPMs 
pre-create keys in the background once users requested a few. I would 
try to create a few primary keys with different combination of key flags 
set and in different hierarchies (and flush them) to use up these 
precreated  keys and see whether that leads to any issues with the TIS 
responsiveness once presumably the device starts creating keys in the 
background...

> is to retry the command submission. Add appropriate logic to do this in

I would describe it as 'retrying to set the TPM_STS_COMMAND_READY flag 
on the TIS STS register' because you are not retring a (TPM) command 
submission, like resubmitting a TPM2_PCR_Extend for example.



> the send path.
> 
> Signed-off-by: Jonathan McDowell <noodles@meta.com>
> ---
>   drivers/char/tpm/tpm_tis_core.c | 24 +++++++++++++++++++-----
>   drivers/char/tpm/tpm_tis_core.h |  1 +
>   include/linux/tpm.h             |  1 +
>   3 files changed, 21 insertions(+), 5 deletions(-)
> 
> diff --git a/drivers/char/tpm/tpm_tis_core.c b/drivers/char/tpm/tpm_tis_core.c
> index f6aa0dfadb93..940abd1a868e 100644
> --- a/drivers/char/tpm/tpm_tis_core.c
> +++ b/drivers/char/tpm/tpm_tis_core.c
> @@ -432,16 +432,27 @@ 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);
> -	int rc, status, burstcnt;
> +	int rc, status, burstcnt, retry;
> +	bool status_fix = test_bit(TPM_TIS_STATUS_WORKAROUND, &priv->flags);

This should probably be moved to the top.
int retry = status_fix ? 3 : 1;

>   	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) {
> +		retry = status_fix ? 3 : 1;
> +
> +		while (retry > 0) {
> +			tpm_tis_ready(chip);
> +			if (wait_for_tpm_stat
> +			    (chip, TPM_STS_COMMAND_READY, chip->timeout_b,
> +			     &priv->int_queue, false) >= 0) {
> +				break;
> +			}
> +
> +			retry--;
> +		}
> +
> +		if (retry == 0) {
>   			rc = -ETIME;
>   			goto out_err;
>   		}
> @@ -1147,6 +1158,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);
> diff --git a/drivers/char/tpm/tpm_tis_core.h b/drivers/char/tpm/tpm_tis_core.h
> index 13e99cf65efe..f888da57535d 100644
> --- a/drivers/char/tpm/tpm_tis_core.h
> +++ b/drivers/char/tpm/tpm_tis_core.h
> @@ -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 {
> diff --git a/include/linux/tpm.h b/include/linux/tpm.h
> index 4ee9d13749ad..5f4998626a98 100644
> --- a/include/linux/tpm.h
> +++ b/include/linux/tpm.h
> @@ -272,6 +272,7 @@ enum tpm2_cc_attrs {
>   #define TPM_VID_WINBOND  0x1050
>   #define TPM_VID_STM      0x104A
>   #define TPM_VID_ATML     0x1114
> +#define TPM_VID_IFX      0x15D1
>   
>   enum tpm_chip_flags {
>   	TPM_CHIP_FLAG_BOOTSTRAPPED		= BIT(0),

Re: [RFC PATCH] tpm: Workaround failed command reception on Infineon devices

[Stefan Berger]

On 10/3/24 5:59 PM, Stefan Berger wrote:
> 
> 
> On 10/2/24 1:04 PM, Jonathan McDowell wrote:
>> (I'm still in the process of testing this to confirm it fixes the
>> errata I've seen, but I wanted to send it out for comments to make sure
>> it's a reasonable approach.)
>>
>> Some Infineon devices have a issue where the status register will get
>> stuck with a quick REQUEST_USE / COMMAND_READY sequence. The work around
> 
> Did you tell Infineon about it? Maybe they should have a look at their 
> firmware.
> 
> What are the TPMs in your fleet doing? I heared that some TPMs 
> pre-create keys in the background once users requested a few. I would 
> try to create a few primary keys with different combination of key flags 

Actually make this child keys of primary keys:

 > tsscreateprimary
Handle 80000000
 > while :; do time tsscreate -hp 80000000 -si  -opem pubkey.pem ; cat 
pubkey.pem; done

This should give a different key every time and maybe key creation time 
goes up at some point...

> set and in different hierarchies (and flush them) to use up these 
> precreated  keys and see whether that leads to any issues with the TIS 
> responsiveness once presumably the device starts creating keys in the 
> background...
> 
>> is to retry the command submission. Add appropriate logic to do this in
> 
> I would describe it as 'retrying to set the TPM_STS_COMMAND_READY flag 
> on the TIS STS register' because you are not retring a (TPM) command 
> submission, like resubmitting a TPM2_PCR_Extend for example.
> 
> 
> 
>> the send path.
>>
>> Signed-off-by: Jonathan McDowell <noodles@meta.com>
>> ---
>>   drivers/char/tpm/tpm_tis_core.c | 24 +++++++++++++++++++-----
>>   drivers/char/tpm/tpm_tis_core.h |  1 +
>>   include/linux/tpm.h             |  1 +
>>   3 files changed, 21 insertions(+), 5 deletions(-)
>>
>> diff --git a/drivers/char/tpm/tpm_tis_core.c 
>> b/drivers/char/tpm/tpm_tis_core.c
>> index f6aa0dfadb93..940abd1a868e 100644
>> --- a/drivers/char/tpm/tpm_tis_core.c
>> +++ b/drivers/char/tpm/tpm_tis_core.c
>> @@ -432,16 +432,27 @@ 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);
>> -    int rc, status, burstcnt;
>> +    int rc, status, burstcnt, retry;
>> +    bool status_fix = test_bit(TPM_TIS_STATUS_WORKAROUND, &priv->flags);
> 
> This should probably be moved to the top.
> int retry = status_fix ? 3 : 1;
> 
>>       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) {
>> +        retry = status_fix ? 3 : 1;
>> +
>> +        while (retry > 0) {
>> +            tpm_tis_ready(chip);
>> +            if (wait_for_tpm_stat
>> +                (chip, TPM_STS_COMMAND_READY, chip->timeout_b,
>> +                 &priv->int_queue, false) >= 0) {
>> +                break;
>> +            }
>> +
>> +            retry--;
>> +        }
>> +
>> +        if (retry == 0) {
>>               rc = -ETIME;
>>               goto out_err;
>>           }
>> @@ -1147,6 +1158,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);
>> diff --git a/drivers/char/tpm/tpm_tis_core.h 
>> b/drivers/char/tpm/tpm_tis_core.h
>> index 13e99cf65efe..f888da57535d 100644
>> --- a/drivers/char/tpm/tpm_tis_core.h
>> +++ b/drivers/char/tpm/tpm_tis_core.h
>> @@ -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 {
>> diff --git a/include/linux/tpm.h b/include/linux/tpm.h
>> index 4ee9d13749ad..5f4998626a98 100644
>> --- a/include/linux/tpm.h
>> +++ b/include/linux/tpm.h
>> @@ -272,6 +272,7 @@ enum tpm2_cc_attrs {
>>   #define TPM_VID_WINBOND  0x1050
>>   #define TPM_VID_STM      0x104A
>>   #define TPM_VID_ATML     0x1114
>> +#define TPM_VID_IFX      0x15D1
>>   enum tpm_chip_flags {
>>       TPM_CHIP_FLAG_BOOTSTRAPPED        = BIT(0),
> 

Re: [RFC PATCH] tpm: Workaround failed command reception on Infineon devices

[Jonathan McDowell]

On Thu, Oct 03, 2024 at 06:25:14PM -0400, Stefan Berger wrote:
> On 10/3/24 5:59 PM, Stefan Berger wrote:
> > On 10/2/24 1:04 PM, Jonathan McDowell wrote:
> > > (I'm still in the process of testing this to confirm it fixes the
> > > errata I've seen, but I wanted to send it out for comments to make sure
> > > it's a reasonable approach.)
> > > 
> > > Some Infineon devices have a issue where the status register will get
> > > stuck with a quick REQUEST_USE / COMMAND_READY sequence. The work around
> > 
> > Did you tell Infineon about it? Maybe they should have a look at their
> > firmware.

I'm in contact with Infineon, and have their errata under NDA.

> > What are the TPMs in your fleet doing? I heared that some TPMs
> > pre-create keys in the background once users requested a few. I would
> > try to create a few primary keys with different combination of key flags
> 
> Actually make this child keys of primary keys:
> 
> > tsscreateprimary
> Handle 80000000
> > while :; do time tsscreate -hp 80000000 -si  -opem pubkey.pem ; cat
> pubkey.pem; done
> 
> This should give a different key every time and maybe key creation time goes
> up at some point...

We're doing a TPM2_CC_CREATE, but as part of a "seal" operation for some
data, rather than full asymmetric key creation. So I don't think this is
likely to be the cause, but it's given me the idea to see if we are
seeing a spike on a particular command - maybe there's something that's
close to the edge on timings that is occasionally going over. Playing
around with bpftrace seems to give useful data so I'll need to
investigate if I can deploy that to do some monitoring.

Our monitoring is running hourly and does the following TPM2
operations (including the in kernel context switching):

TPM2_CC_SELF_TEST
TPM2_CC_GET_CAPABILITY
TPM2_CC_READ_PUBLIC
TPM2_CC_READ_PUBLIC
TPM2_CC_CREATE
TPM2_CC_LOAD
TPM2_CC_CONTEXT_SAVE
TPM2_CC_FLUSH_CONTEXT
TPM2_CC_CONTEXT_LOAD
TPM2_CC_UNSEAL
TPM2_CC_CONTEXT_SAVE
TPM2_CC_FLUSH_CONTEXT
TPM2_CC_CONTEXT_LOAD
TPM2_CC_FLUSH_CONTEXT
TPM2_CC_CONTEXT_SAVE
TPM2_CC_READ_CLOCK
TPM2_CC_GET_CAPABILITY
TPM2_CC_GET_CAPABILITY
TPM2_CC_GET_CAPABILITY
TPM2_CC_GET_CAPABILITY
TPM2_CC_GET_CAPABILITY
TPM2_CC_GET_CAPABILITY
TPM2_CC_READ_PUBLIC

J.

-- 
If I, um, err. Yeah, it probably rounds down. -- Simon Huggins