syzbot


INFO: task hung in snd_seq_write

Status: fixed on 2019/08/14 02:14
Subsystems: sound
[Documentation on labels]
Reported-by: syzbot+4c595632b98bb8ffcc66@syzkaller.appspotmail.com
Fix commit: ede34f397ddb ALSA: seq: Break too long mutex context in the write loop
First crash: 2280d, last: 2073d
Discussions (10)
Title Replies (including bot) Last reply
[PATCH 3.16 00/47] 3.16.76-rc1 review 57 (57) 2019/11/02 07:39
[PATCH 4.9 000/223] 4.9.187-stable review 231 (231) 2019/08/28 03:02
[PATCH 5.2 000/413] 5.2.3-stable review 444 (444) 2019/08/05 12:40
[PATCH 4.4 000/158] 4.4.187-stable review 166 (166) 2019/08/03 15:57
[PATCH 4.14 000/293] 4.14.135-stable review 302 (302) 2019/07/31 09:35
[PATCH 4.19 000/271] 4.19.61-stable review 284 (284) 2019/07/27 10:51
[PATCH 5.1 000/371] 5.1.20-stable review 384 (384) 2019/07/26 12:24
Reminder: 4 open syzbot bugs in sound subsystem 1 (1) 2019/07/09 20:18
Reminder: 9 open syzbot bugs in sound subsystem 1 (1) 2019/06/24 05:07
INFO: task hung in snd_seq_write 0 (1) 2018/08/27 21:03

Sample crash report:
INFO: task syz-executor1:7135 blocked for more than 140 seconds.
      Not tainted 4.19.0-rc6+ #265
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor1   D24128  7135   5409 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2825 [inline]
 __schedule+0x86c/0x1ed0 kernel/sched/core.c:3473
 schedule+0xfe/0x460 kernel/sched/core.c:3517
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:3575
 __mutex_lock_common kernel/locking/mutex.c:1002 [inline]
 __mutex_lock+0xbe7/0x1700 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 snd_seq_write+0x1f1/0x8d0 sound/core/seq/seq_clientmgr.c:1021
 __vfs_write+0x119/0x9f0 fs/read_write.c:485
 vfs_write+0x1fc/0x560 fs/read_write.c:549
 ksys_write+0x101/0x260 fs/read_write.c:598
 __do_sys_write fs/read_write.c:610 [inline]
 __se_sys_write fs/read_write.c:607 [inline]
 __x64_sys_write+0x73/0xb0 fs/read_write.c:607
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457579
Code: Bad RIP value.
RSP: 002b:00007fe9f26b5c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457579
RDX: 000000000000006f RSI: 0000000020000000 RDI: 0000000000000004
RBP: 000000000072bfa0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007fe9f26b66d4
R13: 00000000004c4f77 R14: 00000000004d8580 R15: 00000000ffffffff
INFO: task syz-executor1:7188 blocked for more than 140 seconds.
      Not tainted 4.19.0-rc6+ #265
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor1   D25400  7188   5409 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2825 [inline]
 __schedule+0x86c/0x1ed0 kernel/sched/core.c:3473
 schedule+0xfe/0x460 kernel/sched/core.c:3517
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:3575
 __mutex_lock_common kernel/locking/mutex.c:1002 [inline]
 __mutex_lock+0xbe7/0x1700 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 snd_seq_ioctl+0x221/0x440 sound/core/seq/seq_clientmgr.c:2137
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:501 [inline]
 do_vfs_ioctl+0x1de/0x1720 fs/ioctl.c:685
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:702
 __do_sys_ioctl fs/ioctl.c:709 [inline]
 __se_sys_ioctl fs/ioctl.c:707 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:707
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457579
Code: Bad RIP value.
RSP: 002b:00007fe9f2694c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457579
RDX: 00000000200000c0 RSI: 00000000c08c5332 RDI: 0000000000000009
RBP: 000000000072c040 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007fe9f26956d4
R13: 00000000004c8ba0 R14: 00000000004d12f0 R15: 00000000ffffffff
INFO: task syz-executor1:7189 blocked for more than 140 seconds.
      Not tainted 4.19.0-rc6+ #265
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor1   D24760  7189   5409 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2825 [inline]
 __schedule+0x86c/0x1ed0 kernel/sched/core.c:3473
 schedule+0xfe/0x460 kernel/sched/core.c:3517
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:3575
 __mutex_lock_common kernel/locking/mutex.c:1002 [inline]
 __mutex_lock+0xbe7/0x1700 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 snd_seq_ioctl+0x221/0x440 sound/core/seq/seq_clientmgr.c:2137
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:501 [inline]
 do_vfs_ioctl+0x1de/0x1720 fs/ioctl.c:685
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:702
 __do_sys_ioctl fs/ioctl.c:709 [inline]
 __se_sys_ioctl fs/ioctl.c:707 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:707
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457579
Code: Bad RIP value.
RSP: 002b:00007fe9f2673c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457579
RDX: 0000000020000300 RSI: 0000000040bc5311 RDI: 0000000000000009
RBP: 000000000072c0e0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007fe9f26746d4
R13: 00000000004c8e90 R14: 00000000004d14b8 R15: 00000000ffffffff

Showing all locks held in the system:
1 lock held by khungtaskd/982:
 #0: 00000000f2232a1e (rcu_read_lock){....}, at: debug_show_all_locks+0xd0/0x424 kernel/locking/lockdep.c:4435
1 lock held by rsyslogd/5269:
 #0: 000000004a65a3de (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x1bb/0x200 fs/file.c:766
2 locks held by getty/5359:
 #0: 000000006c785a3d (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 000000000b50b055 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/5360:
 #0: 000000008d9a9e26 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 00000000a1bb0037 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/5361:
 #0: 00000000345e7be5 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 000000005d576670 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/5362:
 #0: 00000000d288fc3a (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 00000000ce345c19 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/5363:
 #0: 0000000017900a57 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 000000001c113d09 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/5364:
 #0: 0000000058456689 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 000000006108e672 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/5365:
 #0: 00000000cfb9feaf (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x32/0x40 drivers/tty/tty_ldsem.c:353
 #1: 0000000036eb2fcf (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by syz-executor1/7125:
1 lock held by syz-executor1/7135:
 #0: 000000000e171819 (&client->ioctl_mutex){+.+.}, at: snd_seq_write+0x1f1/0x8d0 sound/core/seq/seq_clientmgr.c:1021
1 lock held by syz-executor1/7188:
 #0: 000000000e171819 (&client->ioctl_mutex){+.+.}, at: snd_seq_ioctl+0x221/0x440 sound/core/seq/seq_clientmgr.c:2137
1 lock held by syz-executor1/7189:
 #0: 000000000e171819 (&client->ioctl_mutex){+.+.}, at: snd_seq_ioctl+0x221/0x440 sound/core/seq/seq_clientmgr.c:2137
1 lock held by syz-executor1/7195:
 #0: 000000000e171819 (&client->ioctl_mutex){+.+.}, at: snd_seq_write+0x1f1/0x8d0 sound/core/seq/seq_clientmgr.c:1021

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 982 Comm: khungtaskd Not tainted 4.19.0-rc6+ #265
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+0x1c4/0x2b4 lib/dump_stack.c:113
 nmi_cpu_backtrace.cold.3+0x63/0xa2 lib/nmi_backtrace.c:101
 nmi_trigger_cpumask_backtrace+0x1b3/0x1ed 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:144 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:204 [inline]
 watchdog+0xb3e/0x1050 kernel/hung_task.c:265
 kthread+0x35a/0x420 kernel/kthread.c:246
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:413
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 7125 Comm: syz-executor1 Not tainted 4.19.0-rc6+ #265
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:___might_sleep+0x79/0x300 kernel/sched/core.c:6108
Code: f1 f1 f1 f1 c7 40 04 00 f2 f2 f2 65 48 8b 04 25 28 00 00 00 48 89 45 d0 31 c0 e8 52 42 12 00 85 c0 74 0d 80 3d a6 16 99 08 00 <0f> 84 fa 01 00 00 e8 3c 42 12 00 85 c0 74 0d 80 3d 8f 16 99 08 00
RSP: 0018:ffff880187d9f928 EFLAGS: 00000246
RAX: 0000000000000001 RBX: ffff880187d96540 RCX: ffffc90003e86000
RDX: 0000000000000000 RSI: 000000000000000a RDI: ffff880187d96dbc
RBP: ffff880187d9f9b8 R08: ffff880187d96540 R09: ffffed003afc9f78
R10: ffffed003afc9f78 R11: ffff8801d7e4fbc3 R12: 1ffff10030fb3f26
R13: 0000000000000000 R14: ffffffff884074c0 R15: 000000000000000a
FS:  00007fe9f26d7700(0000) GS:ffff8801daf00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffffff600400 CR3: 00000001d960e000 CR4: 00000000001406e0
Call Trace:
 __might_sleep+0x95/0x190 kernel/sched/core.c:6096
 __might_fault+0xc6/0x1e0 mm/memory.c:4575
 _copy_from_user+0x30/0x150 lib/usercopy.c:10
 copy_from_user include/linux/uaccess.h:147 [inline]
 snd_seq_write+0x472/0x8d0 sound/core/seq/seq_clientmgr.c:1033
 __vfs_write+0x119/0x9f0 fs/read_write.c:485
 vfs_write+0x1fc/0x560 fs/read_write.c:549
 ksys_write+0x101/0x260 fs/read_write.c:598
 __do_sys_write fs/read_write.c:610 [inline]
 __se_sys_write fs/read_write.c:607 [inline]
 __x64_sys_write+0x73/0xb0 fs/read_write.c:607
 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457579
Code: 1d b4 fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 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 0f 83 eb b3 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007fe9f26d6c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457579
RDX: 00000000ffffffbd RSI: 0000000020042f70 RDI: 0000000000000004
RBP: 000000000072bf00 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007fe9f26d76d4
R13: 00000000004c569c R14: 00000000004d9018 R15: 00000000ffffffff

Crashes (6):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2018/10/03 22:00 upstream 6bebe37927f3 8b311eaf .config console log report ci-upstream-kasan-gce
2018/09/23 15:26 upstream 328c6333ba3d 37079712 .config console log report ci-upstream-kasan-gce-386
2019/03/21 00:59 linux-next 835727301ed3 a664c187 .config console log report ci-upstream-linux-next-kasan-gce-root
2018/09/09 02:58 linux-next f2b6e66e9885 6b5120a4 .config console log report ci-upstream-linux-next-kasan-gce-root
2018/09/07 10:07 linux-next f2b6e66e9885 e30d3b52 .config console log report ci-upstream-linux-next-kasan-gce-root
2018/08/25 10:33 linux-next e27bc174c9c6 9be5aa1d .config console log report ci-upstream-linux-next-kasan-gce-root
* Struck through repros no longer work on HEAD.