Re: Recent tpm_tis IRQ handling changes are causing kernel backtraces

From: Jarkko Sakkinen <jarkko@kernel.org>
To: Hans de Goede <hdegoede@redhat.com>
Cc: Jerry Snitselaar <jsnitsel@redhat.com>,
	Matthew Garrett <mjg59@google.com>,
	James Bottomley <James.Bottomley@hansenpartnership.com>,
	linux-integrity <linux-integrity@vger.kernel.org>
Subject: Re: Recent tpm_tis IRQ handling changes are causing kernel backtraces
Date: Mon, 10 May 2021 20:25:10 +0300	[thread overview]
Message-ID: <YJlsdgxPIm5I6Jk8@kernel.org> (raw)
In-Reply-To: <8b592417-dc1d-a7f8-0e17-09b6bb1df33a@redhat.com>

On Sat, May 08, 2021 at 11:07:43AM +0200, Hans de Goede wrote:
> Hi Jarko,
> 
> On 3/16/21 8:18 PM, Jarkko Sakkinen wrote:
> > On Tue, Mar 16, 2021 at 04:34:01PM +0100, Hans de Goede wrote:
> >> Hi,
> >>
> >> On 2/11/21 2:09 PM, Hans de Goede wrote:
> >>> Hi Jerry,
> >>>
> >>> It looks like there still is an issue with the recent changes to the tpm_tis IRQ
> >>> handling. At least I think those are the cause I did not dive any deeper,
> >>> I just noticed that we (Fedora) have been receiving an aweful lot of
> >>> kernel tpm_tis_send_data backtraces with most starting with tpm_tis_probe_irq_...
> >>>
> >>> See for example:
> >>> https://bugzilla.redhat.com/show_bug.cgi?id=1912167
> >>> https://bugzilla.redhat.com/show_bug.cgi?id=1927610
> >>>
> >>> Those are just the 3 which landed in my inbox today, for much more see:
> >>> https://bugzilla.redhat.com/buglist.cgi?quicksearch=tpm_tis_send_data
> >>> (this shows 18 bugs atm).
> >>>
> >>> These were reported through the Fedora ABRT tools which automatically
> >>> collects backtraces, the bugs have links to the ABRT reports, e.g. :
> >>> https://retrace.fedoraproject.org/faf/reports/28155/
> >>> https://retrace.fedoraproject.org/faf/reports/37107/
> >>>
> >>> The 28155 report says that so far there have been 308,412 (ouch) automatic
> >>> uploads of that particular variant of these backtraces
> >>>
> >>> Note the second (37107) retrace report is about this happening
> >>> on resume, rather then on probe/tpm_tis_probe_irq_... time.
> >>>
> >>> Did your work on this work land in 5.10 ? Or could it be that the
> >>> issue is an incomplete backport to the 5.10.y stable series ?
> >>
> >> Ping ?
> >>
> >> It is raining bug-reports about this:
> >>
> >> https://bugzilla.redhat.com/buglist.cgi?quicksearch=tpm_tis_send_data
> >>
> >> Currently lists 25 bugs and that is excluding bugs which have already
> >> been marked as a duplicate.
> >>
> >> Can someone involved in the patch-series which is causing this regression
> >> please take a look at these kernel backtraces ?
> >>
> >> Regards,
> >>
> >> Hans
> > 
> > I incorporated two fixes to this issue to my last PR, which were taken
> > to the mainline. What is the situation with the mainline?
> 
> Thank you for your reply and sorry for being slow to respond.
> 
> Is this expected to be fixed in 5.11, or when you say mainline you
> main Linus' master branch / so the fixes are in 5.12 only ?
> 
> The reason I'm asking is because we just received another bugreport
> about this against 5.11.17. The bug is marked private (our tool to
> automatically file bugs for kernel backtraces does this) so let me
> just copy and paste the trace here:
> 
> WARNING: CPU: 0 PID: 3060 at drivers/char/tpm/tpm_tis_core.c:205
> tpm_tis_status+0x66/0x70
> 
> CPU: 0 PID: 3060 Comm: systemd-sleep Not tainted 5.11.17-200.fc33.x86_64 #1
> Hardware name: Hewlett-Packard HP ProBook 6460b/161D, BIOS 68SCE Ver. F.63
> 05/27/2016
> RIP: 0010:tpm_tis_status+0x66/0x70
> Code: 23 75 05 48 83 c4 10 c3 31 c0 80 3d 38 02 56 01 00 75 f0 48 c7 c7 94 67
> 43 96 88 44 24 07 c6 05 24 02 56 01 01 e8 4a 53 3c 00 <0f> 0b 0f b6 44 24 07 eb
> d0 90 66 66 66 66 90 41 57 41 56 41 55 41
> RSP: 0018:ffffaac581427b10 EFLAGS: 00010282
> RAX: 000000000000001b RBX: ffff9dc800b93000 RCX: ffff9dc83b418ac8
> RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff9dc83b418ac0
> RBP: ffff9dc800b93000 R08: ffffffff96a64ec0 R09: ffffaac581427ab0
> R10: 0000000000000001 R11: 000000002d2d2d2d R12: ffff9dc80667c268
> R13: ffff9dc801fd1000 R14: 0000000000000000 R15: ffffaac581427bca
> FS:  00007f8f0f32c000(0000) GS:ffff9dc83b400000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000557044ec6c86 CR3: 0000000062e92001 CR4: 00000000000606f0
> Call Trace:
>  tpm_tis_send_data+0x2b/0x230
>  tpm_tis_send_main+0x1e/0xe0
>  tpm_transmit+0xd8/0x3d0
>  tpm_transmit_cmd+0x25/0x90
>  tpm1_do_selftest+0x88/0x130
>  ? _cond_resched+0x16/0x40
>  tpm_tis_resume+0x4d/0x120
>  ? pnpacpi_resume+0x1b/0xa0
>  ? pnp_bus_suspend+0x10/0x10
>  pnp_bus_resume+0x63/0x90
>  dpm_run_callback+0x4c/0x120
>  device_resume+0xa7/0x200
>  dpm_resume+0xce/0x2c0
>  dpm_resume_end+0xd/0x20
>  suspend_devices_and_enter+0x195/0x750
>  pm_suspend.cold+0x329/0x374
>  state_store+0x71/0xd0
>  kernfs_fop_write_iter+0x124/0x1b0
>  new_sync_write+0x108/0x180
>  vfs_write+0x1bc/0x270
>  ksys_write+0x4f/0xc0
>  do_syscall_64+0x33/0x40
>  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> RIP: 0033:0x7f8f102ec4e7
> Code: 0d 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64
> 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51
> c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
> RSP: 002b:00007ffe87216bf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
> RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f8f102ec4e7
> RDX: 0000000000000004 RSI: 00007ffe87216ce0 RDI: 0000000000000004
> RBP: 00007ffe87216ce0 R08: 000055c485d835e0 R09: 00007f8f103830c0
> R10: 00007f8f10382fc0 R11: 0000000000000246 R12: 0000000000000004
> R13: 000055c485d7f650 R14: 0000000000000004 R15: 00007f8f103bf720
> 
> Regards,
> 
> Hans

I sent a couple fixes (cc'd to you).

/Jarkko