Regression in tpm_tis driver: the TPM now fatally offlines itself after a few hours of use
Subsystems (2)
James Bottomley
maintainerFirst a caveat: all my laptop security goes through the TPM, so I'm a much more industrial consumer of the technology than most users, who don't use a TPM at all.
However, since 4.18-rc1 I've been seeing these errors with the TPM:
jejb@jarvis:~> dmesg|grep tpm
[ 3.282605] tpm_tis MSFT0101:00: 2.0 TPM (device-id 0xFE, rev-id 2) [14566.626614] tpm tpm0: Operation Timed out [14566.626621] tpm tpm0: tpm2_load_context: failed with a system error -62 [14568.626607] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626594] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626605] tpm tpm0: tpm2_load_context: failed with a system error -62 [14572.626526] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14577.710441] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14579.710418] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14581.710404] tpm tpm0: tpm_try_transmit: tpm_send: error -62
...
What happens is that I get one command that errors out with ETIME and from that point on every TPM operation always returns -ETIME and it's impossible to recover the TPM by any means except a reboot.
There are only three patches to tpm_tis in the merge window and it looks like reverting this one fixes the problem:
commit 424eaf910c329ab06ad03a527ef45dcf6a328f00
Author: Nayna Jain <[email protected]> Date: Wed May 16 01:51:25 2018 -0400
tpm: reduce polling time to usecs for even finer granularity
As far as I can tell, all that patch does is cause the TPM to be poked far more often to see if it's finished, but something about this rate of poking is causing it to drop off its bus. Based on this theory, I've got a proposed fix which increases the timing parameters so we can maintain the performance benefits of the above patch while remedying the regression (I'll send it as a reply to this report).
Regards,
James
James Bottomley
maintainerPATCH 1/1 tpm.h: increase poll timings to fix tpm_tis regression
tpm_tis regressed recently to the point where the TPM being driven by it falls off the bus and cannot be contacted after some hours of use. This is the failure trace:
jejb@jarvis:~> dmesg|grep tpm
[ 3.282605] tpm_tis MSFT0101:00: 2.0 TPM (device-id 0xFE, rev-id 2) [14566.626614] tpm tpm0: Operation Timed out [14566.626621] tpm tpm0: tpm2_load_context: failed with a system error -62 [14568.626607] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626594] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626605] tpm tpm0: tpm2_load_context: failed with a system error -62 [14572.626526] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14577.710441] tpm tpm0: tpm_try_transmit: tpm_send: error -62
...
The problem is caused by a change that caused us to poke the TPM far more often to see if it's ready. Apparently something about the bus its on and the TPM means that it crashes or falls off the bus if you poke it too often and once this happens, only a reboot will recover it.
The fix I've come up with is to adjust the timings so the TPM no longer falls of the bus. Obviously, this fix works for my Nuvoton NPCT6xxx but that's the only TPM I've tested it with.
--- drivers/char/tpm/tpm.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)
drivers/char/tpm/tpm.h +2 -2
@@ -58,8 +58,8 @@ enum tpm_timeout {TPM_TIMEOUT_RETRY =100 ,/* msecs */ TPM_TIMEOUT_RANGE_US =300 ,/* usecs */ TPM_TIMEOUT_POLL =1 ,/* msecs */ -TPM_TIMEOUT_USECS_MIN =100 ,/* usecs */ - TPM_TIMEOUT_USECS_MAX = 500 /* usecs */ +TPM_TIMEOUT_USECS_MIN =750 ,/* usecs */ + TPM_TIMEOUT_USECS_MAX = 1000, /* usecs */ };/* TPM addresses */
Signature · 1 line
2.13.7
Jason Gunthorpe
reviewerRe: [PATCH] tpm.h: increase poll timings to fix tpm_tis regression
Quoted 13 lines · James Bottomley
tpm_tisregressed recently to the point where the TPM being driven by it falls off the bus and cannot be contacted after some hours of use. This is the failure trace:jejb@jarvis:~> dmesg|grep tpm
[ 3.282605] tpm_tis MSFT0101:00: 2.0 TPM (device-id 0xFE, rev-id 2) [14566.626614] tpm tpm0: Operation Timed out [14566.626621] tpm tpm0: tpm2_load_context: failed with a system error -62 [14568.626607] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626594] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626605] tpm tpm0: tpm2_load_context: failed with a system error -62 [14572.626526] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14577.710441] tpm tpm0: tpm_try_transmit: tpm_send: error -62
Quoted 7 lines
...
The problem is caused by a change that caused us to poke the TPM far more often to see if it's ready. Apparently something about the bus its on and the TPM means that it crashes or falls off the bus if you poke it too often and once this happens, only a reboot will recover it.
I wonder if something about triggering ETIME even once breaks the driver so it can't talk to the chip at all thereafter..
Ie it doesn't abort the command properly and becomes desynced with the TIS execution protocol.
I would be very surprised if polling the TIS status register effects the firmware running inside the chip..
BTW, no interrupt in your latop setup? I'm surprised by that..
Jason
James Bottomley
maintainerRe: [PATCH] tpm.h: increase poll timings to fix tpm_tis regression
Quoted 30 lines · Jason Gunthorpe
Quoted 20 lines · James Bottomley
tpm_tisregressed recently to the point where the TPM being driven by
it falls off the bus and cannot be contacted after some hours of use.
This is the failure trace:jejb@jarvis:~> dmesg|grep tpm
[ 3.282605] tpm_tis MSFT0101:00: 2.0 TPM (device-id 0xFE, rev-id 2) [14566.626614] tpm tpm0: Operation Timed out [14566.626621] tpm tpm0: tpm2_load_context: failed with a system error -62 [14568.626607] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626594] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626605] tpm tpm0: tpm2_load_context: failed with a system error -62 [14572.626526] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14577.710441] tpm tpm0: tpm_try_transmit: tpm_send: error -62...
Quoted 8 lines
The problem is caused by a change that caused us to poke the TPM far
more often to see if it's ready. Apparently something about the bus
its on and the TPM means that it crashes or falls off the bus if you
poke it too often and once this happens, only a reboot will recover it.
Quoted 5 lines
I wonder if something about triggering ETIME even once breaks the driver so it can't talk to the chip at all thereafter..
Ie it doesn't abort the command properly and becomes desynced with the TIS execution protocol.
Yes, I wondered about this, but I don't understand the bus protocol well enough. The tpm-interface:tpm_try_transmit() which throws the first ETIME says after we get that we send chip->ops->cancel() which tpm_tis simply translates to tpm_tis_ready() which also times out. Is there a bigger hammer I can hit it with?
Quoted 1 line
I would be very surprised if polling the TIS status register effects.
Well, I was surprised too, but given the patch that's causing the problem, it was the only explanation I could come up with.
Quoted 4 lines
the firmware running inside the chip..
BTW, no interrupt in your latop setup? I'm surprised by that..
Heh, I hear rumours that most laptops are delivered like this and a large software company might be annoyed enough about the problem to mandate interrupts the next time it produces a hardware requirements spec.
James
Jason Gunthorpe
reviewerRe: [PATCH] tpm.h: increase poll timings to fix tpm_tis regression
Quoted 34 lines · James Bottomley
Quoted 33 lines · Jason Gunthorpe
Quoted 20 lines · James Bottomley
tpm_tisregressed recently to the point where the TPM being driven by
it falls off the bus and cannot be contacted after some hours of use.
This is the failure trace:jejb@jarvis:~> dmesg|grep tpm
[ 3.282605] tpm_tis MSFT0101:00: 2.0 TPM (device-id 0xFE, rev-id 2) [14566.626614] tpm tpm0: Operation Timed out [14566.626621] tpm tpm0: tpm2_load_context: failed with a system error -62 [14568.626607] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626594] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626605] tpm tpm0: tpm2_load_context: failed with a system error -62 [14572.626526] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14577.710441] tpm tpm0: tpm_try_transmit: tpm_send: error -62...
Quoted 8 lines
The problem is caused by a change that caused us to poke the TPM far
more often to see if it's ready. Apparently something about the bus
its on and the TPM means that it crashes or falls off the bus if you
poke it too often and once this happens, only a reboot will recover it.I wonder if something about triggering ETIME even once breaks the driver so it can't talk to the chip at all thereafter..
Quoted 8 lines
Quoted 2 lines
Ie it doesn't abort the command properly and becomes desynced with the TIS execution protocol.
Yes, I wondered about this, but I don't understand the bus protocol well enough. The tpm-interface:tpm_try_transmit() which throws the first ETIME says after we get that we send
chip->ops->cancel()whichtpm_tissimply translates totpm_tis_ready()which also times out. Is there a bigger hammer I can hit it with?
I don't remember off hand.. But this is, IMHO, a better guess than the firmware crashes from reading the status register..
Perhaps reducing the timeout to force a ETIME would prove the theory?
Jason
James Bottomley
maintainerRe: [PATCH] tpm.h: increase poll timings to fix tpm_tis regression
Quoted 47 lines · Jason Gunthorpe
Quoted 46 lines · James Bottomley
Quoted 44 lines · Jason Gunthorpe
Quoted 25 lines · James Bottomley
tpm_tisregressed recently to the point where the TPM being driven
by
it falls off the bus and cannot be contacted after some hours of
use.
This is the failure trace:jejb@jarvis:~> dmesg|grep tpm
[ 3.282605] tpm_tis MSFT0101:00: 2.0 TPM (device-id 0xFE, rev-id 2) [14566.626614] tpm tpm0: Operation Timed out [14566.626621] tpm tpm0: tpm2_load_context: failed with a system error -62 [14568.626607] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626594] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626605] tpm tpm0: tpm2_load_context: failed with a system error -62 [14572.626526] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14577.710441] tpm tpm0: tpm_try_transmit: tpm_send: error -62...
Quoted 12 lines
The problem is caused by a change that caused us to poke the TPM
far
more often to see if it's ready. Apparently something about the
bus
its on and the TPM means that it crashes or falls off the bus if
you
poke it too often and once this happens, only a reboot will recover
it.I wonder if something about triggering ETIME even once breaks the driver so it can't talk to the chip at all thereafter..
Ie it doesn't abort the command properly and becomes desynced with the TIS execution protocol.
Quoted 8 lines
Quoted 5 lines
Yes, I wondered about this, but I don't understand the bus protocol well enough. The tpm-interface:tpm_try_transmit() which throws the first ETIME says after we get that we send
chip->ops->cancel()whichtpm_tissimply translates totpm_tis_ready()which also times out. Is there a bigger hammer I can hit it with?I don't remember off hand.. But this is, IMHO, a better guess than the firmware crashes from reading the status register..
Oh, actually, I think the bus crashes or wedges, not the TPM. I just don't have any tools to probe the LPC.
James
Quoted 1 line
Perhaps reducing the timeout to force a ETIME would prove the theory?
Peter Huewe
maintainerRe: [PATCH] tpm.h: increase poll timings to fix tpm_tis regression
Am 11. Juli 2018 22:39:05 MESZ schrieb James Bottomley <[email protected]>:
Quoted 54 lines · Jason Gunthorpe
Quoted 53 lines · James Bottomley
Quoted 51 lines · Jason Gunthorpe
Quoted 39 lines · James Bottomley
Quoted 25 lines
tpm_tisregressed recently to the point where the TPM being driven
by
it falls off the bus and cannot be contacted after some hours of
use.
This is the failure trace:jejb@jarvis:~> dmesg|grep tpm
[ 3.282605] tpm_tis MSFT0101:00: 2.0 TPM (device-id 0xFE, rev-id 2) [14566.626614] tpm tpm0: Operation Timed out [14566.626621] tpm tpm0: tpm2_load_context: failed with a system error -62 [14568.626607] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626594] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626605] tpm tpm0: tpm2_load_context: failed with a system error -62 [14572.626526] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14577.710441] tpm tpm0: tpm_try_transmit: tpm_send: error -62...
Quoted 12 lines
The problem is caused by a change that caused us to poke the TPM
far
more often to see if it's ready. Apparently something about the
bus
its on and the TPM means that it crashes or falls off the bus if
you
poke it too often and once this happens, only a reboot will recover
it.Quoted 5 lines
I wonder if something about triggering ETIME even once breaks the driver so it can't talk to the chip at all thereafter..
Ie it doesn't abort the command properly and becomes desynced with the TIS execution protocol.
Yes, I wondered about this, but I don't understand the bus protocol well enough. The tpm-interface:tpm_try_transmit() which throws the first ETIME says after we get that we send
chip->ops->cancel()whichtpm_tissimply translates totpm_tis_ready()which also times out. Is there a bigger hammer I can hit it with?
Quoted 6 lines
Quoted 2 lines
I don't remember off hand.. But this is, IMHO, a better guess than the firmware crashes from reading the status register..
Oh, actually, I think the bus crashes or wedges, not the TPM. I just don't have any tools to probe the LPC.
I doubt that your fTPM is actually attached to LPC.
And usually if lpc wedges it takes down your pc with it (from my experience)
I wonder what the contents of the acc and sts registers actually are.
If you want i can send you a small tis 'debug' tool tomorrow.
Quoted 4 lines
James
Quoted 1 line
Perhaps reducing the timeout to force a ETIME would prove the theory?
Signature · 1 line
Sent from my mobile
James Bottomley
maintainerRe: [PATCH] tpm.h: increase poll timings to fix tpm_tis regression
Quoted 6 lines · Peter Huewe
Am 11. Juli 2018 22:39:05 MESZ schrieb James Bottomley <James.Bottoml [email protected]>:
Quoted 3 lines · Jason Gunthorpe
Quoted 2 lines · James Bottomley
Quoted 1 line · Jason Gunthorpe
[...]
Quoted 16 lines
Quoted 16 lines
Quoted 15 lines
Quoted 6 lines
Quoted 5 lines
I wonder if something about triggering ETIME even once breaks the driver so it can't talk to the chip at all thereafter..
Ie it doesn't abort the command properly and becomes desynced with the TIS execution protocol.
Quoted 6 lines
Yes, I wondered about this, but I don't understand the bus protocol well enough. The tpm-interface:tpm_try_transmit() which throws the first ETIME says after we get that we send
chip->ops->cancel()whichtpm_tissimply translates totpm_tis_ready()which also times out. Is there a bigger hammer I can hit it with?I don't remember off hand.. But this is, IMHO, a better guess than the firmware crashes from reading the status register..
Quoted 7 lines
Quoted 3 lines
Oh, actually, I think the bus crashes or wedges, not the TPM. I just don't have any tools to probe the LPC.
I doubt that your fTPM is actually attached to LPC.
And usually if lpc wedges it takes down your pc with it (from my experience)
How do I tell what it is attached to? Sysfs doesn't seem to know but I assume the ACPI information should contain something relevant.
Quoted 4 lines
I wonder what the contents of the acc and sts registers actually are.
If you want i can send you a small tis 'debug' tool tomorrow.
Sure, that would help ... I'm just leafing through the TIS manual now to see if there's anything I can build into the driver.
James
Jason Gunthorpe
reviewerRe: [PATCH] tpm.h: increase poll timings to fix tpm_tis regression
In reply to Peter HueweQuoted 60 lines · Peter Huewe
Am 11. Juli 2018 22:39:05 MESZ schrieb James Bottomley <[email protected]>:
Quoted 57 lines · Jason Gunthorpe
Quoted 55 lines · James Bottomley
Quoted 43 lines · Jason Gunthorpe
Quoted 42 lines · James Bottomley
Quoted 25 lines
tpm_tisregressed recently to the point where the TPM being driven
by
it falls off the bus and cannot be contacted after some hours of
use.
This is the failure trace:jejb@jarvis:~> dmesg|grep tpm
[ 3.282605] tpm_tis MSFT0101:00: 2.0 TPM (device-id 0xFE, rev-id 2) [14566.626614] tpm tpm0: Operation Timed out [14566.626621] tpm tpm0: tpm2_load_context: failed with a system error -62 [14568.626607] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626594] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14570.626605] tpm tpm0: tpm2_load_context: failed with a system error -62 [14572.626526] tpm tpm0: tpm_try_transmit: tpm_send: error -62 [14577.710441] tpm tpm0: tpm_try_transmit: tpm_send: error -62...
Quoted 12 lines
The problem is caused by a change that caused us to poke the TPM
far
more often to see if it's ready. Apparently something about the
bus
its on and the TPM means that it crashes or falls off the bus if
you
poke it too often and once this happens, only a reboot will recover
it.I wonder if something about triggering ETIME even once breaks the driver so it can't talk to the chip at all thereafter..
Quoted 8 lines
Quoted 2 lines
Ie it doesn't abort the command properly and becomes desynced with the TIS execution protocol.
Yes, I wondered about this, but I don't understand the bus protocol well enough. The tpm-interface:tpm_try_transmit() which throws the first ETIME says after we get that we send
chip->ops->cancel()whichtpm_tissimply translates totpm_tis_ready()which also times out. Is there a bigger hammer I can hit it with?I don't remember off hand.. But this is, IMHO, a better guess than the firmware crashes from reading the status register..
Quoted 6 lines
Quoted 3 lines
Oh, actually, I think the bus crashes or wedges, not the TPM. I just don't have any tools to probe the LPC.
I doubt that your fTPM is actually attached to LPC.
And usually if lpc wedges it takes down your pc with it (from my experience)
Yes, agree. Very, very unlikely LPC crashed or wedged.
You could try reading the ID numbers register (eg the source of this data 'device-id 0xFE rev-id 2').
That should be on the HW side of the FIFO bridge and if it returs the same values as boot the bus is not broken, no matter what the bus is.
Jason
Re: [PATCH] tpm.h: increase poll timings to fix tpm_tis regression
In reply to James BottomleyQuoted 5 lines · James Bottomley
Yes, I wondered about this, but I don't understand the bus protocol well enough. The tpm-interface:tpm_try_transmit() which throws the first ETIME says after we get that we send
chip->ops->cancel()whichtpm_tissimply translates totpm_tis_ready()which also times out. Is there a bigger hammer I can hit it with?
tpm_tis_ready() gets called twice and it is unsynced (no wait). Maybe this confuses the chip somehow?
/Jarkko