tpm, tpm_tis: Acquire locality in tpm_tis_gen_interrupt() and tpm_get_timeouts()

PATCH In review Jarkko Sakkinen 4 participants 26 messages Feb 16, 2021 – Jun 15, 2021 1 message not in the archive

Subsystems (2)

Keys-trusted TPM device driver

lore

Share & tools

lore

Jarkko Sakkinen

author maintainer

2021-02-16 08:20 UTC #0 lore raw

PATCH 1/1 tpm, tpm_tis: Acquire locality in tpm_tis_gen_interrupt() and tpm_get_timeouts()

From: Lukasz Majczak <[email protected]>

This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):

[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f

Background
==========

TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:

The fix
=======

Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().

Cc Laurent Bigonville <[email protected]>

Fixes a3fbfae82b4c ("tpm: take TPM chip power gating out of tpm_transmit()")

Signed-off-by Lukasz Majczak <[email protected]>

Co-developed-by Jarkko Sakkinen <[email protected]>

Signed-off-by Jarkko Sakkinen <[email protected]>

Reviewed-by Guenter Roeck <[email protected]>

---
It was easier to write a new patch based on v5. Since v5 had a crippled change log I just restarted the version count.

 drivers/char/tpm/tpm-interface.c | 16 ++++++++++++++--
 drivers/char/tpm/tpm_tis_core.c  | 16 +++++++++++++---
 2 files changed, 27 insertions(+), 5 deletions(-)

drivers/char/tpm/tpm-interface.c +14 -2

index 1621ce818705..9ab155ae5726 100644
@@ -238,13 +238,25 @@ EXPORT_SYMBOL_GPL(tpm_transmit_cmd);
 
 int tpm_get_timeouts(struct tpm_chip *chip)
 {
+	int ret;
+
 	if (chip->flags & TPM_CHIP_FLAG_HAVE_TIMEOUTS)
 		return 0;
 
+	/* TPM 2.0 */
 	if (chip->flags & TPM_CHIP_FLAG_TPM2)
 		return tpm2_get_timeouts(chip);
-	else
-		return tpm1_get_timeouts(chip);
+
+
+	ret = tpm_chip_start(chip);
+	if (ret)
+		return ret;
+
+	ret = tpm1_get_timeouts(chip);
+
+	tpm_chip_stop(chip);
+
+	return ret;
 }
 EXPORT_SYMBOL_GPL(tpm_get_timeouts);

drivers/char/tpm/tpm_tis_core.c +13 -3

index 431919d5f48a..ce80e7a2d420 100644
@@ -707,12 +707,22 @@ static int tpm_tis_gen_interrupt(struct tpm_chip *chip)
 	const char *desc = "attempting to generate an interrupt";
 	u32 cap2;
 	cap_t cap;
+	int ret;
 
+	/* TPM 2.0 */
 	if (chip->flags & TPM_CHIP_FLAG_TPM2)
 		return tpm2_get_tpm_pt(chip, 0x100, &cap2, desc);
-	else
-		return tpm1_getcap(chip, TPM_CAP_PROP_TIS_TIMEOUT, &cap, desc,
-				  0);
+
+	/* TPM 1.2 */
+	ret = request_locality(chip, 0);
+	if (ret < 0)
+		return ret;
+
+	ret = tpm1_getcap(chip, TPM_CAP_PROP_TIS_TIMEOUT, &cap, desc, 0);
+
+	release_locality(chip, 0);
+
+	return ret;
 }
 
 /* Register the IRQ and issue a command that will cause an interrupt. If an

Signature · 1 line

2.30.1

Paul Menzel

2021-02-16 08:27 UTC #1 lore raw

Dear Jarkko,

Am 16.02.21 um 09:17 schrieb Jarkko Sakkinen:

Quoted 8 lines

From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f

Quoted 8 lines

Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:

Did you miss to paste the trace?

[…]

Kind regards,

Paul

Jarkko Sakkinen

author maintainer

2021-02-16 08:43 UTC #2 lore raw

Quoted 21 lines · Paul Menzel

Dear Jarkko,
Am 16.02.21 um 09:17 schrieb Jarkko Sakkinen:
Quoted 8 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Quoted 8 lines
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:

Quoted 8 lines

Did you miss to paste the trace?
[…]
Kind regards,
Paul

There is partial trace, which I took from the Lukasz patch. IMHO that is sufficient.

And I have no means to generate the full trace anyway.

/Jarkko

Paul Menzel

2021-02-16 08:51 UTC #3 lore raw

Dear Jarko,

Am 16.02.21 um 09:39 schrieb Jarkko Sakkinen:

Quoted 20 lines · Paul Menzel

Quoted 19 lines
Am 16.02.21 um 09:17 schrieb Jarkko Sakkinen:
Quoted 16 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:

Quoted 6 lines

Quoted 3 lines
Did you miss to paste the trace?
[…]
There is partial trace, which I took from the Lukasz patch. IMHO that is sufficient.

Reading the paragraph with “ with the following warning trace:” (and colon), I would expect to see some trace, and not the next section header *The fix*.

Quoted 1 line

And I have no means to generate the full trace anyway.

No problem.

Kind regards,

Paul

Jarkko Sakkinen

author maintainer

2021-02-16 16:15 UTC #4 lore raw

Quoted 26 lines · Paul Menzel

Dear Jarko,
Am 16.02.21 um 09:39 schrieb Jarkko Sakkinen:
Quoted 22 lines · Paul Menzel
Quoted 21 lines
Am 16.02.21 um 09:17 schrieb Jarkko Sakkinen:
Quoted 8 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Quoted 8 lines
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Did you miss to paste the trace?

Quoted 7 lines

Quoted 4 lines
Quoted 1 line
[…]
There is partial trace, which I took from the Lukasz patch. IMHO that is sufficient.
Reading the paragraph with “ with the following warning trace:” (and colon), I would expect to see some trace, and not the next section header *The fix*.

Aah! I took the paragraph from the original commit. So, what if I just remove the last sentence? I see what you mean.

Quoted 10 lines

Quoted 2 lines
And I have no means to generate the full trace anyway.
No problem.
Kind regards,
Paul

/Jarkko

Laurent Bigonville

2021-02-16 11:06 UTC #5 lore raw

In reply to Jarkko Sakkinen

Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :

Quoted 17 lines

From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:

Quoted 5 lines

The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().

I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg

A message that is not in the archive (sent off-list or not yet received): CAFJ_xbo2Tvfjjbt-xFAkEAdqVEg0ZhDnGJa2qkJOYURx47hE+Q@mail.gmail.com

Laurent Bigonville

2021-02-16 11:22 UTC #7 lore raw

Le 16/02/21 à 12:17, Lukasz Majczak a écrit :

Quoted 1 line

Hi Laurent,

Hello Lukasz,

Quoted 2 lines

I think your case is different, as the trace shows the issue in the place already guarded by tpm_chip_start()/stop(). Can you past more dmesg log? (With tpm prefix?). I believe tpm_tis_status() might return something different than 0xff here.

I see "WARNING: CPU: 5 PID: 449 at drivers/char/tpm/tpm_tis_core.c:249 tpm_tis_status+0x86/0xa0 [tpm_tis_core]" in dmesg

Lukasz Majczak

2021-02-16 14:11 UTC #8 lore raw

In reply to Laurent Bigonville

Hi Laurent,

I think your case is different, as the trace shows the issue occurs in the place already guarded by tpm_chip_start()/stop() - tpm2_probe(). Can you paste more dmesg log? (With tpm prefix?). I believe tpm_tis_status() might return something different than 0xff here. Please ensure you have applied Jarkko's patch that logs status
(https://patchwork.kernel.org/project/linux-integrity/patch/[email protected]/)

Best regards
Lukasz

wt., 16 lut 2021 o 12:02 Laurent Bigonville <[email protected]> napisał(a):

Quoted 28 lines · Jarkko Sakkinen

Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg

Jarkko Sakkinen

author maintainer

2021-02-16 16:19 UTC #9 lore raw

Quoted 8 lines · Lukasz Majczak

Hi Laurent,
I think your case is different, as the trace shows the issue occurs in the place already guarded by tpm_chip_start()/stop() - tpm2_probe(). Can you paste more dmesg log? (With tpm prefix?). I believe tpm_tis_status() might return something different than 0xff here. Please ensure you have applied Jarkko's patch that logs status
(https://patchwork.kernel.org/project/linux-integrity/patch/[email protected]/)

I would politely ask you:

- Not to top-post. Quote and reponse properly.
- No HTML emails.

Quoted 2 lines

Best regards
Lukasz

/Jarkko

Jarkko Sakkinen

author maintainer

2021-02-16 16:18 UTC #10 lore raw

In reply to Laurent Bigonville

Quoted 18 lines · Laurent Bigonville

Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:

Quoted 8 lines

Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg

Can you give a shot to

git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git

It has couple of more fixes, and paste the log.

/Jarkko

Jarkko Sakkinen

author maintainer

2021-02-16 16:28 UTC #11 lore raw

Quoted 25 lines · Jarkko Sakkinen

Quoted 24 lines · Laurent Bigonville
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 22 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().

Quoted 8 lines

Quoted 2 lines
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.

And if possible a full stack trace :-)

/Jarkko

Jarkko Sakkinen

author maintainer

2021-02-16 16:35 UTC #12 lore raw

Quoted 29 lines · Jarkko Sakkinen

Quoted 28 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg

Quoted 7 lines

Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)

And apply this patch on top. Cannot apply it there before it's reviewed.

/Jarkko

Laurent Bigonville

2021-02-16 19:07 UTC #13 lore raw

Le 16/02/21 à 17:34, Jarkko Sakkinen a écrit :

Quoted 28 lines · Jarkko Sakkinen

Quoted 27 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Quoted 25 lines
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg

Quoted 8 lines

Quoted 6 lines
Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)
And apply this patch on top. Cannot apply it there before it's reviewed.

I get the following stacktrace with your branch and the patch here:

[   13.498925] ------------[ cut here ]------------
[   13.498930] TPM returned invalid status
[   13.498953] WARNING: CPU: 1 PID: 459 at drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core]
[   13.498963] Modules linked in: libiscsi_tcp(E) tpm_tis(E+) tpm_tis_core(E) libiscsi(E) snd_timer(E) tpm(E) joydev(E) snd(E) scsi_transport_iscsi(E) pcc_cpufreq(E-) fjes(E-) soundcore(E) i7core_edac(E) i5500_temp(E) asus_atk0110(E) rng_core(E) acpi_cpufreq(E-) evdev(E) loop(E) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) ahci(E) libahci(E) libata(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) uhci_hcd(E) ehci_pci(E) firewire_ohci(E) crc32c_intel(E) ehci_hcd(E) drm_kms_helper(E) firewire_core(E) i2c_i801(E) psmouse(E) [   13.499044] scsi_mod(E) cec(E) i2c_smbus(E) mxm_wmi(E) lpc_ich(E) crc_itu_t(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E)
[   13.499058] CPU: 1 PID: 459 Comm: systemd-udevd Tainted: G          I E     5.11.0+ #4
[   13.499062] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.499064] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core]
[   13.499069] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d 83 48 00 00 00 75 e0 48 c7 c7 4c 53 49 c1 88 44 24 07 c6 05 6f 48 00 00 01 e8 b2 24 ba cd <0f> 0b 0f b6 44 24 07 eb c0 e8 fc 99 bd cd 66 66 2e 0f 1f 84 00 00
[   13.499072] RSP: 0018:ffffbaeb80fb3aa0 EFLAGS: 00010286
[   13.499075] RAX: 0000000000000000 RBX: ffff9704034e5000 RCX: ffff9707ada58bc8
[   13.499078] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff9707ada58bc0
[   13.499080] RBP: 00000000ffff5d40 R08: 0000000000000000 R09: ffffbaeb80fb38c0
[   13.499082] R10: ffffbaeb80fb38b8 R11: ffffffff8fac2588 R12: 0000000000000016
[   13.499085] R13: ffff97040c38d000 R14: 0000000000001000 R15: ffffbaeb80fb3ada
[   13.499087] FS: 00007fe1bcfeb8c0(0000) GS:ffff9707ada40000(0000) knlGS:0000000000000000
[   13.499090] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   13.499092] CR2: 000055e5f7048590 CR3: 00000001084fe000 CR4: 00000000000006e0
[   13.499095] Call Trace:
[   13.499099] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.499113] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.499121] tpm2_probe+0xe2/0x140 [tpm]
[   13.499130] tpm_tis_core_init+0x1d5/0x2b0 [tpm_tis_core]
[   13.499135] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.499141] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.499148] pnp_device_probe+0xaf/0x140
[   13.499154] really_probe+0xf2/0x440
[   13.499160] driver_probe_device+0xe1/0x150
[   13.499163] device_driver_attach+0xa1/0xb0
[   13.499167] __driver_attach+0x8a/0x150
[   13.499171] ? device_driver_attach+0xb0/0xb0
[   13.499174] ? device_driver_attach+0xb0/0xb0
[   13.499177] bus_for_each_dev+0x78/0xc0
[   13.499181] bus_add_driver+0x12b/0x1e0
[   13.499184] driver_register+0x8b/0xe0
[   13.499188] ? 0xffffffffc1413000
[   13.499191] init_tis+0xa0/0x1000 [tpm_tis]
[   13.499197] do_one_initcall+0x44/0x1d0
[   13.499202] ? do_init_module+0x23/0x260
[   13.499206] ? kmem_cache_alloc_trace+0xf5/0x200
[   13.499212] do_init_module+0x5c/0x260
[   13.499215] __do_sys_finit_module+0xb1/0x110
[   13.499225] do_syscall_64+0x33/0x80
[   13.499229] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.499234] RIP: 0033:0x7fe1bd4a49b9
[   13.499237] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.499240] RSP: 002b:00007ffca5bfa108 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[   13.499243] RAX: ffffffffffffffda RBX: 000055e5f7036920 RCX: 00007fe1bd4a49b9
[   13.499245] RDX: 0000000000000000 RSI: 00007fe1bd62fe2d RDI: 0000000000000012
[   13.499247] RBP: 0000000000020000 R08: 0000000000000000 R09: 000055e5f6e7a0b0
[   13.499249] R10: 0000000000000012 R11: 0000000000000246 R12: 00007fe1bd62fe2d
[   13.499251] R13: 0000000000000000 R14: 000055e5f7033420 R15: 000055e5f7036920
[   13.499255] ---[ end trace 7e963e5c3647102e ]---

If I also apply the patch to change the WARN_ONCE in dev_warn_once, and grep on the string "tpm", I get the following:

Feb 16 19:51:22 fornost kernel: tpm tpm0: TPM returned invalid status: 0xa0
Feb 16 19:51:22 fornost kernel: tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1)
Feb 16 19:51:24 fornost kernel: tpm tpm0: tpm_try_transmit: send(): error -62
Feb 16 19:51:24 fornost kernel: tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts
Feb 16 19:51:24 fornost kernel: tpm_tis: probe of 00:06 failed with error -62
Feb 16 19:51:24 fornost kernel: tpm_inf_pnp 00:06: Found TPM with ID IFX0102

Lukasz Majczak

2021-02-17 11:54 UTC #14 lore raw

wt., 16 lut 2021 o 20:06 Laurent Bigonville <[email protected]> napisał(a):

Quoted 132 lines · Jarkko Sakkinen

Quoted 28 lines · Jarkko Sakkinen
Quoted 27 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Quoted 25 lines · Jarkko Sakkinen
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg
Quoted 8 lines
Quoted 6 lines
Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)
And apply this patch on top. Cannot apply it there before it's reviewed.
I get the following stacktrace with your branch and the patch here:
[   13.498925] ------------[ cut here ]------------
[   13.498930] TPM returned invalid status
[   13.498953] WARNING: CPU: 1 PID: 459 at
drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core]
[   13.498963] Modules linked in: libiscsi_tcp(E) tpm_tis(E+)
tpm_tis_core(E) libiscsi(E) snd_timer(E) tpm(E) joydev(E) snd(E) scsi_transport_iscsi(E) pcc_cpufreq(E-) fjes(E-) soundcore(E) i7core_edac(E) i5500_temp(E) asus_atk0110(E) rng_core(E) acpi_cpufreq(E-) evdev(E) loop(E) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) ahci(E) libahci(E) libata(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) uhci_hcd(E) ehci_pci(E) firewire_ohci(E) crc32c_intel(E) ehci_hcd(E) drm_kms_helper(E) firewire_core(E) i2c_i801(E) psmouse(E)
[   13.499044]  scsi_mod(E) cec(E) i2c_smbus(E) mxm_wmi(E) lpc_ich(E)
crc_itu_t(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E)
[   13.499058] CPU: 1 PID: 459 Comm: systemd-udevd Tainted: G          I
E     5.11.0+ #4
[   13.499062] Hardware name: System manufacturer System Product
Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.499064] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core]
[   13.499069] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d 83 48 00 00 00
75 e0 48 c7 c7 4c 53 49 c1 88 44 24 07 c6 05 6f 48 00 00 01 e8 b2 24 ba
cd <0f> 0b 0f b6 44 24 07 eb c0 e8 fc 99 bd cd 66 66 2e 0f 1f 84 00 00
[   13.499072] RSP: 0018:ffffbaeb80fb3aa0 EFLAGS: 00010286
[   13.499075] RAX: 0000000000000000 RBX: ffff9704034e5000 RCX:
ffff9707ada58bc8
[   13.499078] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI:
ffff9707ada58bc0
[   13.499080] RBP: 00000000ffff5d40 R08: 0000000000000000 R09:
ffffbaeb80fb38c0
[   13.499082] R10: ffffbaeb80fb38b8 R11: ffffffff8fac2588 R12:
0000000000000016
[   13.499085] R13: ffff97040c38d000 R14: 0000000000001000 R15:
ffffbaeb80fb3ada
[   13.499087] FS:  00007fe1bcfeb8c0(0000) GS:ffff9707ada40000(0000)
knlGS:0000000000000000
[   13.499090] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   13.499092] CR2: 000055e5f7048590 CR3: 00000001084fe000 CR4:
00000000000006e0
[   13.499095] Call Trace:
[   13.499099]  tpm_transmit+0x15f/0x3d0 [tpm]
[   13.499113]  tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.499121]  tpm2_probe+0xe2/0x140 [tpm]
[   13.499130]  tpm_tis_core_init+0x1d5/0x2b0 [tpm_tis_core]
[   13.499135]  ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.499141]  tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.499148]  pnp_device_probe+0xaf/0x140
[   13.499154]  really_probe+0xf2/0x440
[   13.499160]  driver_probe_device+0xe1/0x150
[   13.499163]  device_driver_attach+0xa1/0xb0
[   13.499167]  __driver_attach+0x8a/0x150
[   13.499171]  ? device_driver_attach+0xb0/0xb0
[   13.499174]  ? device_driver_attach+0xb0/0xb0
[   13.499177]  bus_for_each_dev+0x78/0xc0
[   13.499181]  bus_add_driver+0x12b/0x1e0
[   13.499184]  driver_register+0x8b/0xe0
[   13.499188]  ? 0xffffffffc1413000
[   13.499191]  init_tis+0xa0/0x1000 [tpm_tis]
[   13.499197]  do_one_initcall+0x44/0x1d0
[   13.499202]  ? do_init_module+0x23/0x260
[   13.499206]  ? kmem_cache_alloc_trace+0xf5/0x200
[   13.499212]  do_init_module+0x5c/0x260
[   13.499215]  __do_sys_finit_module+0xb1/0x110
[   13.499225]  do_syscall_64+0x33/0x80
[   13.499229]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.499234] RIP: 0033:0x7fe1bd4a49b9
[   13.499237] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f
05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.499240] RSP: 002b:00007ffca5bfa108 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.499243] RAX: ffffffffffffffda RBX: 000055e5f7036920 RCX:
00007fe1bd4a49b9
[   13.499245] RDX: 0000000000000000 RSI: 00007fe1bd62fe2d RDI:
0000000000000012
[   13.499247] RBP: 0000000000020000 R08: 0000000000000000 R09:
000055e5f6e7a0b0
[   13.499249] R10: 0000000000000012 R11: 0000000000000246 R12:
00007fe1bd62fe2d
[   13.499251] R13: 0000000000000000 R14: 000055e5f7033420 R15:
000055e5f7036920
[   13.499255] ---[ end trace 7e963e5c3647102e ]---
If I also apply the patch to change the WARN_ONCE in dev_warn_once, and grep on the string "tpm", I get the following:

Quoted 11 lines

Feb 16 19:51:22 fornost kernel: tpm tpm0: TPM returned invalid status: 0xa0
Feb 16 19:51:22 fornost kernel: tpm_tis 00:06: 1.2 TPM (device-id
0x6871, rev-id 1)
Feb 16 19:51:24 fornost kernel: tpm tpm0: tpm_try_transmit: send():
error -62
Feb 16 19:51:24 fornost kernel: tpm tpm0: A TPM error (-62) occurred
attempting to determine the timeouts
Feb 16 19:51:24 fornost kernel: tpm_tis: probe of 00:06 failed with
error -62
Feb 16 19:51:24 fornost kernel: tpm_inf_pnp 00:06: Found TPM with ID IFX0102

Hi,
According to TCG PC Client Platform TPM Profile Specification for TPM 2.0
(https://trustedcomputinggroup.org/wp-content/uploads/PC-Client-Specific-Platform-TPM-Profile-for-TPM-2p0-v1p05p_r14_pub.pdf)
page 82-82, TPS_STS register bits description, it states, that in your case (0xa0) bits 7 (stsValid, read-only) and 5 (tpmGo, write-only) are set...
Both bits, in theirs descriptions have "Valid indicator: N/A". The "if" statement (that guards this warning) masks TPM_STS with TPM_STS_READ_ZERO (0x23), so it checks bit 0,1 and 5 (tpmGo) which, in this case, is set causing the warning message.
I think the mask (TPM_STS_READ_ZERO) should have value 0x3 (skipping bit 5) as tpmGo is write-only.
What do you think ?

Best regards,
Lukasz

Jarkko Sakkinen

author maintainer

2021-02-17 22:31 UTC #15 lore raw

In reply to Laurent Bigonville

Quoted 130 lines · Laurent Bigonville

Le 16/02/21 à 17:34, Jarkko Sakkinen a écrit :
Quoted 28 lines · Jarkko Sakkinen
Quoted 27 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Quoted 25 lines
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg
Quoted 8 lines
Quoted 6 lines
Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)
And apply this patch on top. Cannot apply it there before it's reviewed.
I get the following stacktrace with your branch and the patch here:
[   13.498925] ------------[ cut here ]------------
[   13.498930] TPM returned invalid status
[   13.498953] WARNING: CPU: 1 PID: 459 at drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.498963] Modules linked in: libiscsi_tcp(E) tpm_tis(E+) tpm_tis_core(E) libiscsi(E) snd_timer(E) tpm(E) joydev(E) snd(E) scsi_transport_iscsi(E) pcc_cpufreq(E-) fjes(E-) soundcore(E) i7core_edac(E) i5500_temp(E) asus_atk0110(E) rng_core(E) acpi_cpufreq(E-) evdev(E) loop(E) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) ahci(E) libahci(E) libata(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) uhci_hcd(E) ehci_pci(E) firewire_ohci(E) crc32c_intel(E) ehci_hcd(E) drm_kms_helper(E) firewire_core(E) i2c_i801(E) psmouse(E)
[   13.499044] scsi_mod(E) cec(E) i2c_smbus(E) mxm_wmi(E) lpc_ich(E) crc_itu_t(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E) [   13.499058] CPU: 1 PID: 459 Comm: systemd-udevd Tainted: G          I E     5.11.0+ #4
[   13.499062] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.499064] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.499069] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d 83 48 00 00 00 75 e0 48 c7 c7 4c 53 49 c1 88 44 24 07 c6 05 6f 48 00 00 01 e8 b2 24 ba cd <0f> 0b 0f b6 44 24 07 eb c0 e8 fc 99 bd cd 66 66 2e 0f 1f 84 00 00
[   13.499072] RSP: 0018:ffffbaeb80fb3aa0 EFLAGS: 00010286
[   13.499075] RAX: 0000000000000000 RBX: ffff9704034e5000 RCX:
ffff9707ada58bc8
[   13.499078] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI:
ffff9707ada58bc0
[   13.499080] RBP: 00000000ffff5d40 R08: 0000000000000000 R09:
ffffbaeb80fb38c0
[   13.499082] R10: ffffbaeb80fb38b8 R11: ffffffff8fac2588 R12:
0000000000000016
[   13.499085] R13: ffff97040c38d000 R14: 0000000000001000 R15:
ffffbaeb80fb3ada
[   13.499087] FS: 00007fe1bcfeb8c0(0000) GS:ffff9707ada40000(0000) knlGS:0000000000000000
[   13.499090] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [   13.499092] CR2: 000055e5f7048590 CR3: 00000001084fe000 CR4:
00000000000006e0
[   13.499095] Call Trace:
[   13.499099] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.499113] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.499121] tpm2_probe+0xe2/0x140 [tpm]
[   13.499130] tpm_tis_core_init+0x1d5/0x2b0 [tpm_tis_core]
[   13.499135] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.499141] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.499148] pnp_device_probe+0xaf/0x140
[   13.499154] really_probe+0xf2/0x440
[   13.499160] driver_probe_device+0xe1/0x150
[   13.499163] device_driver_attach+0xa1/0xb0
[   13.499167] __driver_attach+0x8a/0x150
[   13.499171] ? device_driver_attach+0xb0/0xb0
[   13.499174] ? device_driver_attach+0xb0/0xb0
[   13.499177] bus_for_each_dev+0x78/0xc0
[   13.499181] bus_add_driver+0x12b/0x1e0
[   13.499184] driver_register+0x8b/0xe0
[   13.499188] ? 0xffffffffc1413000
[   13.499191] init_tis+0xa0/0x1000 [tpm_tis]
[   13.499197] do_one_initcall+0x44/0x1d0
[   13.499202] ? do_init_module+0x23/0x260
[   13.499206] ? kmem_cache_alloc_trace+0xf5/0x200
[   13.499212] do_init_module+0x5c/0x260
[   13.499215] __do_sys_finit_module+0xb1/0x110
[   13.499225] do_syscall_64+0x33/0x80
[   13.499229] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.499234] RIP: 0033:0x7fe1bd4a49b9
[   13.499237] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.499240] RSP: 002b:00007ffca5bfa108 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.499243] RAX: ffffffffffffffda RBX: 000055e5f7036920 RCX:
00007fe1bd4a49b9
[   13.499245] RDX: 0000000000000000 RSI: 00007fe1bd62fe2d RDI:
0000000000000012
[   13.499247] RBP: 0000000000020000 R08: 0000000000000000 R09:
000055e5f6e7a0b0
[   13.499249] R10: 0000000000000012 R11: 0000000000000246 R12:
00007fe1bd62fe2d
[   13.499251] R13: 0000000000000000 R14: 000055e5f7033420 R15:
000055e5f7036920
[   13.499255] ---[ end trace 7e963e5c3647102e ]---
If I also apply the patch to change the WARN_ONCE in dev_warn_once, and grep on the string "tpm", I get the following:

Quoted 12 lines

Feb 16 19:51:22 fornost kernel: tpm tpm0: TPM returned invalid status: 0xa0
Feb 16 19:51:22 fornost kernel: tpm_tis 00:06: 1.2 TPM (device-id 0x6871,
rev-id 1)
Feb 16 19:51:24 fornost kernel: tpm tpm0: tpm_try_transmit: send(): error
-62
Feb 16 19:51:24 fornost kernel: tpm tpm0: A TPM error (-62) occurred
attempting to determine the timeouts
Feb 16 19:51:24 fornost kernel: tpm_tis: probe of 00:06 failed with error
-62
Feb 16 19:51:24 fornost kernel: tpm_inf_pnp 00:06: Found TPM with ID IFX0102

No immediate idea why this happens as the code should take locality.

I noticed that the original patch bundles incorrectly two fixes, so I send mu PT without the current fix and turn into a patch set. Let's try to debug this for rc2/rc3.

/Jarkko

Laurent Bigonville

2021-06-01 21:23 UTC #16 lore raw

Le 17/02/21 à 23:29, Jarkko Sakkinen a écrit :

Quoted 143 lines · Laurent Bigonville

Quoted 130 lines
Le 16/02/21 à 17:34, Jarkko Sakkinen a écrit :
Quoted 28 lines · Jarkko Sakkinen
Quoted 27 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Quoted 25 lines
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg
Quoted 8 lines
Quoted 6 lines
Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)
And apply this patch on top. Cannot apply it there before it's reviewed.
I get the following stacktrace with your branch and the patch here:
[   13.498925] ------------[ cut here ]------------
[   13.498930] TPM returned invalid status
[   13.498953] WARNING: CPU: 1 PID: 459 at drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.498963] Modules linked in: libiscsi_tcp(E) tpm_tis(E+) tpm_tis_core(E) libiscsi(E) snd_timer(E) tpm(E) joydev(E) snd(E) scsi_transport_iscsi(E) pcc_cpufreq(E-) fjes(E-) soundcore(E) i7core_edac(E) i5500_temp(E) asus_atk0110(E) rng_core(E) acpi_cpufreq(E-) evdev(E) loop(E) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) ahci(E) libahci(E) libata(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) uhci_hcd(E) ehci_pci(E) firewire_ohci(E) crc32c_intel(E) ehci_hcd(E) drm_kms_helper(E) firewire_core(E) i2c_i801(E) psmouse(E)
[   13.499044] scsi_mod(E) cec(E) i2c_smbus(E) mxm_wmi(E) lpc_ich(E) crc_itu_t(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E) [   13.499058] CPU: 1 PID: 459 Comm: systemd-udevd Tainted: G          I E     5.11.0+ #4
[   13.499062] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.499064] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.499069] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d 83 48 00 00 00 75 e0 48 c7 c7 4c 53 49 c1 88 44 24 07 c6 05 6f 48 00 00 01 e8 b2 24 ba cd <0f> 0b 0f b6 44 24 07 eb c0 e8 fc 99 bd cd 66 66 2e 0f 1f 84 00 00
[   13.499072] RSP: 0018:ffffbaeb80fb3aa0 EFLAGS: 00010286
[   13.499075] RAX: 0000000000000000 RBX: ffff9704034e5000 RCX:
ffff9707ada58bc8
[   13.499078] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI:
ffff9707ada58bc0
[   13.499080] RBP: 00000000ffff5d40 R08: 0000000000000000 R09:
ffffbaeb80fb38c0
[   13.499082] R10: ffffbaeb80fb38b8 R11: ffffffff8fac2588 R12:
0000000000000016
[   13.499085] R13: ffff97040c38d000 R14: 0000000000001000 R15:
ffffbaeb80fb3ada
[   13.499087] FS: 00007fe1bcfeb8c0(0000) GS:ffff9707ada40000(0000) knlGS:0000000000000000
[   13.499090] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [   13.499092] CR2: 000055e5f7048590 CR3: 00000001084fe000 CR4:
00000000000006e0
[   13.499095] Call Trace:
[   13.499099] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.499113] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.499121] tpm2_probe+0xe2/0x140 [tpm]
[   13.499130] tpm_tis_core_init+0x1d5/0x2b0 [tpm_tis_core]
[   13.499135] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.499141] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.499148] pnp_device_probe+0xaf/0x140
[   13.499154] really_probe+0xf2/0x440
[   13.499160] driver_probe_device+0xe1/0x150
[   13.499163] device_driver_attach+0xa1/0xb0
[   13.499167] __driver_attach+0x8a/0x150
[   13.499171] ? device_driver_attach+0xb0/0xb0
[   13.499174] ? device_driver_attach+0xb0/0xb0
[   13.499177] bus_for_each_dev+0x78/0xc0
[   13.499181] bus_add_driver+0x12b/0x1e0
[   13.499184] driver_register+0x8b/0xe0
[   13.499188] ? 0xffffffffc1413000
[   13.499191] init_tis+0xa0/0x1000 [tpm_tis]
[   13.499197] do_one_initcall+0x44/0x1d0
[   13.499202] ? do_init_module+0x23/0x260
[   13.499206] ? kmem_cache_alloc_trace+0xf5/0x200
[   13.499212] do_init_module+0x5c/0x260
[   13.499215] __do_sys_finit_module+0xb1/0x110
[   13.499225] do_syscall_64+0x33/0x80
[   13.499229] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.499234] RIP: 0033:0x7fe1bd4a49b9
[   13.499237] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.499240] RSP: 002b:00007ffca5bfa108 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.499243] RAX: ffffffffffffffda RBX: 000055e5f7036920 RCX:
00007fe1bd4a49b9
[   13.499245] RDX: 0000000000000000 RSI: 00007fe1bd62fe2d RDI:
0000000000000012
[   13.499247] RBP: 0000000000020000 R08: 0000000000000000 R09:
000055e5f6e7a0b0
[   13.499249] R10: 0000000000000012 R11: 0000000000000246 R12:
00007fe1bd62fe2d
[   13.499251] R13: 0000000000000000 R14: 000055e5f7033420 R15:
000055e5f7036920
[   13.499255] ---[ end trace 7e963e5c3647102e ]---
If I also apply the patch to change the WARN_ONCE in dev_warn_once, and grep on the string "tpm", I get the following:
Quoted 12 lines
Feb 16 19:51:22 fornost kernel: tpm tpm0: TPM returned invalid status: 0xa0
Feb 16 19:51:22 fornost kernel: tpm_tis 00:06: 1.2 TPM (device-id 0x6871,
rev-id 1)
Feb 16 19:51:24 fornost kernel: tpm tpm0: tpm_try_transmit: send(): error
-62
Feb 16 19:51:24 fornost kernel: tpm tpm0: A TPM error (-62) occurred
attempting to determine the timeouts
Feb 16 19:51:24 fornost kernel: tpm_tis: probe of 00:06 failed with error
-62
Feb 16 19:51:24 fornost kernel: tpm_inf_pnp 00:06: Found TPM with ID IFX0102

Quoted 5 lines

No immediate idea why this happens as the code should take locality.
I noticed that the original patch bundles incorrectly two fixes, so I send mu PT without the current fix and turn into a patch set. Let's try to debug this for rc2/rc3.

Hey, I'm coming back regarding this issue, I'm running 5.10 (from debian unstable) and still getting this issue

Jarkko Sakkinen

author maintainer

2021-06-03 05:29 UTC #17 lore raw

Quoted 144 lines · Laurent Bigonville

Le 17/02/21 à 23:29, Jarkko Sakkinen a écrit :
Quoted 143 lines · Laurent Bigonville
Quoted 142 lines
Le 16/02/21 à 17:34, Jarkko Sakkinen a écrit :
Quoted 28 lines · Jarkko Sakkinen
Quoted 27 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Quoted 25 lines
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg
Quoted 8 lines
Quoted 6 lines
Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)
And apply this patch on top. Cannot apply it there before it's reviewed.
I get the following stacktrace with your branch and the patch here:
[   13.498925] ------------[ cut here ]------------
[   13.498930] TPM returned invalid status
[   13.498953] WARNING: CPU: 1 PID: 459 at drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.498963] Modules linked in: libiscsi_tcp(E) tpm_tis(E+) tpm_tis_core(E) libiscsi(E) snd_timer(E) tpm(E) joydev(E) snd(E) scsi_transport_iscsi(E) pcc_cpufreq(E-) fjes(E-) soundcore(E) i7core_edac(E) i5500_temp(E) asus_atk0110(E) rng_core(E) acpi_cpufreq(E-) evdev(E) loop(E) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) ahci(E) libahci(E) libata(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) uhci_hcd(E) ehci_pci(E) firewire_ohci(E) crc32c_intel(E) ehci_hcd(E) drm_kms_helper(E) firewire_core(E) i2c_i801(E) psmouse(E)
[   13.499044] scsi_mod(E) cec(E) i2c_smbus(E) mxm_wmi(E) lpc_ich(E) crc_itu_t(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E) [   13.499058] CPU: 1 PID: 459 Comm: systemd-udevd Tainted: G          I E     5.11.0+ #4
[   13.499062] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.499064] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.499069] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d 83 48 00 00 00 75 e0 48 c7 c7 4c 53 49 c1 88 44 24 07 c6 05 6f 48 00 00 01 e8 b2 24 ba cd <0f> 0b 0f b6 44 24 07 eb c0 e8 fc 99 bd cd 66 66 2e 0f 1f 84 00 00
[   13.499072] RSP: 0018:ffffbaeb80fb3aa0 EFLAGS: 00010286
[   13.499075] RAX: 0000000000000000 RBX: ffff9704034e5000 RCX:
ffff9707ada58bc8
[   13.499078] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI:
ffff9707ada58bc0
[   13.499080] RBP: 00000000ffff5d40 R08: 0000000000000000 R09:
ffffbaeb80fb38c0
[   13.499082] R10: ffffbaeb80fb38b8 R11: ffffffff8fac2588 R12:
0000000000000016
[   13.499085] R13: ffff97040c38d000 R14: 0000000000001000 R15:
ffffbaeb80fb3ada
[   13.499087] FS: 00007fe1bcfeb8c0(0000) GS:ffff9707ada40000(0000) knlGS:0000000000000000
[   13.499090] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [   13.499092] CR2: 000055e5f7048590 CR3: 00000001084fe000 CR4:
00000000000006e0
[   13.499095] Call Trace:
[   13.499099] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.499113] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.499121] tpm2_probe+0xe2/0x140 [tpm]
[   13.499130] tpm_tis_core_init+0x1d5/0x2b0 [tpm_tis_core]
[   13.499135] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.499141] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.499148] pnp_device_probe+0xaf/0x140
[   13.499154] really_probe+0xf2/0x440
[   13.499160] driver_probe_device+0xe1/0x150
[   13.499163] device_driver_attach+0xa1/0xb0
[   13.499167] __driver_attach+0x8a/0x150
[   13.499171] ? device_driver_attach+0xb0/0xb0
[   13.499174] ? device_driver_attach+0xb0/0xb0
[   13.499177] bus_for_each_dev+0x78/0xc0
[   13.499181] bus_add_driver+0x12b/0x1e0
[   13.499184] driver_register+0x8b/0xe0
[   13.499188] ? 0xffffffffc1413000
[   13.499191] init_tis+0xa0/0x1000 [tpm_tis]
[   13.499197] do_one_initcall+0x44/0x1d0
[   13.499202] ? do_init_module+0x23/0x260
[   13.499206] ? kmem_cache_alloc_trace+0xf5/0x200
[   13.499212] do_init_module+0x5c/0x260
[   13.499215] __do_sys_finit_module+0xb1/0x110
[   13.499225] do_syscall_64+0x33/0x80
[   13.499229] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.499234] RIP: 0033:0x7fe1bd4a49b9
[   13.499237] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.499240] RSP: 002b:00007ffca5bfa108 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.499243] RAX: ffffffffffffffda RBX: 000055e5f7036920 RCX:
00007fe1bd4a49b9
[   13.499245] RDX: 0000000000000000 RSI: 00007fe1bd62fe2d RDI:
0000000000000012
[   13.499247] RBP: 0000000000020000 R08: 0000000000000000 R09:
000055e5f6e7a0b0
[   13.499249] R10: 0000000000000012 R11: 0000000000000246 R12:
00007fe1bd62fe2d
[   13.499251] R13: 0000000000000000 R14: 000055e5f7033420 R15:
000055e5f7036920
[   13.499255] ---[ end trace 7e963e5c3647102e ]---
If I also apply the patch to change the WARN_ONCE in dev_warn_once, and grep on the string "tpm", I get the following:
Feb 16 19:51:22 fornost kernel: tpm tpm0: TPM returned invalid status: 0xa0
Feb 16 19:51:22 fornost kernel: tpm_tis 00:06: 1.2 TPM (device-id 0x6871,
rev-id 1)
Feb 16 19:51:24 fornost kernel: tpm tpm0: tpm_try_transmit: send(): error
-62
Feb 16 19:51:24 fornost kernel: tpm tpm0: A TPM error (-62) occurred
attempting to determine the timeouts
Feb 16 19:51:24 fornost kernel: tpm_tis: probe of 00:06 failed with error
-62
Feb 16 19:51:24 fornost kernel: tpm_inf_pnp 00:06: Found TPM with ID IFX0102

Quoted 7 lines

Quoted 5 lines
No immediate idea why this happens as the code should take locality.
I noticed that the original patch bundles incorrectly two fixes, so I send mu PT without the current fix and turn into a patch set. Let's try to debug this for rc2/rc3.
Hey, I'm coming back regarding this issue, I'm running 5.10 (from debian unstable) and still getting this issue

Many of the fixes are landing to 5.13, stable kernels do not acquire out-of-tree fixes unless downstream maintainers decide to apply them by hand.

/Jarkko

Laurent Bigonville

2021-06-03 09:42 UTC #18 lore raw

Le 3/06/21 à 07:28, Jarkko Sakkinen a écrit :

Quoted 147 lines · Laurent Bigonville

Quoted 146 lines
Le 17/02/21 à 23:29, Jarkko Sakkinen a écrit :
Quoted 145 lines · Laurent Bigonville
Quoted 130 lines
Le 16/02/21 à 17:34, Jarkko Sakkinen a écrit :
Quoted 28 lines · Jarkko Sakkinen
Quoted 27 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Quoted 25 lines
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg
Quoted 8 lines
Quoted 6 lines
Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)
And apply this patch on top. Cannot apply it there before it's reviewed.
I get the following stacktrace with your branch and the patch here:
[   13.498925] ------------[ cut here ]------------
[   13.498930] TPM returned invalid status
[   13.498953] WARNING: CPU: 1 PID: 459 at drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.498963] Modules linked in: libiscsi_tcp(E) tpm_tis(E+) tpm_tis_core(E) libiscsi(E) snd_timer(E) tpm(E) joydev(E) snd(E) scsi_transport_iscsi(E) pcc_cpufreq(E-) fjes(E-) soundcore(E) i7core_edac(E) i5500_temp(E) asus_atk0110(E) rng_core(E) acpi_cpufreq(E-) evdev(E) loop(E) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) ahci(E) libahci(E) libata(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) uhci_hcd(E) ehci_pci(E) firewire_ohci(E) crc32c_intel(E) ehci_hcd(E) drm_kms_helper(E) firewire_core(E) i2c_i801(E) psmouse(E)
[   13.499044] scsi_mod(E) cec(E) i2c_smbus(E) mxm_wmi(E) lpc_ich(E) crc_itu_t(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E) [   13.499058] CPU: 1 PID: 459 Comm: systemd-udevd Tainted: G          I E     5.11.0+ #4
[   13.499062] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.499064] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.499069] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d 83 48 00 00 00 75 e0 48 c7 c7 4c 53 49 c1 88 44 24 07 c6 05 6f 48 00 00 01 e8 b2 24 ba cd <0f> 0b 0f b6 44 24 07 eb c0 e8 fc 99 bd cd 66 66 2e 0f 1f 84 00 00
[   13.499072] RSP: 0018:ffffbaeb80fb3aa0 EFLAGS: 00010286
[   13.499075] RAX: 0000000000000000 RBX: ffff9704034e5000 RCX:
ffff9707ada58bc8
[   13.499078] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI:
ffff9707ada58bc0
[   13.499080] RBP: 00000000ffff5d40 R08: 0000000000000000 R09:
ffffbaeb80fb38c0
[   13.499082] R10: ffffbaeb80fb38b8 R11: ffffffff8fac2588 R12:
0000000000000016
[   13.499085] R13: ffff97040c38d000 R14: 0000000000001000 R15:
ffffbaeb80fb3ada
[   13.499087] FS: 00007fe1bcfeb8c0(0000) GS:ffff9707ada40000(0000) knlGS:0000000000000000
[   13.499090] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [   13.499092] CR2: 000055e5f7048590 CR3: 00000001084fe000 CR4:
00000000000006e0
[   13.499095] Call Trace:
[   13.499099] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.499113] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.499121] tpm2_probe+0xe2/0x140 [tpm]
[   13.499130] tpm_tis_core_init+0x1d5/0x2b0 [tpm_tis_core]
[   13.499135] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.499141] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.499148] pnp_device_probe+0xaf/0x140
[   13.499154] really_probe+0xf2/0x440
[   13.499160] driver_probe_device+0xe1/0x150
[   13.499163] device_driver_attach+0xa1/0xb0
[   13.499167] __driver_attach+0x8a/0x150
[   13.499171] ? device_driver_attach+0xb0/0xb0
[   13.499174] ? device_driver_attach+0xb0/0xb0
[   13.499177] bus_for_each_dev+0x78/0xc0
[   13.499181] bus_add_driver+0x12b/0x1e0
[   13.499184] driver_register+0x8b/0xe0
[   13.499188] ? 0xffffffffc1413000
[   13.499191] init_tis+0xa0/0x1000 [tpm_tis]
[   13.499197] do_one_initcall+0x44/0x1d0
[   13.499202] ? do_init_module+0x23/0x260
[   13.499206] ? kmem_cache_alloc_trace+0xf5/0x200
[   13.499212] do_init_module+0x5c/0x260
[   13.499215] __do_sys_finit_module+0xb1/0x110
[   13.499225] do_syscall_64+0x33/0x80
[   13.499229] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.499234] RIP: 0033:0x7fe1bd4a49b9
[   13.499237] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.499240] RSP: 002b:00007ffca5bfa108 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.499243] RAX: ffffffffffffffda RBX: 000055e5f7036920 RCX:
00007fe1bd4a49b9
[   13.499245] RDX: 0000000000000000 RSI: 00007fe1bd62fe2d RDI:
0000000000000012
[   13.499247] RBP: 0000000000020000 R08: 0000000000000000 R09:
000055e5f6e7a0b0
[   13.499249] R10: 0000000000000012 R11: 0000000000000246 R12:
00007fe1bd62fe2d
[   13.499251] R13: 0000000000000000 R14: 000055e5f7033420 R15:
000055e5f7036920
[   13.499255] ---[ end trace 7e963e5c3647102e ]---
If I also apply the patch to change the WARN_ONCE in dev_warn_once, and grep on the string "tpm", I get the following:
Quoted 12 lines
Feb 16 19:51:22 fornost kernel: tpm tpm0: TPM returned invalid status: 0xa0
Feb 16 19:51:22 fornost kernel: tpm_tis 00:06: 1.2 TPM (device-id 0x6871,
rev-id 1)
Feb 16 19:51:24 fornost kernel: tpm tpm0: tpm_try_transmit: send(): error
-62
Feb 16 19:51:24 fornost kernel: tpm tpm0: A TPM error (-62) occurred
attempting to determine the timeouts
Feb 16 19:51:24 fornost kernel: tpm_tis: probe of 00:06 failed with error
-62
Feb 16 19:51:24 fornost kernel: tpm_inf_pnp 00:06: Found TPM with ID IFX0102
No immediate idea why this happens as the code should take locality.

Quoted 8 lines

Quoted 5 lines
Quoted 3 lines
I noticed that the original patch bundles incorrectly two fixes, so I send mu PT without the current fix and turn into a patch set. Let's try to debug this for rc2/rc3.
Hey, I'm coming back regarding this issue, I'm running 5.10 (from debian unstable) and still getting this issue
Many of the fixes are landing to 5.13, stable kernels do not acquire out-of-tree fixes unless downstream maintainers decide to apply them by hand.

OK I tried again with linus master branch (5.13.0-rc4+) and your linux-tpmdd branch and the problem persists

Jarkko Sakkinen

author maintainer

2021-06-09 12:43 UTC #19 lore raw

Quoted 152 lines · Laurent Bigonville

Le 3/06/21 à 07:28, Jarkko Sakkinen a écrit :
Quoted 150 lines · Laurent Bigonville
Quoted 149 lines
Le 17/02/21 à 23:29, Jarkko Sakkinen a écrit :
Quoted 148 lines · Laurent Bigonville
Quoted 130 lines
Le 16/02/21 à 17:34, Jarkko Sakkinen a écrit :
Quoted 28 lines · Jarkko Sakkinen
Quoted 27 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Quoted 25 lines
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg
Quoted 8 lines
Quoted 6 lines
Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)
And apply this patch on top. Cannot apply it there before it's reviewed.
I get the following stacktrace with your branch and the patch here:
[   13.498925] ------------[ cut here ]------------
[   13.498930] TPM returned invalid status
[   13.498953] WARNING: CPU: 1 PID: 459 at drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.498963] Modules linked in: libiscsi_tcp(E) tpm_tis(E+) tpm_tis_core(E) libiscsi(E) snd_timer(E) tpm(E) joydev(E) snd(E) scsi_transport_iscsi(E) pcc_cpufreq(E-) fjes(E-) soundcore(E) i7core_edac(E) i5500_temp(E) asus_atk0110(E) rng_core(E) acpi_cpufreq(E-) evdev(E) loop(E) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) ahci(E) libahci(E) libata(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) uhci_hcd(E) ehci_pci(E) firewire_ohci(E) crc32c_intel(E) ehci_hcd(E) drm_kms_helper(E) firewire_core(E) i2c_i801(E) psmouse(E)
[   13.499044] scsi_mod(E) cec(E) i2c_smbus(E) mxm_wmi(E) lpc_ich(E) crc_itu_t(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E) [   13.499058] CPU: 1 PID: 459 Comm: systemd-udevd Tainted: G          I E     5.11.0+ #4
[   13.499062] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.499064] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.499069] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d 83 48 00 00 00 75 e0 48 c7 c7 4c 53 49 c1 88 44 24 07 c6 05 6f 48 00 00 01 e8 b2 24 ba cd <0f> 0b 0f b6 44 24 07 eb c0 e8 fc 99 bd cd 66 66 2e 0f 1f 84 00 00
[   13.499072] RSP: 0018:ffffbaeb80fb3aa0 EFLAGS: 00010286
[   13.499075] RAX: 0000000000000000 RBX: ffff9704034e5000 RCX:
ffff9707ada58bc8
[   13.499078] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI:
ffff9707ada58bc0
[   13.499080] RBP: 00000000ffff5d40 R08: 0000000000000000 R09:
ffffbaeb80fb38c0
[   13.499082] R10: ffffbaeb80fb38b8 R11: ffffffff8fac2588 R12:
0000000000000016
[   13.499085] R13: ffff97040c38d000 R14: 0000000000001000 R15:
ffffbaeb80fb3ada
[   13.499087] FS: 00007fe1bcfeb8c0(0000) GS:ffff9707ada40000(0000) knlGS:0000000000000000
[   13.499090] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [   13.499092] CR2: 000055e5f7048590 CR3: 00000001084fe000 CR4:
00000000000006e0
[   13.499095] Call Trace:
[   13.499099] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.499113] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.499121] tpm2_probe+0xe2/0x140 [tpm]
[   13.499130] tpm_tis_core_init+0x1d5/0x2b0 [tpm_tis_core]
[   13.499135] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.499141] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.499148] pnp_device_probe+0xaf/0x140
[   13.499154] really_probe+0xf2/0x440
[   13.499160] driver_probe_device+0xe1/0x150
[   13.499163] device_driver_attach+0xa1/0xb0
[   13.499167] __driver_attach+0x8a/0x150
[   13.499171] ? device_driver_attach+0xb0/0xb0
[   13.499174] ? device_driver_attach+0xb0/0xb0
[   13.499177] bus_for_each_dev+0x78/0xc0
[   13.499181] bus_add_driver+0x12b/0x1e0
[   13.499184] driver_register+0x8b/0xe0
[   13.499188] ? 0xffffffffc1413000
[   13.499191] init_tis+0xa0/0x1000 [tpm_tis]
[   13.499197] do_one_initcall+0x44/0x1d0
[   13.499202] ? do_init_module+0x23/0x260
[   13.499206] ? kmem_cache_alloc_trace+0xf5/0x200
[   13.499212] do_init_module+0x5c/0x260
[   13.499215] __do_sys_finit_module+0xb1/0x110
[   13.499225] do_syscall_64+0x33/0x80
[   13.499229] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.499234] RIP: 0033:0x7fe1bd4a49b9
[   13.499237] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.499240] RSP: 002b:00007ffca5bfa108 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.499243] RAX: ffffffffffffffda RBX: 000055e5f7036920 RCX:
00007fe1bd4a49b9
[   13.499245] RDX: 0000000000000000 RSI: 00007fe1bd62fe2d RDI:
0000000000000012
[   13.499247] RBP: 0000000000020000 R08: 0000000000000000 R09:
000055e5f6e7a0b0
[   13.499249] R10: 0000000000000012 R11: 0000000000000246 R12:
00007fe1bd62fe2d
[   13.499251] R13: 0000000000000000 R14: 000055e5f7033420 R15:
000055e5f7036920
[   13.499255] ---[ end trace 7e963e5c3647102e ]---
If I also apply the patch to change the WARN_ONCE in dev_warn_once, and grep on the string "tpm", I get the following:
Quoted 12 lines
Feb 16 19:51:22 fornost kernel: tpm tpm0: TPM returned invalid status: 0xa0
Feb 16 19:51:22 fornost kernel: tpm_tis 00:06: 1.2 TPM (device-id 0x6871,
rev-id 1)
Feb 16 19:51:24 fornost kernel: tpm tpm0: tpm_try_transmit: send(): error
-62
Feb 16 19:51:24 fornost kernel: tpm tpm0: A TPM error (-62) occurred
attempting to determine the timeouts
Feb 16 19:51:24 fornost kernel: tpm_tis: probe of 00:06 failed with error
-62
Feb 16 19:51:24 fornost kernel: tpm_inf_pnp 00:06: Found TPM with ID IFX0102
No immediate idea why this happens as the code should take locality.
I noticed that the original patch bundles incorrectly two fixes, so I send mu PT without the current fix and turn into a patch set. Let's try to debug this for rc2/rc3.

Quoted 7 lines

Quoted 5 lines
Quoted 2 lines
Hey, I'm coming back regarding this issue, I'm running 5.10 (from debian unstable) and still getting this issue
Many of the fixes are landing to 5.13, stable kernels do not acquire out-of-tree fixes unless downstream maintainers decide to apply them by hand.
OK I tried again with linus master branch (5.13.0-rc4+) and your linux-tpmdd branch and the problem persists

Do have a klog for this?

/Jarkko

Laurent Bigonville

2021-06-10 11:35 UTC #20 lore raw

Le 9/06/21 à 14:43, Jarkko Sakkinen a écrit :

Quoted 152 lines · Laurent Bigonville

Quoted 151 lines
Le 3/06/21 à 07:28, Jarkko Sakkinen a écrit :
Quoted 150 lines · Laurent Bigonville
Quoted 149 lines
Le 17/02/21 à 23:29, Jarkko Sakkinen a écrit :
Quoted 148 lines · Laurent Bigonville
Quoted 130 lines
Le 16/02/21 à 17:34, Jarkko Sakkinen a écrit :
Quoted 28 lines · Jarkko Sakkinen
Quoted 27 lines · Jarkko Sakkinen
Quoted 26 lines · Laurent Bigonville
Quoted 25 lines
Le 16/02/21 à 09:17, Jarkko Sakkinen a écrit :
Quoted 17 lines
From: Lukasz Majczak <[email protected]>
This is shown with Samsung Chromebook Pro (Caroline) with TPM 1.2 (SLB 9670):
[    4.324298] TPM returned invalid status
[    4.324806] WARNING: CPU: 2 PID: 1 at drivers/char/tpm/tpm_tis_core.c:275 tpm_tis_status+0x86/0x8f
Background
==========
TCG PC Client Platform TPM Profile (PTP) Specification, paragraph 6.1 FIFO Interface Locality Usage per Register, Table 39 Register Behavior Based on Locality Setting for FIFO - a read attempt to TPM_STS_x Registers returns 0xFF in case of lack of locality. The described situation manifests itself with the following warning trace:
Quoted 5 lines
The fix
=======
Add the proper decorations to tpm_tis_gen_interrupt() and tpm_get_timeouts().
I tried that patch (alone on the top of the HEAD of Linus master) and I still get the same trace in dmesg
Quoted 8 lines
Quoted 6 lines
Quoted 5 lines
Can you give a shot to
git://git.kernel.org/pub/scm/linux/kernel/git/jarkko/linux-tpmdd.git
It has couple of more fixes, and paste the log.
And if possible a full stack trace :-)
And apply this patch on top. Cannot apply it there before it's reviewed.
I get the following stacktrace with your branch and the patch here:
[   13.498925] ------------[ cut here ]------------
[   13.498930] TPM returned invalid status
[   13.498953] WARNING: CPU: 1 PID: 459 at drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.498963] Modules linked in: libiscsi_tcp(E) tpm_tis(E+) tpm_tis_core(E) libiscsi(E) snd_timer(E) tpm(E) joydev(E) snd(E) scsi_transport_iscsi(E) pcc_cpufreq(E-) fjes(E-) soundcore(E) i7core_edac(E) i5500_temp(E) asus_atk0110(E) rng_core(E) acpi_cpufreq(E-) evdev(E) loop(E) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) ahci(E) libahci(E) libata(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) uhci_hcd(E) ehci_pci(E) firewire_ohci(E) crc32c_intel(E) ehci_hcd(E) drm_kms_helper(E) firewire_core(E) i2c_i801(E) psmouse(E)
[   13.499044] scsi_mod(E) cec(E) i2c_smbus(E) mxm_wmi(E) lpc_ich(E) crc_itu_t(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E) [   13.499058] CPU: 1 PID: 459 Comm: systemd-udevd Tainted: G          I E     5.11.0+ #4
[   13.499062] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.499064] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core] [   13.499069] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d 83 48 00 00 00 75 e0 48 c7 c7 4c 53 49 c1 88 44 24 07 c6 05 6f 48 00 00 01 e8 b2 24 ba cd <0f> 0b 0f b6 44 24 07 eb c0 e8 fc 99 bd cd 66 66 2e 0f 1f 84 00 00
[   13.499072] RSP: 0018:ffffbaeb80fb3aa0 EFLAGS: 00010286
[   13.499075] RAX: 0000000000000000 RBX: ffff9704034e5000 RCX:
ffff9707ada58bc8
[   13.499078] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI:
ffff9707ada58bc0
[   13.499080] RBP: 00000000ffff5d40 R08: 0000000000000000 R09:
ffffbaeb80fb38c0
[   13.499082] R10: ffffbaeb80fb38b8 R11: ffffffff8fac2588 R12:
0000000000000016
[   13.499085] R13: ffff97040c38d000 R14: 0000000000001000 R15:
ffffbaeb80fb3ada
[   13.499087] FS: 00007fe1bcfeb8c0(0000) GS:ffff9707ada40000(0000) knlGS:0000000000000000
[   13.499090] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [   13.499092] CR2: 000055e5f7048590 CR3: 00000001084fe000 CR4:
00000000000006e0
[   13.499095] Call Trace:
[   13.499099] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.499113] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.499121] tpm2_probe+0xe2/0x140 [tpm]
[   13.499130] tpm_tis_core_init+0x1d5/0x2b0 [tpm_tis_core]
[   13.499135] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.499141] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.499148] pnp_device_probe+0xaf/0x140
[   13.499154] really_probe+0xf2/0x440
[   13.499160] driver_probe_device+0xe1/0x150
[   13.499163] device_driver_attach+0xa1/0xb0
[   13.499167] __driver_attach+0x8a/0x150
[   13.499171] ? device_driver_attach+0xb0/0xb0
[   13.499174] ? device_driver_attach+0xb0/0xb0
[   13.499177] bus_for_each_dev+0x78/0xc0
[   13.499181] bus_add_driver+0x12b/0x1e0
[   13.499184] driver_register+0x8b/0xe0
[   13.499188] ? 0xffffffffc1413000
[   13.499191] init_tis+0xa0/0x1000 [tpm_tis]
[   13.499197] do_one_initcall+0x44/0x1d0
[   13.499202] ? do_init_module+0x23/0x260
[   13.499206] ? kmem_cache_alloc_trace+0xf5/0x200
[   13.499212] do_init_module+0x5c/0x260
[   13.499215] __do_sys_finit_module+0xb1/0x110
[   13.499225] do_syscall_64+0x33/0x80
[   13.499229] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.499234] RIP: 0033:0x7fe1bd4a49b9
[   13.499237] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.499240] RSP: 002b:00007ffca5bfa108 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.499243] RAX: ffffffffffffffda RBX: 000055e5f7036920 RCX:
00007fe1bd4a49b9
[   13.499245] RDX: 0000000000000000 RSI: 00007fe1bd62fe2d RDI:
0000000000000012
[   13.499247] RBP: 0000000000020000 R08: 0000000000000000 R09:
000055e5f6e7a0b0
[   13.499249] R10: 0000000000000012 R11: 0000000000000246 R12:
00007fe1bd62fe2d
[   13.499251] R13: 0000000000000000 R14: 000055e5f7033420 R15:
000055e5f7036920
[   13.499255] ---[ end trace 7e963e5c3647102e ]---
If I also apply the patch to change the WARN_ONCE in dev_warn_once, and grep on the string "tpm", I get the following:
Quoted 12 lines
Feb 16 19:51:22 fornost kernel: tpm tpm0: TPM returned invalid status: 0xa0
Feb 16 19:51:22 fornost kernel: tpm_tis 00:06: 1.2 TPM (device-id 0x6871,
rev-id 1)
Feb 16 19:51:24 fornost kernel: tpm tpm0: tpm_try_transmit: send(): error
-62
Feb 16 19:51:24 fornost kernel: tpm tpm0: A TPM error (-62) occurred
attempting to determine the timeouts
Feb 16 19:51:24 fornost kernel: tpm_tis: probe of 00:06 failed with error
-62
Feb 16 19:51:24 fornost kernel: tpm_inf_pnp 00:06: Found TPM with ID IFX0102
No immediate idea why this happens as the code should take locality.
I noticed that the original patch bundles incorrectly two fixes, so I send mu PT without the current fix and turn into a patch set. Let's try to debug this for rc2/rc3.

Quoted 8 lines

Quoted 7 lines
Quoted 5 lines
Quoted 2 lines
Hey, I'm coming back regarding this issue, I'm running 5.10 (from debian unstable) and still getting this issue
Many of the fixes are landing to 5.13, stable kernels do not acquire out-of-tree fixes unless downstream maintainers decide to apply them by hand.
OK I tried again with linus master branch (5.13.0-rc4+) and your linux-tpmdd branch and the problem persists
Do have a klog for this?

In dmesg I see the following:

[   13.018702] ------------[ cut here ]------------
[   13.018706] TPM returned invalid status
[   13.018720] WARNING: CPU: 1 PID: 450 at drivers/char/tpm/tpm_tis_core.c:205 tpm_tis_status+0x86/0xa0 [tpm_tis_core]
[   13.018728] Modules linked in: tpm_tis(E+) tpm_tis_core(E) tpm(E) asus_atk0110(E) rng_core(E) fjes(E-) evdev(E) acpi_cpufreq(E-) loop(E+) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ahci(E) ttm(E) libahci(E) firewire_ohci(E) i2c_i801(E) libata(E) drm_kms_helper(E) uhci_hcd(E) ehci_pci(E) cec(E) crc32c_intel(E) firewire_core(E) mxm_wmi(E) psmouse(E) ehci_hcd(E) crc_itu_t(E) i2c_smbus(E) scsi_mod(E) lpc_ich(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E) [   13.018782] CPU: 1 PID: 450 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc4+ #6
[   13.018784] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.018786] RIP: 0010:tpm_tis_status+0x86/0xa0 [tpm_tis_core]
[   13.018790] Code: 00 75 30 48 83 c4 18 c3 31 c0 80 3d c3 49 00 00 00 75 e0 48 c7 c7 64 03 4d c1 88 44 24 07 c6 05 af 49 00 00 01 e8 42 ab b8 f0 <0f> 0b 0f b6 44 24 07 eb c0 e8 9c 36 bc f0 66 66 2e 0f 1f 84 00 00
[   13.018792] RSP: 0000:ffffae84807f3a98 EFLAGS: 00010282
[   13.018794] RAX: 0000000000000000 RBX: ffff96e5491b9000 RCX: ffff96e8eda58788
[   13.018795] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff96e8eda58780
[   13.018797] RBP: 00000000ffff5cf4 R08: 0000000000000000 R09: ffffae84807f38c0
[   13.018798] R10: ffffae84807f38b8 R11: ffffffffb2ac3888 R12: 0000000000000016
[   13.018800] R13: ffff96e550d1e000 R14: 0000000000001000 R15: ffffae84807f3ad2
[   13.018801] FS: 00007f75db70e8c0(0000) GS:ffff96e8eda40000(0000) knlGS:0000000000000000
[   13.018803] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   13.018805] CR2: 00007f75da19d077 CR3: 000000010675e000 CR4: 00000000000006e0
[   13.018807] Call Trace:
[   13.018810] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.018818] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.018824] tpm2_probe+0xe2/0x140 [tpm]
[   13.018830] tpm_tis_core_init+0x1d5/0x2aa [tpm_tis_core]
[   13.018834] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.018838] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.018843] pnp_device_probe+0xaf/0x140
[   13.018847] really_probe+0xf2/0x460
[   13.018852] driver_probe_device+0xe8/0x160
[   13.018854] device_driver_attach+0xa1/0xb0
[   13.018866] __driver_attach+0x8f/0x150
[   13.018869] ? device_driver_attach+0xb0/0xb0
[   13.018871] ? device_driver_attach+0xb0/0xb0
[   13.018873] bus_for_each_dev+0x78/0xc0
[   13.018876] bus_add_driver+0x12b/0x1e0
[   13.018879] driver_register+0x8b/0xe0
[   13.018881] ? 0xffffffffc14de000
[   13.018883] init_tis+0xa0/0x1000 [tpm_tis]
[   13.018888] do_one_initcall+0x44/0x1d0
[   13.018892] ? kmem_cache_alloc_trace+0x119/0x240
[   13.018896] do_init_module+0x5c/0x260
[   13.018900] __do_sys_finit_module+0xb1/0x110
[   13.018904] do_syscall_64+0x40/0xb0
[   13.018908] entry_SYSCALL_64_after_hwframe+0x44/0xae
[   13.018911] RIP: 0033:0x7f75dbbc79b9
[   13.018913] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.018926] RSP: 002b:00007ffe79a15068 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[   13.018929] RAX: ffffffffffffffda RBX: 0000555b250d19a0 RCX: 00007f75dbbc79b9
[   13.018930] RDX: 0000000000000000 RSI: 00007f75dbd52e2d RDI: 0000000000000012
[   13.018936] RBP: 0000000000020000 R08: 0000000000000000 R09: 0000555b250d0060
[   13.018938] R10: 0000000000000012 R11: 0000000000000246 R12: 00007f75dbd52e2d
[   13.018939] R13: 0000000000000000 R14: 0000555b250d1420 R15: 0000555b250d19a0
[   13.018944] ---[ end trace 6abb891c8492a76e ]---

And

# dmesg |grep -i tpm

[   13.019986] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1)
[   15.016198] tpm tpm0: tpm_try_transmit: send(): error -62
[   15.016208] tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts [   15.016239] tpm_tis: probe of 00:06 failed with error -62
[   15.053255] tpm_inf_pnp 00:06: Found TPM with ID IFX0102

Jarkko Sakkinen

author maintainer

2021-06-10 12:29 UTC #21 lore raw

Quoted 8 lines · Laurent Bigonville

# dmesg |grep -i tpm
[   13.019986] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1) [   15.016198] tpm tpm0: tpm_try_transmit: send(): error -62
[   15.016208] tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts
[   15.016239] tpm_tis: probe of 00:06 failed with error -62
[   15.053255] tpm_inf_pnp 00:06: Found TPM with ID IFX0102

If possible, can you check what happens when you apply the attached patch. I'm not proposing it as a bug fix but it just simplifies the flow a lot, and might help to observe something.

/Jarkko

From 0b0dfc48b47e44d547282b20f6d8c97103fadbe6 Mon Sep 17 00:00:00 2001
From: Jarkko Sakkinen <[email protected]>
Date: Thu, 10 Jun 2021 15:24:49 +0300
Subject: [PATCH] tpm_tis: Use request_locality() before calling tpm2_probe()

Avoid unnecessary round-tripping in and out of the TIS driver by calling request_locality() directly, instead of going through tpm_chip_start(), and for the consistency sake (other sites in initialization code work this way).

Signed-off-by Jarkko Sakkinen <[email protected]>

---
 drivers/char/tpm/tpm_tis_core.c | 8 +++-----
 1 file changed, 3 insertions(+), 5 deletions(-)

drivers/char/tpm/tpm_tis_core.c +3 -5

index 69579efb247b..3b5a03f9efce 100644
@@ -980,13 +980,11 @@ int tpm_tis_core_init(struct device *dev, struct tpm_tis_data *priv, int irq,
 	intmask &= ~TPM_GLOBAL_INT_ENABLE;
 	tpm_tis_write32(priv, TPM_INT_ENABLE(priv->locality), intmask);
 
-	rc = tpm_chip_start(chip);
-	if (rc)
+	rc = request_locality(chip, 0);
+	if (rc < 0)
 		goto out_err;
 	rc = tpm2_probe(chip);
-	tpm_chip_stop(chip);
-	if (rc)
-		goto out_err;
+	release_locality(chip, 0);
 
 	rc = tpm_tis_read32(priv, TPM_DID_VID(0), &vendor);
 	if (rc < 0)

Signature · 1 line

2.31.1

Laurent Bigonville

2021-06-10 14:00 UTC #22 lore raw

Le 10/06/21 à 14:29, Jarkko Sakkinen a écrit :

Quoted 9 lines · Laurent Bigonville

Quoted 8 lines
# dmesg |grep -i tpm
[   13.019986] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1) [   15.016198] tpm tpm0: tpm_try_transmit: send(): error -62
[   15.016208] tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts
[   15.016239] tpm_tis: probe of 00:06 failed with error -62
[   15.053255] tpm_inf_pnp 00:06: Found TPM with ID IFX0102

Quoted 4 lines

If possible, can you check what happens when you apply the attached patch. I'm not proposing it as a bug fix but it just simplifies the flow a lot, and might help to observe something.

With the patch on the top of HEAD of master and the patch from your branch, I'm getting this:

[   13.140548] tpm tpm0: invalid TPM_STS.x 0xa0, dumping stack for forensics
[   13.140617] CPU: 4 PID: 462 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc5+ #7
[   13.140621] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.140623] Call Trace:
[   13.140628] dump_stack+0x76/0x94
[   13.140637] tpm_tis_status.cold+0x19/0x20 [tpm_tis_core]
[   13.140643] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.140657] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.140666] tpm2_probe+0xe2/0x140 [tpm]
[   13.140676] tpm_tis_core_init+0x1d7/0x2ba [tpm_tis_core]
[   13.140681] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.140688] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.140695] pnp_device_probe+0xaf/0x140
[   13.140702] really_probe+0xf2/0x460
[   13.140708] driver_probe_device+0xe8/0x160
[   13.140712] device_driver_attach+0xa1/0xb0
[   13.140716] __driver_attach+0x8f/0x150
[   13.140720] ? device_driver_attach+0xb0/0xb0
[   13.140723] ? device_driver_attach+0xb0/0xb0
[   13.140726] bus_for_each_dev+0x78/0xc0
[   13.140730] bus_add_driver+0x12b/0x1e0
[   13.140734] driver_register+0x8b/0xe0
[   13.140738] ? 0xffffffffc11c4000
[   13.140741] init_tis+0xa0/0x1000 [tpm_tis]
[   13.140748] do_one_initcall+0x44/0x1d0
[   13.140754] ? kmem_cache_alloc_trace+0x119/0x240
[   13.140759] do_init_module+0x5c/0x260
[   13.140764] __do_sys_finit_module+0xb1/0x110
[   13.140769] do_syscall_64+0x40/0xb0
[   13.140775] entry_SYSCALL_64_after_hwframe+0x44/0xae
[   13.140780] RIP: 0033:0x7f082957b9b9
[   13.140783] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48 [   13.140786] RSP: 002b:00007fffd1b5a048 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[   13.140791] RAX: ffffffffffffffda RBX: 000055bd4f3f6960 RCX: 00007f082957b9b9
[   13.140793] RDX: 0000000000000000 RSI: 00007f0829706e2d RDI: 0000000000000012
[   13.140796] RBP: 0000000000020000 R08: 0000000000000000 R09: 000055bd4f238350
[   13.140798] R10: 0000000000000012 R11: 0000000000000246 R12: 00007f0829706e2d
[   13.140800] R13: 0000000000000000 R14: 000055bd4f2381c0 R15: 000055bd4f3f6960
[   13.141844] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1)

# dmesg |grep -i tpm

[...]
[   15.140121] tpm tpm0: tpm_try_transmit: send(): error -62
[   15.141852] tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts [   15.143596] tpm_tis: probe of 00:06 failed with error -62
[   15.185451] tpm_inf_pnp 00:06: Found TPM with ID IFX0102

Jarkko Sakkinen

author maintainer

2021-06-14 20:40 UTC #23 lore raw

Quoted 17 lines · Laurent Bigonville

Le 10/06/21 à 14:29, Jarkko Sakkinen a écrit :
Quoted 9 lines · Laurent Bigonville
Quoted 8 lines
# dmesg |grep -i tpm
[   13.019986] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1) [   15.016198] tpm tpm0: tpm_try_transmit: send(): error -62
[   15.016208] tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts
[   15.016239] tpm_tis: probe of 00:06 failed with error -62
[   15.053255] tpm_inf_pnp 00:06: Found TPM with ID IFX0102
Quoted 4 lines
If possible, can you check what happens when you apply the attached patch. I'm not proposing it as a bug fix but it just simplifies the flow a lot, and might help to observe something.
With the patch on the top of HEAD of master and the patch from your branch, I'm getting this:

Quoted 11 lines

[   13.140548] tpm tpm0: invalid TPM_STS.x 0xa0, dumping stack for forensics [   13.140617] CPU: 4 PID: 462 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc5+ #7
[   13.140621] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.140623] Call Trace:
[   13.140628] dump_stack+0x76/0x94
[   13.140637] tpm_tis_status.cold+0x19/0x20 [tpm_tis_core]
[   13.140643] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.140657] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.140666] tpm2_probe+0xe2/0x140 [tpm]

It's weird because it's the first transaction with the TPM, not likely to have any sort of mismatch in power gating.

I'm suspecting this:

	if (wait_startup(chip, 0) != 0) {
		rc = -ENODEV;
		goto out_err;
	}

I did not find anything from [*] stating that reading Access Register, could cause any change in the burstCount (0xa0) but still might be worth of testing to couple that with

	release_locality(chip, 0);

I.e. add that just after the first snippet.

[*] https://trustedcomputinggroup.org/resource/pc-client-platform-tpm-profile-ptp-specification/

/Jarkko

Laurent Bigonville

2021-06-15 11:20 UTC #24 lore raw

Le 14/06/21 à 22:40, Jarkko Sakkinen a écrit :

Quoted 39 lines · Laurent Bigonville

Quoted 17 lines
Le 10/06/21 à 14:29, Jarkko Sakkinen a écrit :
Quoted 9 lines · Laurent Bigonville
Quoted 8 lines
# dmesg |grep -i tpm
[   13.019986] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1) [   15.016198] tpm tpm0: tpm_try_transmit: send(): error -62
[   15.016208] tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts
[   15.016239] tpm_tis: probe of 00:06 failed with error -62
[   15.053255] tpm_inf_pnp 00:06: Found TPM with ID IFX0102
Quoted 4 lines
If possible, can you check what happens when you apply the attached patch. I'm not proposing it as a bug fix but it just simplifies the flow a lot, and might help to observe something.
With the patch on the top of HEAD of master and the patch from your branch, I'm getting this:
Quoted 11 lines
[   13.140548] tpm tpm0: invalid TPM_STS.x 0xa0, dumping stack for forensics [   13.140617] CPU: 4 PID: 462 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc5+ #7
[   13.140621] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.140623] Call Trace:
[   13.140628] dump_stack+0x76/0x94
[   13.140637] tpm_tis_status.cold+0x19/0x20 [tpm_tis_core]
[   13.140643] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.140657] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.140666] tpm2_probe+0xe2/0x140 [tpm]
It's weird because it's the first transaction with the TPM, not likely to have any sort of mismatch in power gating.
I'm suspecting this:
	if (wait_startup(chip, 0) != 0) {
		rc = -ENODEV;
		goto out_err;
	}

Quoted 8 lines

I did not find anything from [*] stating that reading Access Register, could cause any change in the burstCount (0xa0) but still might be worth of testing to couple that with
	release_locality(chip, 0);
I.e. add that just after the first snippet.

You mean this, right?

drivers/char/tpm/tpm_tis_core.c +0 -0

index 3b5a03f9efce..857ea790e9d3 100644
@@ -969,6 +969,7 @@ int tpm_tis_core_init(struct device *dev, struct tpm_tis_data *priv, int irq,

                rc = -ENODEV;
                goto out_err;
        }
+       release_locality(chip, 0);

/* Take control of the TPM's interrupt hardware and shut it off */ rc = tpm_tis_read32(priv, TPM_INT_ENABLE(priv->locality), &intmask);

With this change (and with or without "tpm_tis: Use request_locality() before calling tpm2_probe()"), I get the following:

[   13.420485] tpm tpm0: invalid TPM_STS.x 0xff, dumping stack for forensics
[   13.420494] CPU: 5 PID: 461 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc6+ #8
[   13.420498] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.420500] Call Trace:
[   13.420505] dump_stack+0x76/0x94
[   13.420512] tpm_tis_status.cold+0x19/0x20 [tpm_tis_core]
[   13.420519] wait_for_tpm_stat+0x49/0x200 [tpm_tis_core]
[   13.420524] ? get_page_from_freelist+0x228/0xed0
[   13.420530] ? tpm_tcg_read_bytes+0x30/0x50 [tpm_tis]
[   13.420536] tpm_tis_send_data+0x90/0x250 [tpm_tis_core]
[   13.420542] tpm_tis_send_main+0x2e/0xf0 [tpm_tis_core]
[   13.420547] tpm_transmit+0xd8/0x3d0 [tpm]
[   13.420559] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.420567] tpm2_probe+0xe2/0x140 [tpm]
[   13.420577] tpm_tis_core_init+0x1fd/0x2e0 [tpm_tis_core]
[   13.420582] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.420587] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.420594] pnp_device_probe+0xaf/0x140
[   13.420600] really_probe+0xf2/0x460
[   13.420606] driver_probe_device+0xe8/0x160
[   13.420610] device_driver_attach+0xa1/0xb0
[   13.420614] __driver_attach+0x8f/0x150
[   13.420618] ? device_driver_attach+0xb0/0xb0
[   13.420621] ? device_driver_attach+0xb0/0xb0
[   13.420624] bus_for_each_dev+0x78/0xc0
[   13.420628] bus_add_driver+0x12b/0x1e0
[   13.420632] driver_register+0x8b/0xe0
[   13.420636] ? 0xffffffffc1413000
[   13.420639] init_tis+0xa0/0x1000 [tpm_tis]
[   13.420646] do_one_initcall+0x44/0x1d0
[   13.420652] ? kmem_cache_alloc_trace+0x119/0x240
[   13.420657] do_init_module+0x5c/0x260
[   13.420662] __do_sys_finit_module+0xb1/0x110
[   13.420668] do_syscall_64+0x40/0xb0
[   13.420673] entry_SYSCALL_64_after_hwframe+0x44/0xae
[   13.420678] RIP: 0033:0x7f15fe84e9b9
[   13.420681] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48 [   13.420685] RSP: 002b:00007fffc3aca668 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[   13.420689] RAX: ffffffffffffffda RBX: 00005561627275b0 RCX: 00007f15fe84e9b9
[   13.420692] RDX: 0000000000000000 RSI: 00007f15fe9d9e2d RDI: 0000000000000012
[   13.420694] RBP: 0000000000020000 R08: 0000000000000000 R09: 0000556161c2f330
[   13.420696] R10: 0000000000000012 R11: 0000000000000246 R12: 00007f15fe9d9e2d
[   13.420698] R13: 0000000000000000 R14: 000055616271dab0 R15: 00005561627275b0
[...]
[   14.185406] tpm tpm0: tpm_try_transmit: send(): error -62
[   14.185422] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1)
[   15.021233] tpm tpm0: tpm_try_transmit: send(): error -62
[   24.381575] tpm tpm0: tpm_try_transmit: send(): error -62
[...]

But now the /dev/tpm0 device appears (but doesn't seem to work)

Jarkko Sakkinen

author maintainer

2021-06-15 12:56 UTC #25 lore raw

Quoted 129 lines · Laurent Bigonville

Le 14/06/21 à 22:40, Jarkko Sakkinen a écrit :
Quoted 39 lines · Laurent Bigonville
Quoted 17 lines
Le 10/06/21 à 14:29, Jarkko Sakkinen a écrit :
Quoted 9 lines · Laurent Bigonville
Quoted 8 lines
# dmesg |grep -i tpm
[   13.019986] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1) [   15.016198] tpm tpm0: tpm_try_transmit: send(): error -62
[   15.016208] tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts
[   15.016239] tpm_tis: probe of 00:06 failed with error -62
[   15.053255] tpm_inf_pnp 00:06: Found TPM with ID IFX0102
Quoted 4 lines
If possible, can you check what happens when you apply the attached patch. I'm not proposing it as a bug fix but it just simplifies the flow a lot, and might help to observe something.
With the patch on the top of HEAD of master and the patch from your branch, I'm getting this:
Quoted 11 lines
[   13.140548] tpm tpm0: invalid TPM_STS.x 0xa0, dumping stack for forensics [   13.140617] CPU: 4 PID: 462 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc5+ #7
[   13.140621] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.140623] Call Trace:
[   13.140628] dump_stack+0x76/0x94
[   13.140637] tpm_tis_status.cold+0x19/0x20 [tpm_tis_core]
[   13.140643] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.140657] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.140666] tpm2_probe+0xe2/0x140 [tpm]
It's weird because it's the first transaction with the TPM, not likely to have any sort of mismatch in power gating.
I'm suspecting this:
	if (wait_startup(chip, 0) != 0) {
		rc = -ENODEV;
		goto out_err;
	}
Quoted 8 lines
I did not find anything from [*] stating that reading Access Register, could cause any change in the burstCount (0xa0) but still might be worth of testing to couple that with
	release_locality(chip, 0);
I.e. add that just after the first snippet.
You mean this, right?
drivers/char/tpm/tpm_tis_core.c +1 -0
index 3b5a03f9efce..857ea790e9d3 100644
@@ -969,6 +969,7 @@ int tpm_tis_core_init(struct device *dev, struct
 tpm_tis_data *priv, int irq,
                 rc = -ENODEV;
                 goto out_err;
         }
+       release_locality(chip, 0);
 
         /* Take control of the TPM's interrupt hardware and shut it off */
        rc = tpm_tis_read32(priv, TPM_INT_ENABLE(priv->locality), &intmask);
With this change (and with or without "tpm_tis: Use request_locality() before calling tpm2_probe()"), I get the following:
[   13.420485] tpm tpm0: invalid TPM_STS.x 0xff, dumping stack for forensics [   13.420494] CPU: 5 PID: 461 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc6+ #8
[   13.420498] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.420500] Call Trace:
[   13.420505] dump_stack+0x76/0x94
[   13.420512] tpm_tis_status.cold+0x19/0x20 [tpm_tis_core]
[   13.420519] wait_for_tpm_stat+0x49/0x200 [tpm_tis_core]
[   13.420524] ? get_page_from_freelist+0x228/0xed0
[   13.420530] ? tpm_tcg_read_bytes+0x30/0x50 [tpm_tis]
[   13.420536] tpm_tis_send_data+0x90/0x250 [tpm_tis_core]
[   13.420542] tpm_tis_send_main+0x2e/0xf0 [tpm_tis_core]
[   13.420547] tpm_transmit+0xd8/0x3d0 [tpm]
[   13.420559] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.420567] tpm2_probe+0xe2/0x140 [tpm]
[   13.420577] tpm_tis_core_init+0x1fd/0x2e0 [tpm_tis_core]
[   13.420582] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.420587] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.420594] pnp_device_probe+0xaf/0x140
[   13.420600] really_probe+0xf2/0x460
[   13.420606] driver_probe_device+0xe8/0x160
[   13.420610] device_driver_attach+0xa1/0xb0
[   13.420614] __driver_attach+0x8f/0x150
[   13.420618] ? device_driver_attach+0xb0/0xb0
[   13.420621] ? device_driver_attach+0xb0/0xb0
[   13.420624] bus_for_each_dev+0x78/0xc0
[   13.420628] bus_add_driver+0x12b/0x1e0
[   13.420632] driver_register+0x8b/0xe0
[   13.420636] ? 0xffffffffc1413000
[   13.420639] init_tis+0xa0/0x1000 [tpm_tis]
[   13.420646] do_one_initcall+0x44/0x1d0
[   13.420652] ? kmem_cache_alloc_trace+0x119/0x240
[   13.420657] do_init_module+0x5c/0x260
[   13.420662] __do_sys_finit_module+0xb1/0x110
[   13.420668] do_syscall_64+0x40/0xb0
[   13.420673] entry_SYSCALL_64_after_hwframe+0x44/0xae
[   13.420678] RIP: 0033:0x7f15fe84e9b9
[   13.420681] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.420685] RSP: 002b:00007fffc3aca668 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.420689] RAX: ffffffffffffffda RBX: 00005561627275b0 RCX:
00007f15fe84e9b9
[   13.420692] RDX: 0000000000000000 RSI: 00007f15fe9d9e2d RDI:
0000000000000012
[   13.420694] RBP: 0000000000020000 R08: 0000000000000000 R09:
0000556161c2f330
[   13.420696] R10: 0000000000000012 R11: 0000000000000246 R12:
00007f15fe9d9e2d
[   13.420698] R13: 0000000000000000 R14: 000055616271dab0 R15:
00005561627275b0
[...]
[   14.185406] tpm tpm0: tpm_try_transmit: send(): error -62
[   14.185422] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1) [   15.021233] tpm tpm0: tpm_try_transmit: send(): error -62
[   24.381575] tpm tpm0: tpm_try_transmit: send(): error -62 [...]

Quoted 1 line

But now the /dev/tpm0 device appears (but doesn't seem to work)

I'm sorry, I made a mistake: release_locality() call should be exactly right before tpm_chip_start(). The reason is that we access TPM_INT_ENABLE, i.e. locality is released too early.

In summary, I think I would try this:

	tpm_chip_stop(chip);

	rc = tpm_chip_start(chip);
	if (rc)
		goto out_err;
	rc = tpm2_probe(chip);
	tpm_chip_stop(chip);
	if (rc)
		goto out_err;

tpm_chip_stop() is makes more sense it takes care also of disabling clk_enable.

I.e. TPM should be shut down right after intmask mangling...

/Jarkko

Laurent Bigonville

2021-06-15 16:27 UTC #26 lore raw

Le 15/06/21 à 14:56, Jarkko Sakkinen a écrit :

Quoted 147 lines · Laurent Bigonville

Quoted 129 lines
Le 14/06/21 à 22:40, Jarkko Sakkinen a écrit :
Quoted 39 lines · Laurent Bigonville
Quoted 17 lines
Le 10/06/21 à 14:29, Jarkko Sakkinen a écrit :
Quoted 9 lines · Laurent Bigonville
Quoted 8 lines
# dmesg |grep -i tpm
[   13.019986] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1) [   15.016198] tpm tpm0: tpm_try_transmit: send(): error -62
[   15.016208] tpm tpm0: A TPM error (-62) occurred attempting to determine the timeouts
[   15.016239] tpm_tis: probe of 00:06 failed with error -62
[   15.053255] tpm_inf_pnp 00:06: Found TPM with ID IFX0102
Quoted 4 lines
If possible, can you check what happens when you apply the attached patch. I'm not proposing it as a bug fix but it just simplifies the flow a lot, and might help to observe something.
With the patch on the top of HEAD of master and the patch from your branch, I'm getting this:
Quoted 11 lines
[   13.140548] tpm tpm0: invalid TPM_STS.x 0xa0, dumping stack for forensics [   13.140617] CPU: 4 PID: 462 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc5+ #7
[   13.140621] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.140623] Call Trace:
[   13.140628] dump_stack+0x76/0x94
[   13.140637] tpm_tis_status.cold+0x19/0x20 [tpm_tis_core]
[   13.140643] tpm_transmit+0x15f/0x3d0 [tpm]
[   13.140657] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.140666] tpm2_probe+0xe2/0x140 [tpm]
It's weird because it's the first transaction with the TPM, not likely to have any sort of mismatch in power gating.
I'm suspecting this:
	if (wait_startup(chip, 0) != 0) {
		rc = -ENODEV;
		goto out_err;
	}
Quoted 8 lines
I did not find anything from [*] stating that reading Access Register, could cause any change in the burstCount (0xa0) but still might be worth of testing to couple that with
	release_locality(chip, 0);
I.e. add that just after the first snippet.
You mean this, right?
drivers/char/tpm/tpm_tis_core.c +1 -0
index 3b5a03f9efce..857ea790e9d3 100644
@@ -969,6 +969,7 @@ int tpm_tis_core_init(struct device *dev, struct
 tpm_tis_data *priv, int irq,
                 rc = -ENODEV;
                 goto out_err;
         }
+       release_locality(chip, 0);
 
         /* Take control of the TPM's interrupt hardware and shut it off */
        rc = tpm_tis_read32(priv, TPM_INT_ENABLE(priv->locality), &intmask);
With this change (and with or without "tpm_tis: Use request_locality() before calling tpm2_probe()"), I get the following:
[   13.420485] tpm tpm0: invalid TPM_STS.x 0xff, dumping stack for forensics [   13.420494] CPU: 5 PID: 461 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc6+ #8
[   13.420498] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.420500] Call Trace:
[   13.420505] dump_stack+0x76/0x94
[   13.420512] tpm_tis_status.cold+0x19/0x20 [tpm_tis_core]
[   13.420519] wait_for_tpm_stat+0x49/0x200 [tpm_tis_core]
[   13.420524] ? get_page_from_freelist+0x228/0xed0
[   13.420530] ? tpm_tcg_read_bytes+0x30/0x50 [tpm_tis]
[   13.420536] tpm_tis_send_data+0x90/0x250 [tpm_tis_core]
[   13.420542] tpm_tis_send_main+0x2e/0xf0 [tpm_tis_core]
[   13.420547] tpm_transmit+0xd8/0x3d0 [tpm]
[   13.420559] tpm_transmit_cmd+0x25/0x90 [tpm]
[   13.420567] tpm2_probe+0xe2/0x140 [tpm]
[   13.420577] tpm_tis_core_init+0x1fd/0x2e0 [tpm_tis_core]
[   13.420582] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.420587] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.420594] pnp_device_probe+0xaf/0x140
[   13.420600] really_probe+0xf2/0x460
[   13.420606] driver_probe_device+0xe8/0x160
[   13.420610] device_driver_attach+0xa1/0xb0
[   13.420614] __driver_attach+0x8f/0x150
[   13.420618] ? device_driver_attach+0xb0/0xb0
[   13.420621] ? device_driver_attach+0xb0/0xb0
[   13.420624] bus_for_each_dev+0x78/0xc0
[   13.420628] bus_add_driver+0x12b/0x1e0
[   13.420632] driver_register+0x8b/0xe0
[   13.420636] ? 0xffffffffc1413000
[   13.420639] init_tis+0xa0/0x1000 [tpm_tis]
[   13.420646] do_one_initcall+0x44/0x1d0
[   13.420652] ? kmem_cache_alloc_trace+0x119/0x240
[   13.420657] do_init_module+0x5c/0x260
[   13.420662] __do_sys_finit_module+0xb1/0x110
[   13.420668] do_syscall_64+0x40/0xb0
[   13.420673] entry_SYSCALL_64_after_hwframe+0x44/0xae
[   13.420678] RIP: 0033:0x7f15fe84e9b9
[   13.420681] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.420685] RSP: 002b:00007fffc3aca668 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[   13.420689] RAX: ffffffffffffffda RBX: 00005561627275b0 RCX:
00007f15fe84e9b9
[   13.420692] RDX: 0000000000000000 RSI: 00007f15fe9d9e2d RDI:
0000000000000012
[   13.420694] RBP: 0000000000020000 R08: 0000000000000000 R09:
0000556161c2f330
[   13.420696] R10: 0000000000000012 R11: 0000000000000246 R12:
00007f15fe9d9e2d
[   13.420698] R13: 0000000000000000 R14: 000055616271dab0 R15:
00005561627275b0
[...]
[   14.185406] tpm tpm0: tpm_try_transmit: send(): error -62
[   14.185422] tpm_tis 00:06: 1.2 TPM (device-id 0x6871, rev-id 1) [   15.021233] tpm tpm0: tpm_try_transmit: send(): error -62
[   24.381575] tpm tpm0: tpm_try_transmit: send(): error -62 [...]
Quoted 1 line
But now the /dev/tpm0 device appears (but doesn't seem to work)
I'm sorry, I made a mistake: release_locality() call should be exactly right before tpm_chip_start(). The reason is that we access TPM_INT_ENABLE, i.e. locality is released too early.
In summary, I think I would try this:
	tpm_chip_stop(chip);

	rc = tpm_chip_start(chip);
	if (rc)
		goto out_err;
	rc = tpm2_probe(chip);
	tpm_chip_stop(chip);
	if (rc)
		goto out_err;

Quoted 4 lines

tpm_chip_stop() is makes more sense it takes care also of disabling clk_enable.
I.e. TPM should be shut down right after intmask mangling...

Sorry to bring bad news but it's still not working :(

With the following change:

drivers/char/tpm/tpm_tis_core.c +0 -0

index 69579efb247b..45ad813ce840 100644
@@ -980,6 +980,8 @@ int tpm_tis_core_init(struct device *dev, struct tpm_tis_data *priv, int irq,

intmask &= ~TPM_GLOBAL_INT_ENABLE; tpm_tis_write32(priv, TPM_INT_ENABLE(priv->locality), intmask);

+       tpm_chip_stop(chip);
+
        rc = tpm_chip_start(chip);
        if (rc)
                goto out_err;

I get now a Oops

[   13.438251] BUG: unable to handle page fault for address: ffff9e8141157000
[   13.438257] #PF: supervisor write access in kernel mode
[   13.438259] #PF: error_code(0x0002) - not-present page
[   13.438261] PGD 100000067 P4D 100000067 PUD 0
[   13.438265] Oops: 0002 [#1] SMP PTI
[   13.438268] CPU: 7 PID: 469 Comm: systemd-udevd Tainted: G          I E     5.13.0-rc6+ #8
[   13.438271] Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS 0406    04/24/2009
[   13.438273] RIP: 0010:iowrite8+0x9/0x50
[   13.438282] Code: 48 c7 c2 e8 6a 10 98 48 89 04 24 e8 ac 5e 3f 00 0f 0b 48 8b 04 24 48 83 c4 08 c3 66 0f 1f 44 00 00 48 81 fe ff ff 03 00 76 04 <40> 88 3e c3 48 81 fe 00 00 01 00 76 07 0f b7 d6 89 f8 ee c3 8b 05
[   13.438286] RSP: 0018:ffff9e8040f23b10 EFLAGS: 00010292
[   13.438289] RAX: ffffffffc15440b0 RBX: ffff9e8040f23b48 RCX: ffff9e8040f23b47
[   13.438292] RDX: 0000000000000001 RSI: ffff9e8141157000 RDI: 0000000000000020
[   13.438295] RBP: ffff9e8040f23b48 R08: ffff88f2108bf018 R09: ffff88f20104b290
[   13.438297] R10: 0000000000000002 R11: 0000000000000004 R12: ffff88f2108bf018
[   13.438300] R13: 00000000fffff000 R14: ffff88f20104b000 R15: 00000000ffffffff
[   13.438303] FS: 00007fafaab758c0(0000) GS:ffff88f5adbc0000(0000) knlGS:0000000000000000
[   13.438307] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   13.438310] CR2: ffff9e8141157000 CR3: 00000001065ca000 CR4: 00000000000006e0
[   13.438313] Call Trace:
[   13.438318] tpm_tcg_write_bytes+0x33/0x50 [tpm_tis]
[   13.438326] release_locality+0x3c/0x60 [tpm_tis_core]
[   13.438331] tpm_relinquish_locality+0x24/0x40 [tpm]
[   13.438342] tpm_chip_stop+0x26/0x50 [tpm]
[   13.438351] tpm_tis_core_init+0x1c2/0x2b2 [tpm_tis_core]
[   13.438357] ? tpm_tis_init.part.0+0x130/0x130 [tpm_tis]
[   13.438363] tpm_tis_pnp_init+0xe1/0x110 [tpm_tis]
[   13.438370] pnp_device_probe+0xaf/0x140
[   13.438377] really_probe+0xf2/0x460
[   13.438384] driver_probe_device+0xe8/0x160
[   13.438388] device_driver_attach+0xa1/0xb0
[   13.438393] __driver_attach+0x8f/0x150
[   13.438397] ? device_driver_attach+0xb0/0xb0
[   13.438402] ? device_driver_attach+0xb0/0xb0
[   13.438405] bus_for_each_dev+0x78/0xc0
[   13.438410] bus_add_driver+0x12b/0x1e0
[   13.438415] driver_register+0x8b/0xe0
[   13.438419] ? 0xffffffffc1549000
[   13.438422] init_tis+0xa0/0x1000 [tpm_tis]
[   13.438430] do_one_initcall+0x44/0x1d0
[   13.438437] ? kmem_cache_alloc_trace+0x119/0x240
[   13.438444] do_init_module+0x5c/0x260
[   13.438450] __do_sys_finit_module+0xb1/0x110
[   13.438456] do_syscall_64+0x40/0xb0
[   13.438462] entry_SYSCALL_64_after_hwframe+0x44/0xae
[   13.438467] RIP: 0033:0x7fafab02e9b9
[   13.438471] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a7 54 0c 00 f7 d8 64 89 01 48
[   13.438475] RSP: 002b:00007ffe03c50528 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[   13.438480] RAX: ffffffffffffffda RBX: 00005596198bfc00 RCX: 00007fafab02e9b9
[   13.438483] RDX: 0000000000000000 RSI: 00007fafab1b9e2d RDI: 0000000000000012
[   13.438486] RBP: 0000000000020000 R08: 0000000000000000 R09: 00005596198baaa0
[   13.438489] R10: 0000000000000012 R11: 0000000000000246 R12: 00007fafab1b9e2d
[   13.438492] R13: 0000000000000000 R14: 00005596198bab20 R15: 00005596198bfc00
[   13.438497] Modules linked in: tpm_tis(E+) tpm_tis_core(E) tpm(E) asus_atk0110(E) rng_core(E) fjes(E-) evdev(E) acpi_cpufreq(E-) loop(E+) firewire_sbp2(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) sunrpc(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) btrfs(E) blake2b_generic(E) zstd_compress(E) efivars(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) raid0(E) multipath(E) linear(E) md_mod(E) dm_mod(E) sr_mod(E) sd_mod(E) cdrom(E) t10_pi(E) hid_generic(E) usbhid(E) hid(E) amdgpu(E) gpu_sched(E) i2c_algo_bit(E) drm_ttm_helper(E) ttm(E) ahci(E) libahci(E) drm_kms_helper(E) i2c_i801(E) firewire_ohci(E) ehci_pci(E) uhci_hcd(E) libata(E) firewire_core(E) cec(E) crc32c_intel(E) mxm_wmi(E) psmouse(E) ehci_hcd(E) crc_itu_t(E) scsi_mod(E) i2c_smbus(E) lpc_ich(E) sky2(E) usbcore(E) drm(E) mfd_core(E) wmi(E) button(E) [   13.438584] CR2: ffff9e8141157000
[   13.438587] ---[ end trace 25e12430fd1718f9 ]---
[   13.438589] RIP: 0010:iowrite8+0x9/0x50
[   13.438594] Code: 48 c7 c2 e8 6a 10 98 48 89 04 24 e8 ac 5e 3f 00 0f 0b 48 8b 04 24 48 83 c4 08 c3 66 0f 1f 44 00 00 48 81 fe ff ff 03 00 76 04 <40> 88 3e c3 48 81 fe 00 00 01 00 76 07 0f b7 d6 89 f8 ee c3 8b 05
[   13.438597] RSP: 0018:ffff9e8040f23b10 EFLAGS: 00010292
[   13.438601] RAX: ffffffffc15440b0 RBX: ffff9e8040f23b48 RCX: ffff9e8040f23b47
[   13.438604] RDX: 0000000000000001 RSI: ffff9e8141157000 RDI: 0000000000000020
[   13.438606] RBP: ffff9e8040f23b48 R08: ffff88f2108bf018 R09: ffff88f20104b290
[   13.438609] R10: 0000000000000002 R11: 0000000000000004 R12: ffff88f2108bf018
[   13.438612] R13: 00000000fffff000 R14: ffff88f20104b000 R15: 00000000ffffffff
[   13.438615] FS: 00007fafaab758c0(0000) GS:ffff88f5adbc0000(0000) knlGS:0000000000000000
[   13.438619] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   13.438622] CR2: ffff9e8141157000 CR3: 00000001065ca000 CR4: 00000000000006e0