* tpm2_createprim blocked for more than 122 seconds
@ 2022-08-16 1:07 Anatol Pomozov
2022-08-16 14:27 ` Jarkko Sakkinen
0 siblings, 1 reply; 4+ messages in thread
From: Anatol Pomozov @ 2022-08-16 1:07 UTC (permalink / raw)
To: linux-integrity
Hello folks,
I am running a tool that performs some basic operations (seal/unseal)
with TPM. Most of my machines work fine. Though once in a while I see
the following problem with my tool:
[7955220.676259] INFO: task tpm2_createprim:258741 blocked for more
than 122 seconds.
[7955220.683837] Not tainted 5.10.89-t3.el7.twitter.x86_64 #1
[7955220.689848] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[7955220.697846] task:tpm2_createprim state:D stack: 0 pid:258741
ppid:258724 flags:0x10000080
[7955220.706454] Call Trace:
[7955220.709088] __schedule+0x266/0x840
[7955220.712756] schedule+0x46/0xb0
[7955220.716073] schedule_preempt_disabled+0xa/0x10
[7955220.720780] __mutex_lock.constprop.0+0x123/0x440
[7955220.725660] ? handle_mm_fault+0x168b/0x1ae0
[7955220.730105] tpm_try_get_ops+0x3c/0x90
[7955220.734035] tpm_common_write+0xfb/0x1c0
[7955220.738141] vfs_write+0xc0/0x260
[7955220.741636] ksys_write+0x4f/0xc0
[7955220.745134] do_syscall_64+0x33/0x40
[7955220.748886] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[7955220.754111] RIP: 0033:0x7fbd13d446e0
[7955220.757864] RSP: 002b:00007ffc77d004f8 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[7955220.765603] RAX: ffffffffffffffda RBX: 0000000000000000 RCX:
00007fbd13d446e0
[7955220.772910] RDX: 0000000000000043 RSI: 00005626520d33e8 RDI:
0000000000000003
[7955220.780215] RBP: 00005626520d22f0 R08: 00007ffc77d004c4 R09:
00007ffc77d006b0
[7955220.787519] R10: 00007ffc77cfff60 R11: 0000000000000246 R12:
00005626520d33e8
[7955220.794827] R13: 0000000000000043 R14: 0000000000000000 R15:
00007ffc77d00780
[7955290.222553] tpm tpm0: Operation Timed out
[7955292.226513] tpm tpm0: tpm_try_transmit: send(): error -62
[8311409.491438] tpm tpm0: tpm_try_transmit: send(): error -62
[8311412.625426] tpm tpm0: tpm_try_transmit: send(): error -62
The kernel is 5.10.89; CentOS7. I do not know how to reproduce the
problem reliably. I know if I reboot the host it gets "fixed".
Is it a known problem? If not what would be the best way to debug it?
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: tpm2_createprim blocked for more than 122 seconds
2022-08-16 1:07 tpm2_createprim blocked for more than 122 seconds Anatol Pomozov
@ 2022-08-16 14:27 ` Jarkko Sakkinen
2022-08-16 16:29 ` Anatol Pomozov
0 siblings, 1 reply; 4+ messages in thread
From: Jarkko Sakkinen @ 2022-08-16 14:27 UTC (permalink / raw)
To: Anatol Pomozov; +Cc: linux-integrity
On Mon, Aug 15, 2022 at 06:07:00PM -0700, Anatol Pomozov wrote:
> Hello folks,
>
> I am running a tool that performs some basic operations (seal/unseal)
> with TPM. Most of my machines work fine. Though once in a while I see
> the following problem with my tool:
>
> [7955220.676259] INFO: task tpm2_createprim:258741 blocked for more
> than 122 seconds.
> [7955220.683837] Not tainted 5.10.89-t3.el7.twitter.x86_64 #1
> [7955220.689848] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [7955220.697846] task:tpm2_createprim state:D stack: 0 pid:258741
> ppid:258724 flags:0x10000080
> [7955220.706454] Call Trace:
> [7955220.709088] __schedule+0x266/0x840
> [7955220.712756] schedule+0x46/0xb0
> [7955220.716073] schedule_preempt_disabled+0xa/0x10
> [7955220.720780] __mutex_lock.constprop.0+0x123/0x440
> [7955220.725660] ? handle_mm_fault+0x168b/0x1ae0
> [7955220.730105] tpm_try_get_ops+0x3c/0x90
> [7955220.734035] tpm_common_write+0xfb/0x1c0
> [7955220.738141] vfs_write+0xc0/0x260
> [7955220.741636] ksys_write+0x4f/0xc0
> [7955220.745134] do_syscall_64+0x33/0x40
> [7955220.748886] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [7955220.754111] RIP: 0033:0x7fbd13d446e0
> [7955220.757864] RSP: 002b:00007ffc77d004f8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000001
> [7955220.765603] RAX: ffffffffffffffda RBX: 0000000000000000 RCX:
> 00007fbd13d446e0
> [7955220.772910] RDX: 0000000000000043 RSI: 00005626520d33e8 RDI:
> 0000000000000003
> [7955220.780215] RBP: 00005626520d22f0 R08: 00007ffc77d004c4 R09:
> 00007ffc77d006b0
> [7955220.787519] R10: 00007ffc77cfff60 R11: 0000000000000246 R12:
> 00005626520d33e8
> [7955220.794827] R13: 0000000000000043 R14: 0000000000000000 R15:
> 00007ffc77d00780
> [7955290.222553] tpm tpm0: Operation Timed out
> [7955292.226513] tpm tpm0: tpm_try_transmit: send(): error -62
> [8311409.491438] tpm tpm0: tpm_try_transmit: send(): error -62
> [8311412.625426] tpm tpm0: tpm_try_transmit: send(): error -62
>
>
>
> The kernel is 5.10.89; CentOS7. I do not know how to reproduce the
> problem reliably. I know if I reboot the host it gets "fixed".
>
> Is it a known problem? If not what would be the best way to debug it?
We really cannot give feedback on non-mainline issues.
BR, Jarkko
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: tpm2_createprim blocked for more than 122 seconds
2022-08-16 14:27 ` Jarkko Sakkinen
@ 2022-08-16 16:29 ` Anatol Pomozov
2022-08-26 3:10 ` Jarkko Sakkinen
0 siblings, 1 reply; 4+ messages in thread
From: Anatol Pomozov @ 2022-08-16 16:29 UTC (permalink / raw)
To: Jarkko Sakkinen; +Cc: linux-integrity
Hi
On Tue, Aug 16, 2022 at 7:27 AM Jarkko Sakkinen <jarkko@kernel.org> wrote:
>
> On Mon, Aug 15, 2022 at 06:07:00PM -0700, Anatol Pomozov wrote:
> > Hello folks,
> >
> > I am running a tool that performs some basic operations (seal/unseal)
> > with TPM. Most of my machines work fine. Though once in a while I see
> > the following problem with my tool:
> >
> > [7955220.676259] INFO: task tpm2_createprim:258741 blocked for more
> > than 122 seconds.
> > [7955220.683837] Not tainted 5.10.89-t3.el7.twitter.x86_64 #1
> > [7955220.689848] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables this message.
> > [7955220.697846] task:tpm2_createprim state:D stack: 0 pid:258741
> > ppid:258724 flags:0x10000080
> > [7955220.706454] Call Trace:
> > [7955220.709088] __schedule+0x266/0x840
> > [7955220.712756] schedule+0x46/0xb0
> > [7955220.716073] schedule_preempt_disabled+0xa/0x10
> > [7955220.720780] __mutex_lock.constprop.0+0x123/0x440
> > [7955220.725660] ? handle_mm_fault+0x168b/0x1ae0
> > [7955220.730105] tpm_try_get_ops+0x3c/0x90
> > [7955220.734035] tpm_common_write+0xfb/0x1c0
> > [7955220.738141] vfs_write+0xc0/0x260
> > [7955220.741636] ksys_write+0x4f/0xc0
> > [7955220.745134] do_syscall_64+0x33/0x40
> > [7955220.748886] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> > [7955220.754111] RIP: 0033:0x7fbd13d446e0
> > [7955220.757864] RSP: 002b:00007ffc77d004f8 EFLAGS: 00000246 ORIG_RAX:
> > 0000000000000001
> > [7955220.765603] RAX: ffffffffffffffda RBX: 0000000000000000 RCX:
> > 00007fbd13d446e0
> > [7955220.772910] RDX: 0000000000000043 RSI: 00005626520d33e8 RDI:
> > 0000000000000003
> > [7955220.780215] RBP: 00005626520d22f0 R08: 00007ffc77d004c4 R09:
> > 00007ffc77d006b0
> > [7955220.787519] R10: 00007ffc77cfff60 R11: 0000000000000246 R12:
> > 00005626520d33e8
> > [7955220.794827] R13: 0000000000000043 R14: 0000000000000000 R15:
> > 00007ffc77d00780
> > [7955290.222553] tpm tpm0: Operation Timed out
> > [7955292.226513] tpm tpm0: tpm_try_transmit: send(): error -62
> > [8311409.491438] tpm tpm0: tpm_try_transmit: send(): error -62
> > [8311412.625426] tpm tpm0: tpm_try_transmit: send(): error -62
> >
> >
> >
> > The kernel is 5.10.89; CentOS7. I do not know how to reproduce the
> > problem reliably. I know if I reboot the host it gets "fixed".
> >
> > Is it a known problem? If not what would be the best way to debug it?
>
> We really cannot give feedback on non-mainline issues.
The kernel that is used here is 5.10.89 compiled from the stable repo.
So it is as mainline as a production kernel can be.
I also saw the same issues with 5.10.113 (also compiled from stable repo).
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: tpm2_createprim blocked for more than 122 seconds
2022-08-16 16:29 ` Anatol Pomozov
@ 2022-08-26 3:10 ` Jarkko Sakkinen
0 siblings, 0 replies; 4+ messages in thread
From: Jarkko Sakkinen @ 2022-08-26 3:10 UTC (permalink / raw)
To: Anatol Pomozov; +Cc: linux-integrity
On Tue, Aug 16, 2022 at 09:29:29AM -0700, Anatol Pomozov wrote:
> Hi
>
> On Tue, Aug 16, 2022 at 7:27 AM Jarkko Sakkinen <jarkko@kernel.org> wrote:
> >
> > On Mon, Aug 15, 2022 at 06:07:00PM -0700, Anatol Pomozov wrote:
> > > Hello folks,
> > >
> > > I am running a tool that performs some basic operations (seal/unseal)
> > > with TPM. Most of my machines work fine. Though once in a while I see
> > > the following problem with my tool:
> > >
> > > [7955220.676259] INFO: task tpm2_createprim:258741 blocked for more
> > > than 122 seconds.
> > > [7955220.683837] Not tainted 5.10.89-t3.el7.twitter.x86_64 #1
> > > [7955220.689848] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > > disables this message.
> > > [7955220.697846] task:tpm2_createprim state:D stack: 0 pid:258741
> > > ppid:258724 flags:0x10000080
> > > [7955220.706454] Call Trace:
> > > [7955220.709088] __schedule+0x266/0x840
> > > [7955220.712756] schedule+0x46/0xb0
> > > [7955220.716073] schedule_preempt_disabled+0xa/0x10
> > > [7955220.720780] __mutex_lock.constprop.0+0x123/0x440
> > > [7955220.725660] ? handle_mm_fault+0x168b/0x1ae0
> > > [7955220.730105] tpm_try_get_ops+0x3c/0x90
> > > [7955220.734035] tpm_common_write+0xfb/0x1c0
> > > [7955220.738141] vfs_write+0xc0/0x260
> > > [7955220.741636] ksys_write+0x4f/0xc0
> > > [7955220.745134] do_syscall_64+0x33/0x40
> > > [7955220.748886] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> > > [7955220.754111] RIP: 0033:0x7fbd13d446e0
> > > [7955220.757864] RSP: 002b:00007ffc77d004f8 EFLAGS: 00000246 ORIG_RAX:
> > > 0000000000000001
> > > [7955220.765603] RAX: ffffffffffffffda RBX: 0000000000000000 RCX:
> > > 00007fbd13d446e0
> > > [7955220.772910] RDX: 0000000000000043 RSI: 00005626520d33e8 RDI:
> > > 0000000000000003
> > > [7955220.780215] RBP: 00005626520d22f0 R08: 00007ffc77d004c4 R09:
> > > 00007ffc77d006b0
> > > [7955220.787519] R10: 00007ffc77cfff60 R11: 0000000000000246 R12:
> > > 00005626520d33e8
> > > [7955220.794827] R13: 0000000000000043 R14: 0000000000000000 R15:
> > > 00007ffc77d00780
> > > [7955290.222553] tpm tpm0: Operation Timed out
> > > [7955292.226513] tpm tpm0: tpm_try_transmit: send(): error -62
> > > [8311409.491438] tpm tpm0: tpm_try_transmit: send(): error -62
> > > [8311412.625426] tpm tpm0: tpm_try_transmit: send(): error -62
> > >
> > >
> > >
> > > The kernel is 5.10.89; CentOS7. I do not know how to reproduce the
> > > problem reliably. I know if I reboot the host it gets "fixed".
> > >
> > > Is it a known problem? If not what would be the best way to debug it?
> >
> > We really cannot give feedback on non-mainline issues.
>
> The kernel that is used here is 5.10.89 compiled from the stable repo.
> So it is as mainline as a production kernel can be.
>
> I also saw the same issues with 5.10.113 (also compiled from stable repo).
I'm sorry got the wrong impression from your original email.
It's not really a problem that can be fixed though.
Primary key creation just takes enough time to trigger
this warning.
For pure interest, do you get the same result with O_NONBLOCK?
BR, Jarkko
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2022-08-26 3:11 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-08-16 1:07 tpm2_createprim blocked for more than 122 seconds Anatol Pomozov
2022-08-16 14:27 ` Jarkko Sakkinen
2022-08-16 16:29 ` Anatol Pomozov
2022-08-26 3:10 ` Jarkko Sakkinen
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.