From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from anor.bigon.be ([91.121.173.99]:37759 "EHLO anor.bigon.be" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750871AbdKJIV3 (ORCPT ); Fri, 10 Nov 2017 03:21:29 -0500 Subject: Re: [tpmdd-devel] tpm device not showing up in /dev anymore To: Jerry Snitselaar Cc: Jarkko Sakkinen , Alexander.Steffen@infineon.com, linux-integrity@vger.kernel.org References: <20171014081318.busge2fhteusfjwx@rhwork> <20171023132346.jbqgokwv3ah2oqjo@linux.intel.com> <20171023134515.56siz3m6lhrhnovv@rhwork> <20171024135123.uqail7olnespun4k@linux.intel.com> <20171024145706.na56ff34w5agzo2t@rhwork> <20171024160725.r6kj452jdzpkbb6o@linux.intel.com> <8f4df9a9-c8cd-832f-4c3f-5305fabab7a8@debian.org> <0a6e4771-f871-b3ca-b5b0-26dbd9efa8b1@debian.org> <20171110002820.wtfvb3tv5fcjqecu@localhost.localdomain> <20171110070738.ki5xie4z7yql77fk@localhost.localdomain> From: Laurent Bigonville Message-ID: <9245ef7d-dd34-fa5f-6fd9-bfb9582f910e@debian.org> Date: Fri, 10 Nov 2017 09:21:19 +0100 MIME-Version: 1.0 In-Reply-To: <20171110070738.ki5xie4z7yql77fk@localhost.localdomain> Content-Type: multipart/mixed; boundary="------------D033D66A59EE10C39792CEF7" Sender: linux-integrity-owner@vger.kernel.org List-ID: Le 10/11/17 a 08:07, Jerry Snitselaar a ecrit : > On Thu Nov 09 17, Jerry Snitselaar wrote: >> On Thu Nov 09 17, Laurent Bigonville wrote: >>> Le 09/11/17 a 01:04, Laurent Bigonville a ecrit : >>>> >>>> >>>> Le 24/10/17 a 18:07, Jarkko Sakkinen a ecrit : >>>>> On Tue, Oct 24, 2017 at 07:57:06AM -0700, Jerry Snitselaar wrote: >>>>>> On Tue Oct 24 17, Jarkko Sakkinen wrote: >>>>>>> On Mon, Oct 23, 2017 at 06:45:15AM -0700, Jerry Snitselaar wrote: >>>>>>>> On Mon Oct 23 17, Jarkko Sakkinen wrote: >>>>>>>>> On Sat, Oct 21, 2017 at 10:53:55AM +0200, Laurent Bigonville >>>>>>>>> wrote: >>>>>>>>>> Le 14/10/17 a 10:13, Jerry Snitselaar a ecrit : >>>>>>>>>>> On Wed Sep 06 17, Jarkko Sakkinen wrote: >>>>>>>>>>>> On Fri, Sep 01, 2017 at 02:10:18PM +0200, Laurent >>>>>>>>>>>> Bigonville wrote: >>>>>>>>>>>>> Le 31/08/17 a 18:40, Jerry Snitselaar a ecrit : >>>>>>>>>>>>>> On Thu Aug 31 17, Alexander.Steffen@infineon.com wrote: >>>>>>>>>>>>>>>> Le 29/08/17 a 18:35, Laurent Bigonville a ecrit : >>>>>>>>>>>>>>>>> Le 29/08/17 a 18:00, Alexander.Steffen@infineon.com a >>>>>>>>>>>>>>>>> ecrit : >>>>>>>>>>>>>>>>>>> An idea how to troubleshoot this? >>>>>>>>>>>>>>>>>> Can you run git bisect on the changes between 4.11 and >>>>>>>>>>>>> 4.12, so that >>>>>>>>>>>>>>>>>> we find the offending commit? It is probably sufficient >>>>>>>>>>>>> to limit the >>>>>>>>>>>>>>>>>> search to commits that touch something in >>>>>>>>>>>>>>>>>> drivers/char/tpm. >>>>>>>>>>>>>>>>> I'll try and keep you posted. >>>>>>>>>>>>>>>> OK I've been able to bisect the problem and the bad >>>>>>>>>>>>>>>> commit is: >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> e6aef069b6e97790cb127d5eeb86ae9ff0b7b0e3 is the first >>>>>>>>>>>>>>>> bad commit >>>>>>>>>>>>>>>> commit e6aef069b6e97790cb127d5eeb86ae9ff0b7b0e3 >>>>>>>>>>>>>>>> Author: Jerry Snitselaar >>>>>>>>>>>>>>>> Date: Mon Mar 27 08:46:04 2017 -0700 >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> tpm_tis: convert to using locality callbacks >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> This patch converts tpm_tis to use of the new tpm >>>>>>>>>>>>>>>> class ops >>>>>>>>>>>>>>>> request_locality, and relinquish_locality. >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> With the move to using the callbacks, >>>>>>>>>>>>>>>> release_locality is >>>>>>>>>>>>>>>> changed so >>>>>>>>>>>>>>>> that we now release the locality even if there is no >>>>>>>>>>>>>>>> request pending. >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> This required some changes to the tpm_tis_core_init >>>>>>>>>>>>> code path to >>>>>>>>>>>>>>>> make sure locality is requested when needed: >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> - tpm2_probe code path will end up calling >>>>>>>>>>>>>>>> request/release through >>>>>>>>>>>>>>>> callbacks, so request_locality prior to >>>>>>>>>>>>> tpm2_probe not needed. >>>>>>>>>>>>>>>> - probe_itpm makes calls to tpm_tis_send_data >>>>>>>>>>>>>>>> which no >>>>>>>>>>>>>>>> longer calls >>>>>>>>>>>>>>>> request_locality, so add request_locality >>>>>>>>>>>>>>>> prior to >>>>>>>>>>>>>>>> tpm_tis_send_data >>>>>>>>>>>>>>>> calls. Also drop release_locality call in >>>>>>>>>>>>>>>> middleof >>>>>>>>>>>>>>>> probe_itpm, and >>>>>>>>>>>>>>>> keep locality until release_locality called >>>>>>>>>>>>>>>> at end of >>>>>>>>>>>>>>>> probe_itpm. >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> Cc: Peter Huewe >>>>>>>>>>>>>>>> Cc: Jarkko Sakkinen >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> Cc: Jason Gunthorpe >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> Cc: Marcel Selhorst >>>>>>>>>>>>>>>> Signed-off-by: Jerry Snitselaar >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> Reviewed-by: Jarkko Sakkinen >>>>>>>>>>>>> >>>>>>>>>>>>>>>> Tested-by: Jarkko Sakkinen >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> Signed-off-by: Jarkko Sakkinen >>>>>>>>>>>>> >>>>>>>>>>>>>>>> :040000 040000 70234365da69959d47076ebb40c8d17f520c3e44 >>>>>>>>>>>>>>>> 72f21b446e45ea1003de75902b0553deb99157fd M drivers >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>> I've looked again at the code in question, but could not >>>>>>>>>>>>>>> find >>>>>>>>>>>>>>> anything that is obviously wrong there. Locality is now >>>>>>>>>>>>>>> requested/released at slightly different points in the >>>>>>>>>>>>>>> process than >>>>>>>>>>>>>>> before, but that's it. It does not seem to cause >>>>>>>>>>>>>>> problems with the >>>>>>>>>>>>>>> majority of TPMs, since you are the first to report any, so >>>>>>>>>>>>> maybe it >>>>>>>>>>>>>>> is a quirk that only affects this device. >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> Perhaps Jerry can help, since this is his change? >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> Alexander >>>>>>>>>>>>>> Getting some caffeine in me, and starting to take a look. >>>>>>>>>>>>>> Adding >>>>>>>>>>>>>> Jarkko as well since this might involve the general >>>>>>>>>>>>>> locality changes. >>>>>>>>>>>>>> >>>>>>>>>>>>>> Laurent, if I send you a patch with some debugging code >>>>>>>>>>>>>> added, would >>>>>>>>>>>>>> you be able to run it on that system? I wasn't running >>>>>>>>>>>>>> into issues >>>>>>>>>>>>>> on the system I had with a 1.2 device, but I no longer >>>>>>>>>>>>>> have access >>>>>>>>>>>>>> to it. I'll see if I can find one in our labs and >>>>>>>>>>>>>> reproduce it there. >>>>>>>>>>>>> Yes I should be able to do that >>>>>>>>>>>> Any findings? >>>>>>>>>>>> >>>>>>>>>>>> /Jarkko >>>>>>>>>>> Okay, finally getting back to this. Looking at the code it >>>>>>>>>>> isn't clear >>>>>>>>>>> to me >>>>>>>>>>> why the change is causing this. So while I stare at this >>>>>>>>>>> some more >>>>>>>>>>> Laurent >>>>>>>>>>> could you reproduce it with this patch so I can see what the >>>>>>>>>>> status and >>>>>>>>>>> access registers look like? Does anyone else on here happen >>>>>>>>>>> to have a >>>>>>>>>>> Sinosun >>>>>>>>>>> tpm device? The systems I have access to with TPM1.2 devices >>>>>>>>>>> don't have >>>>>>>>>>> this >>>>>>>>>>> issue. >>>>>>>>>>> >>>>>>>>>>> --8<-- >>>>>>>>>>> >>>>>>>>>>> diff --git a/drivers/char/tpm/tpm_tis_core.c >>>>>>>>>>> b/drivers/char/tpm/tpm_tis_core.c >>>>>>>>>>> index fdde971bc810..7d60a7e4b50a 100644 >>>>>>>>>>> --- a/drivers/char/tpm/tpm_tis_core.c >>>>>>>>>>> +++ b/drivers/char/tpm/tpm_tis_core.c >>>>>>>>>>> @@ -258,6 +258,7 @@ static int tpm_tis_send_data(struct >>>>>>>>>>> tpm_chip *chip, >>>>>>>>>>> const u8 *buf, size_t len) >>>>>>>>>>> int rc, status, burstcnt; >>>>>>>>>>> size_t count = 0; >>>>>>>>>>> bool itpm = priv->flags & TPM_TIS_ITPM_WORKAROUND; >>>>>>>>>>> + u8 access; >>>>>>>>>>> >>>>>>>>>>> status = tpm_tis_status(chip); >>>>>>>>>>> if ((status & TPM_STS_COMMAND_READY) == 0) { >>>>>>>>>>> @@ -292,6 +293,11 @@ static int tpm_tis_send_data(struct >>>>>>>>>>> tpm_chip *chip, >>>>>>>>>>> const u8 *buf, size_t len) >>>>>>>>>>> } >>>>>>>>>>> status = tpm_tis_status(chip); >>>>>>>>>>> if (!itpm && (status & TPM_STS_DATA_EXPECT) == 0) { >>>>>>>>>>> + rc = tpm_tis_read8(priv, >>>>>>>>>>> TPM_ACCESS(priv->locality), >>>>>>>>>>> &access); >>>>>>>>>>> + if (rc < 0) >>>>>>>>>>> + dev_info(&chip->dev, "TPM_STS_DATA_EXPECT >>>>>>>>>>> == 0: read >>>>>>>>>>> failure TPM_ACCESS(%d)\n", priv->locality); >>>>>>>>>>> + else >>>>>>>>>>> + dev_info(&chip->dev, "TPM_STS_DATA_EXPECT >>>>>>>>>>> == 0: >>>>>>>>>>> locality: %d status: %x access: %x\n", priv->locality, >>>>>>>>>>> status, access); >>>>>>>>>>> rc = -EIO; >>>>>>>>>>> goto out_err; >>>>>>>>>>> } >>>>>>>>>>> @@ -309,6 +315,11 @@ static int tpm_tis_send_data(struct >>>>>>>>>>> tpm_chip *chip, >>>>>>>>>>> const u8 *buf, size_t len) >>>>>>>>>>> } >>>>>>>>>>> status = tpm_tis_status(chip); >>>>>>>>>>> if (!itpm && (status & TPM_STS_DATA_EXPECT) != 0) { >>>>>>>>>>> + rc = tpm_tis_read8(priv, >>>>>>>>>>> TPM_ACCESS(priv->locality), &access); >>>>>>>>>>> + if (rc < 0) >>>>>>>>>>> + dev_info(&chip->dev, "TPM_STS_DATA_EXPECT != 0: >>>>>>>>>>> read >>>>>>>>>>> failure TPM_ACCESS(%d)\n", priv->locality); >>>>>>>>>>> + else >>>>>>>>>>> + dev_info(&chip->dev, "TPM_STS_DATA_EXPECT != 0: >>>>>>>>>>> locality: >>>>>>>>>>> %d status: %x access: %x\n", priv->locality, status, access); >>>>>>>>>>> rc = -EIO; >>>>>>>>>>> goto out_err; >>>>>>>>>>> } >>>>>>>>>> Please find here the dmesg output of the patched kernel >>>>>>>>> At least 0xff is corrupted value in senseful way. CPU fills >>>>>>>>> the read >>>>>>>>> with ones for example for unaligned bus read. See table 19 in >>>>>>>>> PC client >>>>>>>>> spec. This can happen when you do unaligned read for example. >>>>>>>>> >>>>>>>>> Maybe TPM is unreachable i.e. powered off. Bit busy with stuff >>>>>>>>> ATM but >>>>>>>>> would probably make sense to compare that 0x81 to table 18 in >>>>>>>>> the same >>>>>>>>> spec. >>>>>>>>> >>>>>>>>> /Jarkko >>>>>>>> 0x81 is saying the access register status is valid, and the >>>>>>>> locality >>>>>>>> is not active. That first bit means A Dynamic OS has not been >>>>>>>> previously >>>>>>>> established on the platform. Normally we would see 0xa1, which >>>>>>>> would >>>>>>>> mean valid register status, and the locality is active. >>>>>>> I think the important thing to note here is that STS has bits >>>>>>> set that >>>>>>> should never be set. So we can conclude that TPM might be either >>>>>>> >>>>>>> 1. Powered off >>>>>>> 2. In some transition state? >>>>>>> >>>>>>> /Jarkko >>>>>> If it was powered off would we be getting a valid read from the >>>>>> access >>>>>> register? >>>>> I think there is no universal answer to that :-) >>>>> >>>>> Maybe adding a extra delay would be next test to make? If for random >>>>> reason it is in-between states... >>>> Any more ideas? >>>> >>>> The chip is definitely in a weird state :/ I tried several ways to >>>> reset the chip (windows, tpm-tools,...). >>>> >>>> I've been able to reset the chip via the bios (which now shows >>>> unowned) but chip is still locked apparently. >>>> >>>> But still with < 4.12 I'm able to get /some/ information Public EK, >>>> PCR,... out of the chip so it's not completely broken... >>> >>> OK correction the TPM is now unlocked (I let the computer running >>> for more than 24h with nothing accessing the TPM) and with 4.9 I've >>> been able to take the ownership again. >>> >>> Under 4.12 I still have the same errors as mentioned originally >> >> Hi Laurent, >> >> Would it be possible for you to run ftrace from boot with the >> following kernel parameters: >> >> ftrace=function_graph ftrace_filter=tpm* >> > > actually 'ftrace=function_graph > ftrace_filter=tpm*,*locality,wait_for_tpm_stat' would be better > >> and then send me the results of 'cat /sys/kernel/debug/tracing/trace' ? Here you are. [ Part 2, Text/PLAIN (Name: "trace.txt") ~8 KB. ] [ Unable to print this part. ]