INFO: task hung in tls_sw_release_resources_tx

INFO: task hung in tls_sw_release_resources_tx

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit:    6d5afe20 sctp: fix memleak in sctp_send_reset_streams
git tree:       net
console output: https://syzkaller.appspot.com/x/log.txt?x=16e5536a600000
kernel config:  https://syzkaller.appspot.com/x/.config?x=a4c9e9f08e9e8960
dashboard link: https://syzkaller.appspot.com/bug?extid=6a9ff159672dfbb41c95
compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=17cb0502600000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=14d5dc22600000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+6a9ff159672dfbb41c95@syzkaller.appspotmail.com

INFO: task syz-executor153:10198 blocked for more than 143 seconds.
       Not tainted 5.3.0-rc3+ #162
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor153 D27672 10198  10179 0x80000002
Call Trace:
  context_switch kernel/sched/core.c:3254 [inline]
  __schedule+0x755/0x1580 kernel/sched/core.c:3880
  schedule+0xa8/0x270 kernel/sched/core.c:3944
  schedule_timeout+0x717/0xc50 kernel/time/timer.c:1783
  do_wait_for_common kernel/sched/completion.c:83 [inline]
  __wait_for_common kernel/sched/completion.c:104 [inline]
  wait_for_common kernel/sched/completion.c:115 [inline]
  wait_for_completion+0x29c/0x440 kernel/sched/completion.c:136
  crypto_wait_req include/linux/crypto.h:685 [inline]
  crypto_wait_req include/linux/crypto.h:680 [inline]
  tls_sw_release_resources_tx+0x4ee/0x6b0 net/tls/tls_sw.c:2075
  tls_sk_proto_cleanup net/tls/tls_main.c:275 [inline]
  tls_sk_proto_close+0x686/0x970 net/tls/tls_main.c:305
  inet_release+0xed/0x200 net/ipv4/af_inet.c:427
  inet6_release+0x53/0x80 net/ipv6/af_inet6.c:470
  __sock_release+0xce/0x280 net/socket.c:590
  sock_close+0x1e/0x30 net/socket.c:1268
  __fput+0x2ff/0x890 fs/file_table.c:280
  ____fput+0x16/0x20 fs/file_table.c:313
  task_work_run+0x145/0x1c0 kernel/task_work.c:113
  exit_task_work include/linux/task_work.h:22 [inline]
  do_exit+0x92f/0x2e50 kernel/exit.c:879
  do_group_exit+0x135/0x360 kernel/exit.c:983
  __do_sys_exit_group kernel/exit.c:994 [inline]
  __se_sys_exit_group kernel/exit.c:992 [inline]
  __x64_sys_exit_group+0x44/0x50 kernel/exit.c:992
  do_syscall_64+0xfd/0x6a0 arch/x86/entry/common.c:296
  entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x43ff88
Code: 00 00 be 3c 00 00 00 eb 19 66 0f 1f 84 00 00 00 00 00 48 89 d7 89 f0  
0f 05 48 3d 00 f0 ff ff 77 21 f4 48 89 d7 44 89 c0 0f 05 <48> 3d 00 f0 ff  
ff 76 e0 f7 d8 64 41 89 01 eb d8 0f 1f 84 00 00 00
RSP: 002b:00007ffd1c2d0f78 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 000000000043ff88
RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
RBP: 00000000004bf890 R08: 00000000000000e7 R09: ffffffffffffffd0
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
R13: 00000000006d1180 R14: 0000000000000000 R15: 0000000000000000
INFO: lockdep is turned off.
NMI backtrace for cpu 0
CPU: 0 PID: 1057 Comm: khungtaskd Not tainted 5.3.0-rc3+ #162
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS  
Google 01/01/2011
Call Trace:
  __dump_stack lib/dump_stack.c:77 [inline]
  dump_stack+0x172/0x1f0 lib/dump_stack.c:113
  nmi_cpu_backtrace.cold+0x70/0xb2 lib/nmi_backtrace.c:101
  nmi_trigger_cpumask_backtrace+0x23b/0x28b lib/nmi_backtrace.c:62
  arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
  trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
  check_hung_uninterruptible_tasks kernel/hung_task.c:205 [inline]
  watchdog+0x9d0/0xef0 kernel/hung_task.c:289
  kthread+0x361/0x430 kernel/kthread.c:255
  ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:352
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1 skipped: idling at native_safe_halt+0xe/0x10  
arch/x86/include/asm/irqflags.h:60


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzkaller@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
syzbot can test patches for this bug, for details see:
https://goo.gl/tpsmEJ#testing-patches

Re: INFO: task hung in tls_sw_release_resources_tx

[syzbot]

syzbot has bisected this bug to:

commit 130b392c6cd6b2aed1b7eb32253d4920babb4891
Author: Dave Watson <davejwatson@fb.com>
Date:   Wed Jan 30 21:58:31 2019 +0000

     net: tls: Add tls 1.3 support

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=118e8dee600000
start commit:   6d5afe20 sctp: fix memleak in sctp_send_reset_streams
git tree:       net
final crash:    https://syzkaller.appspot.com/x/report.txt?x=138e8dee600000
console output: https://syzkaller.appspot.com/x/log.txt?x=158e8dee600000
kernel config:  https://syzkaller.appspot.com/x/.config?x=a4c9e9f08e9e8960
dashboard link: https://syzkaller.appspot.com/bug?extid=6a9ff159672dfbb41c95
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=17cb0502600000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=14d5dc22600000

Reported-by: syzbot+6a9ff159672dfbb41c95@syzkaller.appspotmail.com
Fixes: 130b392c6cd6 ("net: tls: Add tls 1.3 support")

For information about bisection process see: https://goo.gl/tpsmEJ#bisection

Re: INFO: task hung in tls_sw_release_resources_tx

[Jakub Kicinski]

On Thu, 15 Aug 2019 22:14:19 +0800, Hillf Danton wrote:
> On Thu, 15 Aug 2019 03:54:06 -0700
> > Hello,
> > 
> > syzbot found the following crash on:
> > 
> > HEAD commit:    6d5afe20 sctp: fix memleak in sctp_send_reset_streams
> > git tree:       net
> > console output: https://syzkaller.appspot.com/x/log.txt?x=16e5536a600000
> > kernel config:  https://syzkaller.appspot.com/x/.config?x=a4c9e9f08e9e8960
> > dashboard link: https://syzkaller.appspot.com/bug?extid=6a9ff159672dfbb41c95
> > compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
> > syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=17cb0502600000
> > C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=14d5dc22600000
> > 
> > IMPORTANT: if you fix the bug, please add the following tag to the commit:
> > Reported-by: syzbot+6a9ff159672dfbb41c95@syzkaller.appspotmail.com
> > 
> > INFO: task syz-executor153:10198 blocked for more than 143 seconds.
> >        Not tainted 5.3.0-rc3+ #162
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > syz-executor153 D27672 10198  10179 0x80000002
> > Call Trace:
> >   context_switch kernel/sched/core.c:3254 [inline]
> >   __schedule+0x755/0x1580 kernel/sched/core.c:3880
> >   schedule+0xa8/0x270 kernel/sched/core.c:3944
> >   schedule_timeout+0x717/0xc50 kernel/time/timer.c:1783
> >   do_wait_for_common kernel/sched/completion.c:83 [inline]
> >   __wait_for_common kernel/sched/completion.c:104 [inline]
> >   wait_for_common kernel/sched/completion.c:115 [inline]
> >   wait_for_completion+0x29c/0x440 kernel/sched/completion.c:136
> >   crypto_wait_req include/linux/crypto.h:685 [inline]
> >   crypto_wait_req include/linux/crypto.h:680 [inline]
> >   tls_sw_release_resources_tx+0x4ee/0x6b0 net/tls/tls_sw.c:2075
> >   tls_sk_proto_cleanup net/tls/tls_main.c:275 [inline]
> >   tls_sk_proto_close+0x686/0x970 net/tls/tls_main.c:305
> >   inet_release+0xed/0x200 net/ipv4/af_inet.c:427
> >   inet6_release+0x53/0x80 net/ipv6/af_inet6.c:470
> >   __sock_release+0xce/0x280 net/socket.c:590
> >   sock_close+0x1e/0x30 net/socket.c:1268
> >   __fput+0x2ff/0x890 fs/file_table.c:280
> >   ____fput+0x16/0x20 fs/file_table.c:313
> >   task_work_run+0x145/0x1c0 kernel/task_work.c:113
> >   exit_task_work include/linux/task_work.h:22 [inline]
> >   do_exit+0x92f/0x2e50 kernel/exit.c:879
> >   do_group_exit+0x135/0x360 kernel/exit.c:983
> >   __do_sys_exit_group kernel/exit.c:994 [inline]
> >   __se_sys_exit_group kernel/exit.c:992 [inline]
> >   __x64_sys_exit_group+0x44/0x50 kernel/exit.c:992
> >   do_syscall_64+0xfd/0x6a0 arch/x86/entry/common.c:296
> >   entry_SYSCALL_64_after_hwframe+0x49/0xbe
> > RIP: 0033:0x43ff88
> > Code: 00 00 be 3c 00 00 00 eb 19 66 0f 1f 84 00 00 00 00 00 48 89 d7 89 f0  
> > 0f 05 48 3d 00 f0 ff ff 77 21 f4 48 89 d7 44 89 c0 0f 05 <48> 3d 00 f0 ff  
> > ff 76 e0 f7 d8 64 41 89 01 eb d8 0f 1f 84 00 00 00
> > RSP: 002b:00007ffd1c2d0f78 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
> > RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 000000000043ff88
> > RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
> > RBP: 00000000004bf890 R08: 00000000000000e7 R09: ffffffffffffffd0
> > R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
> > R13: 00000000006d1180 R14: 0000000000000000 R15: 0000000000000000
> > INFO: lockdep is turned off.
> > NMI backtrace for cpu 0
> > CPU: 0 PID: 1057 Comm: khungtaskd Not tainted 5.3.0-rc3+ #162
> > Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS  
> > Google 01/01/2011
> > Call Trace:
> >   __dump_stack lib/dump_stack.c:77 [inline]
> >   dump_stack+0x172/0x1f0 lib/dump_stack.c:113
> >   nmi_cpu_backtrace.cold+0x70/0xb2 lib/nmi_backtrace.c:101
> >   nmi_trigger_cpumask_backtrace+0x23b/0x28b lib/nmi_backtrace.c:62
> >   arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
> >   trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
> >   check_hung_uninterruptible_tasks kernel/hung_task.c:205 [inline]
> >   watchdog+0x9d0/0xef0 kernel/hung_task.c:289
> >   kthread+0x361/0x430 kernel/kthread.c:255
> >   ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:352
> > Sending NMI from CPU 0 to CPUs 1:
> > NMI backtrace for cpu 1 skipped: idling at native_safe_halt+0xe/0x10  
> > arch/x86/include/asm/irqflags.h:60  
> 
> 1, diff -> commit f87e62d45e51 -> commit 1023121375c6
> 
> --- a/net/tls/tls_sw.c
> +++ b/net/tls/tls_sw.c
> @@ -2167,11 +2167,13 @@ static void tx_work_handler(struct work_
>  		return;
>  
>  	ctx = tls_sw_ctx_tx(tls_ctx);
> -	if (test_bit(BIT_TX_CLOSING, &ctx->tx_bitmask))
> -		return;
> -
> -	if (!test_and_clear_bit(BIT_TX_SCHEDULED, &ctx->tx_bitmask))
> -		return;
> +	if (test_bit(BIT_TX_CLOSING, &ctx->tx_bitmask)) {
> +		if (!test_bit(BIT_TX_SCHEDULED, &ctx->tx_bitmask))
> +			return;
> +	} else {
> +		if (!test_and_clear_bit(BIT_TX_SCHEDULED, &ctx->tx_bitmask))
> +			return;
> +	}
>  	lock_sock(sk);
>  	tls_tx_records(sk, -1);
>  	release_sock(sk);
> --
> 
> 2, a simpler one. And clear BIT_TX_SCHEDULED perhaps after releasing sock.
> 
> --- a/net/tls/tls_sw.c
> +++ b/net/tls/tls_sw.c
> @@ -2167,11 +2167,9 @@ static void tx_work_handler(struct work_
>  		return;
>  
>  	ctx = tls_sw_ctx_tx(tls_ctx);
> -	if (test_bit(BIT_TX_CLOSING, &ctx->tx_bitmask))
> -		return;
> +	if (!test_bit(BIT_TX_CLOSING, &ctx->tx_bitmask))
> +		clear_bit(BIT_TX_SCHEDULED, &ctx->tx_bitmask);
>  
> -	if (!test_and_clear_bit(BIT_TX_SCHEDULED, &ctx->tx_bitmask))
> -		return;
>  	lock_sock(sk);
>  	tls_tx_records(sk, -1);
>  	release_sock(sk);

Mmm.. too terse, I don't follow what you're trying to do here :(

I've been staring at this for a while and trying to repo but it's not
happening here.

The only thing I see is that EBUSY is not handled.