Topics

Periodic Openssl TPM2 engine failures

Doug Fraser
 

Hello all.

Currently running ibm libtss 1.3.3.1 and openssl engine 2.1.0 connected to openssl 1.0.2 under Alpine 3.8 on 32 bit armhf.

I have tested with engine 2.3.0 and seen similar results.

At a run rate of about 1 of 40 down to 1 of 50 test cases, I get the following failure feedback from the engine.

TPM2_ReadPublic failed with 720963
response code unknown
TPM2_StartAuthSession failed with 720912
TSS_RC_FILE_OPEN - The file could not be opened
Failed to get Key Handle in TPM EC key routines

Is anyone else seeing these error codes pop up?

I'm going to enable tpm-tis tracing in the kernel and see what pops out of there.

Sincerely,

Douglas Fraser

Doug Fraser
 

I should also have noted that the physical TPM is an Infineon SLB9670 20 updated to what I believe is the latest firmware, 7.63.3353

Kernel is 4.14.77-v7+

Modules are:
tpm_tis_spi 16384 0
tpm_tis_core 20480 1 tpm_tis_spi
tpm 57344 2 tpm_tis_spi,tpm_tis_core

-----Original Message-----
From: Doug Fraser
Sent: Thursday, March 14, 2019 3:42 PM
To: openssl-tpm2-engine@groups.io; Ibmtpm20tss-users@...
Subject: Periodic Openssl TPM2 engine failures

Hello all.

Currently running ibm libtss 1.3.3.1 and openssl engine 2.1.0 connected to openssl 1.0.2 under Alpine 3.8 on 32 bit armhf.

I have tested with engine 2.3.0 and seen similar results.

At a run rate of about 1 of 40 down to 1 of 50 test cases, I get the following failure feedback from the engine.

TPM2_ReadPublic failed with 720963
response code unknown
TPM2_StartAuthSession failed with 720912 TSS_RC_FILE_OPEN - The file could not be opened Failed to get Key Handle in TPM EC key routines

Is anyone else seeing these error codes pop up?

I'm going to enable tpm-tis tracing in the kernel and see what pops out of there.

Sincerely,

Douglas Fraser

Doug Fraser
 

And from the kernel....


Mar 14 20:22:07 C05BUB0000A000004124 kern.warn kernel: [ 4876.887354] tpm tpm0: tpm2_load_context: failed with a TPM error 0x01DF
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4876.938901] tpm tpm0: A TPM error (459) occurred flushing context
Mar 14 20:22:07 C05BUB0000A000004124 kern.warn kernel: [ 4876.972604] tpm tpm0: tpm2_load_context: failed with a TPM error 0x01DF
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4876.993230] tpm tpm0: A TPM error (459) occurred flushing context
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4877.020956] tpm tpm0: A TPM error (459) occurred flushing context
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4877.030189] tpm tpm0: tpm_try_transmit: tpm_send: error -5
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4877.040832] tpm tpm0: A TPM error (357) occurred flushing context

At least I have something concrete to look at now....

Note: I have the libtss built with default TPM_DEVICE=/dev/tpmrm0

I am curious why the "tpm0" in the messages above instead of "tpmrm0", but I guess that RM path eventually maps to plan vanilla tpm0.

Douglas

-----Original Message-----
From: Doug Fraser
Sent: Thursday, March 14, 2019 4:00 PM
To: openssl-tpm2-engine@groups.io; Ibmtpm20tss-users@...
Subject: RE: Periodic Openssl TPM2 engine failures

I should also have noted that the physical TPM is an Infineon SLB9670 20 updated to what I believe is the latest firmware, 7.63.3353

Kernel is 4.14.77-v7+

Modules are:
tpm_tis_spi 16384 0
tpm_tis_core 20480 1 tpm_tis_spi
tpm 57344 2 tpm_tis_spi,tpm_tis_core

-----Original Message-----
From: Doug Fraser
Sent: Thursday, March 14, 2019 3:42 PM
To: openssl-tpm2-engine@groups.io; Ibmtpm20tss-users@...
Subject: Periodic Openssl TPM2 engine failures

Hello all.

Currently running ibm libtss 1.3.3.1 and openssl engine 2.1.0 connected to openssl 1.0.2 under Alpine 3.8 on 32 bit armhf.

I have tested with engine 2.3.0 and seen similar results.

At a run rate of about 1 of 40 down to 1 of 50 test cases, I get the following failure feedback from the engine.

TPM2_ReadPublic failed with 720963
response code unknown
TPM2_StartAuthSession failed with 720912 TSS_RC_FILE_OPEN - The file could not be opened Failed to get Key Handle in TPM EC key routines

Is anyone else seeing these error codes pop up?

I'm going to enable tpm-tis tracing in the kernel and see what pops out of there.

Sincerely,

Douglas Fraser

James Bottomley
 

On Thu, 2019-03-14 at 19:42 +0000, Doug Fraser wrote:
Hello all.

Currently running ibm libtss 1.3.3.1 and openssl engine 2.1.0
connected to openssl 1.0.2 under Alpine 3.8 on 32 bit armhf.

I have tested with engine 2.3.0 and seen similar results.

At a run rate of about 1 of 40 down to 1 of 50 test cases, I get the
following failure feedback from the engine.

TPM2_ReadPublic failed with 720963
response code unknown
This isn't actually response code unknown, it's TSS_RC_MALFORMED_PUBLIC
and it means the public structure doesn't match the name.

I've seen this before as a bug in one of the ECC routines where there
was an unnecessary leading zero in a point which is what causes the
name hash to mismatch. But in any case it seems to be a bug worth
tracking down in either the hardware or the IBM TSS.

Probably all the rest of the errors below stem from this, so the above
is what needs root causing.

James


TPM2_StartAuthSession failed with 720912
TSS_RC_FILE_OPEN - The file could not be opened
Failed to get Key Handle in TPM EC key routines

Is anyone else seeing these error codes pop up?

I'm going to enable tpm-tis tracing in the kernel and see what pops
out of there.

Sincerely,

Douglas Fraser


James Bottomley
 

On Thu, 2019-03-14 at 20:30 +0000, Doug Fraser wrote:
And from the kernel....


Mar 14 20:22:07 C05BUB0000A000004124 kern.warn kernel: [ 4876.887354]
tpm tpm0: tpm2_load_context: failed with a TPM error 0x01DF
Oh boy, this is a nasty one: it's TPM_RC_INTEGRITY. It means that the
integrity check failed of the context we're trying to load into the
TPM. I've never seen this in all my stress testing of the in-kernel
resource manager, so it is likely a TPM communication issue, possibly a
bus glitch.

Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4876.938901]
tpm tpm0: A TPM error (459) occurred flushing context
Mar 14 20:22:07 C05BUB0000A000004124 kern.warn kernel: [ 4876.972604]
tpm tpm0: tpm2_load_context: failed with a TPM error 0x01DF
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4876.993230]
tpm tpm0: A TPM error (459) occurred flushing context
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4877.020956]
tpm tpm0: A TPM error (459) occurred flushing context
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4877.030189]
tpm tpm0: tpm_try_transmit: tpm_send: error -5
Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4877.040832]
tpm tpm0: A TPM error (357) occurred flushing context

At least I have something concrete to look at now....

Note: I have the libtss built with default TPM_DEVICE=/dev/tpmrm0

I am curious why the "tpm0" in the messages above instead of
"tpmrm0", but I guess that RM path eventually maps to plan vanilla
tpm0.
It's because the dev_print is on the chip device which is always tpmN
regardless of whether you use /dev/tpmrmN or /dev/tpmN

James

Doug Fraser
 

James, you totally rule!

Thanks. I am going to toss a scope on the SPI leads and poke around. Look at eye patterns and such.
If nothing else, I am going to see what happens if I 'de-clock' the bus. Maybe knock it down by half.

I'll feed back onto this thread whatever I find.

Thanks again!

Douglas

-----Original Message-----
From: James Bottomley <James.Bottomley@...>
Sent: Thursday, March 14, 2019 4:35 PM
To: openssl-tpm2-engine@groups.io; Doug Fraser <doug.fraser@...>; Ibmtpm20tss-users@...
Subject: Re: [openssl-tpm2-engine] Periodic Openssl TPM2 engine failures

On Thu, 2019-03-14 at 20:30 +0000, Doug Fraser wrote:
And from the kernel....


Mar 14 20:22:07 C05BUB0000A000004124 kern.warn kernel: [ 4876.887354]
tpm tpm0: tpm2_load_context: failed with a TPM error 0x01DF
Oh boy, this is a nasty one: it's TPM_RC_INTEGRITY. It means that the integrity check failed of the context we're trying to load into the TPM. I've never seen this in all my stress testing of the in-kernel resource manager, so it is likely a TPM communication issue, possibly a bus glitch.

Mar 14 20:22:07 C05BUB0000A000004124 kern.err kernel: [ 4876.938901]
tpm tpm0: A TPM error (459) occurred flushing context Mar 14 20:22:07
C05BUB0000A000004124 kern.warn kernel: [ 4876.972604] tpm tpm0:
tpm2_load_context: failed with a TPM error 0x01DF Mar 14 20:22:07
C05BUB0000A000004124 kern.err kernel: [ 4876.993230] tpm tpm0: A TPM
error (459) occurred flushing context Mar 14 20:22:07
C05BUB0000A000004124 kern.err kernel: [ 4877.020956] tpm tpm0: A TPM
error (459) occurred flushing context Mar 14 20:22:07
C05BUB0000A000004124 kern.err kernel: [ 4877.030189] tpm tpm0:
tpm_try_transmit: tpm_send: error -5 Mar 14 20:22:07
C05BUB0000A000004124 kern.err kernel: [ 4877.040832] tpm tpm0: A TPM
error (357) occurred flushing context

At least I have something concrete to look at now....

Note: I have the libtss built with default TPM_DEVICE=/dev/tpmrm0

I am curious why the "tpm0" in the messages above instead of "tpmrm0",
but I guess that RM path eventually maps to plan vanilla tpm0.
It's because the dev_print is on the chip device which is always tpmN regardless of whether you use /dev/tpmrmN or /dev/tpmN

James


This email and any files transmitted with it are confidential and intended solely for the use of the individual or entity to whom they are addressed. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient:(a) any dissemination or copying of this message is strictly prohibited; and (b) immediately notify the sender by return message and destroy any copies of this message in any form (electronic, paper or otherwise) that you have. The delivery of this message and its information is neither intended to be nor constitutes a disclosure or waiver of any trade secrets, intellectual property, attorney work product, or attorney-client communications.

Doug Fraser
 

James,

So I had originally set the MAX SPI clock in my DTSI to 10Mhz.
Spec on the part is 40Mhz, and it seemed that 10Mhz would be lots of margin.

The errors were really infrequent even under heavy use, so it took a while to notice they were occurring.

Over the course of this morning I tested at various clock rates.

100Khz, fine,
1Mhz, fine,
5Mhz, fine,
8Mhz, failed more often than at 10Mhz!

So I need to look at the bus with a scope, but I am currently setting at 2Mhz to unblock my users, and then continuing to look at the signal.

Given that it is worse at 8 Mhz than at 10 Mhz, my guess is overshoot and ringing, not slow rise time, but again, that is just a guess at this point.

Thanks again.

Doug

-----Original Message-----
From: openssl-tpm2-engine@groups.io <openssl-tpm2-engine@groups.io> On Behalf Of James Bottomley
Sent: Thursday, March 14, 2019 4:31 PM
To: openssl-tpm2-engine@groups.io; Doug Fraser <doug.fraser@...>; Ibmtpm20tss-users@...
Subject: Re: [openssl-tpm2-engine] Periodic Openssl TPM2 engine failures

On Thu, 2019-03-14 at 19:42 +0000, Doug Fraser wrote:
Hello all.

Currently running ibm libtss 1.3.3.1 and openssl engine 2.1.0
connected to openssl 1.0.2 under Alpine 3.8 on 32 bit armhf.

I have tested with engine 2.3.0 and seen similar results.

At a run rate of about 1 of 40 down to 1 of 50 test cases, I get the
following failure feedback from the engine.

TPM2_ReadPublic failed with 720963
response code unknown
This isn't actually response code unknown, it's TSS_RC_MALFORMED_PUBLIC and it means the public structure doesn't match the name.

I've seen this before as a bug in one of the ECC routines where there was an unnecessary leading zero in a point which is what causes the name hash to mismatch. But in any case it seems to be a bug worth tracking down in either the hardware or the IBM TSS.

Probably all the rest of the errors below stem from this, so the above is what needs root causing.

James


TPM2_StartAuthSession failed with 720912 TSS_RC_FILE_OPEN - The file
could not be opened Failed to get Key Handle in TPM EC key routines

Is anyone else seeing these error codes pop up?

I'm going to enable tpm-tis tracing in the kernel and see what pops
out of there.

Sincerely,

Douglas Fraser






This email and any files transmitted with it are confidential and intended solely for the use of the individual or entity to whom they are addressed. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient:(a) any dissemination or copying of this message is strictly prohibited; and (b) immediately notify the sender by return message and destroy any copies of this message in any form (electronic, paper or otherwise) that you have. The delivery of this message and its information is neither intended to be nor constitutes a disclosure or waiver of any trade secrets, intellectual property, attorney work product, or attorney-client communications.
This email and any files transmitted with it are confidential and intended solely for the use of the individual or entity to whom they are addressed. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient:(a) any dissemination or copying of this message is strictly prohibited; and (b) immediately notify the sender by return message and destroy any copies of this message in any form (electronic, paper or otherwise) that you have. The delivery of this message and its information is neither intended to be nor constitutes a disclosure or waiver of any trade secrets, intellectual property, attorney work product, or attorney-client communications.

Doug Fraser
 

Final note on this issue. Took the clock down to 1Mhz. Sixty four hours of continuous openssl engine testing down to the device, zero errors from the test code and zero warnings or errors from the kernel driver.

I am going to look into signal integrity issues on the board, but clearly there is a signal problem.

Note: given the run time for cipher operations inside the TPM in comparison to data transfer time, there is very little effect on overall performance dropping from 10Mhz to 1Mhz on SPI.

-----Original Message-----
From: openssl-tpm2-engine@groups.io <openssl-tpm2-engine@groups.io> On Behalf Of Doug Fraser
Sent: Friday, March 15, 2019 11:45 AM
To: openssl-tpm2-engine@groups.io; James.Bottomley@...; Ibmtpm20tss-users@...
Subject: Re: [openssl-tpm2-engine] Periodic Openssl TPM2 engine failures

James,

So I had originally set the MAX SPI clock in my DTSI to 10Mhz.
Spec on the part is 40Mhz, and it seemed that 10Mhz would be lots of margin.

The errors were really infrequent even under heavy use, so it took a while to notice they were occurring.

Over the course of this morning I tested at various clock rates.

100Khz, fine,
1Mhz, fine,
5Mhz, fine,
8Mhz, failed more often than at 10Mhz!

So I need to look at the bus with a scope, but I am currently setting at 2Mhz to unblock my users, and then continuing to look at the signal.

Given that it is worse at 8 Mhz than at 10 Mhz, my guess is overshoot and ringing, not slow rise time, but again, that is just a guess at this point.

Thanks again.

Doug

-----Original Message-----
From: openssl-tpm2-engine@groups.io <openssl-tpm2-engine@groups.io> On Behalf Of James Bottomley
Sent: Thursday, March 14, 2019 4:31 PM
To: openssl-tpm2-engine@groups.io; Doug Fraser <doug.fraser@...>; Ibmtpm20tss-users@...
Subject: Re: [openssl-tpm2-engine] Periodic Openssl TPM2 engine failures

On Thu, 2019-03-14 at 19:42 +0000, Doug Fraser wrote:
Hello all.

Currently running ibm libtss 1.3.3.1 and openssl engine 2.1.0
connected to openssl 1.0.2 under Alpine 3.8 on 32 bit armhf.

I have tested with engine 2.3.0 and seen similar results.

At a run rate of about 1 of 40 down to 1 of 50 test cases, I get the
following failure feedback from the engine.

TPM2_ReadPublic failed with 720963
response code unknown
This isn't actually response code unknown, it's TSS_RC_MALFORMED_PUBLIC and it means the public structure doesn't match the name.

I've seen this before as a bug in one of the ECC routines where there was an unnecessary leading zero in a point which is what causes the name hash to mismatch. But in any case it seems to be a bug worth tracking down in either the hardware or the IBM TSS.

Probably all the rest of the errors below stem from this, so the above is what needs root causing.

James


TPM2_StartAuthSession failed with 720912 TSS_RC_FILE_OPEN - The file
could not be opened Failed to get Key Handle in TPM EC key routines

Is anyone else seeing these error codes pop up?

I'm going to enable tpm-tis tracing in the kernel and see what pops
out of there.

Sincerely,

Douglas Fraser






This email and any files transmitted with it are confidential and intended solely for the use of the individual or entity to whom they are addressed. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient:(a) any dissemination or copying of this message is strictly prohibited; and (b) immediately notify the sender by return message and destroy any copies of this message in any form (electronic, paper or otherwise) that you have. The delivery of this message and its information is neither intended to be nor constitutes a disclosure or waiver of any trade secrets, intellectual property, attorney work product, or attorney-client communications.
This email and any files transmitted with it are confidential and intended solely for the use of the individual or entity to whom they are addressed. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient:(a) any dissemination or copying of this message is strictly prohibited; and (b) immediately notify the sender by return message and destroy any copies of this message in any form (electronic, paper or otherwise) that you have. The delivery of this message and its information is neither intended to be nor constitutes a disclosure or waiver of any trade secrets, intellectual property, attorney work product, or attorney-client communications.





This email and any files transmitted with it are confidential and intended solely for the use of the individual or entity to whom they are addressed. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient:(a) any dissemination or copying of this message is strictly prohibited; and (b) immediately notify the sender by return message and destroy any copies of this message in any form (electronic, paper or otherwise) that you have. The delivery of this message and its information is neither intended to be nor constitutes a disclosure or waiver of any trade secrets, intellectual property, attorney work product, or attorney-client communications.