Re: [syzbot] possible deadlock in console_unlock

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
possible deadlock in console_unlock

======================================================
WARNING: possible circular locking dependency detected
5.12.0-rc5-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor.3/10136 is trying to acquire lock:
ffffffff8b6805a0 (console_owner){....}-{0:0}, at: console_unlock+0x2f2/0xc80 kernel/printk/printk.c:2551

but task is already holding lock:
ffffffff8f930798 (&port->lock){-.-.}-{2:2}, at: tty_port_close_start.part.0+0x28/0x550 drivers/tty/tty_port.c:567

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&port->lock){-.-.}-{2:2}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x39/0x50 kernel/locking/spinlock.c:159
tty_port_tty_get+0x1f/0x100 drivers/tty/tty_port.c:288
tty_port_default_wakeup+0x11/0x40 drivers/tty/tty_port.c:47
serial8250_tx_chars+0x487/0xa80 drivers/tty/serial/8250/8250_port.c:1832
serial8250_handle_irq.part.0+0x328/0x3d0 drivers/tty/serial/8250/8250_port.c:1919
serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1892 [inline]
serial8250_default_handle_irq+0xb2/0x220 drivers/tty/serial/8250/8250_port.c:1935
serial8250_interrupt+0xfd/0x200 drivers/tty/serial/8250/8250_core.c:126
__handle_irq_event_percpu+0x303/0x8f0 kernel/irq/handle.c:156
handle_irq_event_percpu kernel/irq/handle.c:196 [inline]
handle_irq_event+0x102/0x290 kernel/irq/handle.c:213
handle_edge_irq+0x25f/0xd00 kernel/irq/chip.c:819
generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
handle_irq arch/x86/kernel/irq.c:231 [inline]
__common_interrupt+0x9e/0x200 arch/x86/kernel/irq.c:250
common_interrupt+0x9f/0xd0 arch/x86/kernel/irq.c:240
asm_common_interrupt+0x1e/0x40 arch/x86/include/asm/idtentry.h:623
__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:161 [inline]
_raw_spin_unlock_irqrestore+0x38/0x70 kernel/locking/spinlock.c:191
spin_unlock_irqrestore include/linux/spinlock.h:409 [inline]
uart_write+0x30d/0x570 drivers/tty/serial/serial_core.c:615
do_output_char+0x5de/0x850 drivers/tty/n_tty.c:443
process_output drivers/tty/n_tty.c:510 [inline]
n_tty_write+0x4c3/0xfd0 drivers/tty/n_tty.c:2365
do_tty_write drivers/tty/tty_io.c:1043 [inline]
file_tty_write.constprop.0+0x526/0x910 drivers/tty/tty_io.c:1133
redirected_tty_write+0xa1/0xc0 drivers/tty/tty_io.c:1140
call_write_iter include/linux/fs.h:1977 [inline]
do_iter_readv_writev+0x46f/0x740 fs/read_write.c:740
do_iter_write+0x188/0x670 fs/read_write.c:866
vfs_writev+0x1aa/0x630 fs/read_write.c:939
do_writev+0x139/0x300 fs/read_write.c:982
do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
entry_SYSCALL_64_after_hwframe+0x44/0xae

-> #1 (&port_lock_key){-.-.}-{2:2}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x39/0x50 kernel/locking/spinlock.c:159
serial8250_console_write+0x8b2/0xae0 drivers/tty/serial/8250/8250_port.c:3292
call_console_drivers kernel/printk/printk.c:1862 [inline]
console_unlock+0x895/0xc80 kernel/printk/printk.c:2576
vprintk_emit+0x1ca/0x560 kernel/printk/printk.c:2098
vprintk_func+0x8d/0x1e0 kernel/printk/printk_safe.c:401
printk+0xba/0xed kernel/printk/printk.c:2146
register_console kernel/printk/printk.c:2927 [inline]
register_console+0x606/0x840 kernel/printk/printk.c:2807
univ8250_console_init+0x3a/0x46 drivers/tty/serial/8250/8250_core.c:690
console_init+0x3c7/0x596 kernel/printk/printk.c:3027
start_kernel+0x306/0x496 init/main.c:993
secondary_startup_64_no_verify+0xb0/0xbb

-> #0 (console_owner){....}-{0:0}:
check_prev_add kernel/locking/lockdep.c:2936 [inline]
check_prevs_add kernel/locking/lockdep.c:3059 [inline]
validate_chain kernel/locking/lockdep.c:3674 [inline]
__lock_acquire+0x2b14/0x54c0 kernel/locking/lockdep.c:4900
lock_acquire kernel/locking/lockdep.c:5510 [inline]
lock_acquire+0x1ab/0x740 kernel/locking/lockdep.c:5475
console_lock_spinning_enable kernel/printk/printk.c:1714 [inline]
console_unlock+0x371/0xc80 kernel/printk/printk.c:2573
vprintk_emit+0x1ca/0x560 kernel/printk/printk.c:2098
vprintk_func+0x8d/0x1e0 kernel/printk/printk_safe.c:401
printk+0xba/0xed kernel/printk/printk.c:2146
tty_port_close_start.part.0+0x503/0x550 drivers/tty/tty_port.c:569
tty_port_close_start drivers/tty/tty_port.c:641 [inline]
tty_port_close+0x46/0x170 drivers/tty/tty_port.c:634
tty_release+0x45e/0x1210 drivers/tty/tty_io.c:1779
__fput+0x288/0x920 fs/file_table.c:280
task_work_run+0xdd/0x1a0 kernel/task_work.c:140
tracehook_notify_resume include/linux/tracehook.h:189 [inline]
exit_to_user_mode_loop kernel/entry/common.c:174 [inline]
exit_to_user_mode_prepare+0x249/0x250 kernel/entry/common.c:208
__syscall_exit_to_user_mode_work kernel/entry/common.c:290 [inline]
syscall_exit_to_user_mode+0x19/0x60 kernel/entry/common.c:301
entry_SYSCALL_64_after_hwframe+0x44/0xae

other info that might help us debug this:

Chain exists of:
console_owner --> &port_lock_key --> &port->lock

Possible unsafe locking scenario:

CPU0 CPU1
---- ----
lock(&port->lock);
lock(&port_lock_key);
lock(&port->lock);
lock(console_owner);

*** DEADLOCK ***

3 locks held by syz-executor.3/10136:
#0: ffff8880124491c0 (&tty->legacy_mutex){+.+.}-{3:3}, at: tty_lock+0xbd/0x120 drivers/tty/tty_mutex.c:19
#1: ffffffff8f930798 (&port->lock){-.-.}-{2:2}, at: tty_port_close_start.part.0+0x28/0x550 drivers/tty/tty_port.c:567
#2: ffffffff8b760920 (console_lock){+.+.}-{0:0}, at: vprintk_func+0x8d/0x1e0 kernel/printk/printk_safe.c:401

stack backtrace:
CPU: 0 PID: 10136 Comm: syz-executor.3 Not tainted 5.12.0-rc5-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120
check_noncircular+0x25f/0x2e0 kernel/locking/lockdep.c:2127
check_prev_add kernel/locking/lockdep.c:2936 [inline]
check_prevs_add kernel/locking/lockdep.c:3059 [inline]
validate_chain kernel/locking/lockdep.c:3674 [inline]
__lock_acquire+0x2b14/0x54c0 kernel/locking/lockdep.c:4900
lock_acquire kernel/locking/lockdep.c:5510 [inline]
lock_acquire+0x1ab/0x740 kernel/locking/lockdep.c:5475
console_lock_spinning_enable kernel/printk/printk.c:1714 [inline]
console_unlock+0x371/0xc80 kernel/printk/printk.c:2573
vprintk_emit+0x1ca/0x560 kernel/printk/printk.c:2098
vprintk_func+0x8d/0x1e0 kernel/printk/printk_safe.c:401
printk+0xba/0xed kernel/printk/printk.c:2146
tty_port_close_start.part.0+0x503/0x550 drivers/tty/tty_port.c:569
tty_port_close_start drivers/tty/tty_port.c:641 [inline]
tty_port_close+0x46/0x170 drivers/tty/tty_port.c:634
tty_release+0x45e/0x1210 drivers/tty/tty_io.c:1779
__fput+0x288/0x920 fs/file_table.c:280
task_work_run+0xdd/0x1a0 kernel/task_work.c:140
tracehook_notify_resume include/linux/tracehook.h:189 [inline]
exit_to_user_mode_loop kernel/entry/common.c:174 [inline]
exit_to_user_mode_prepare+0x249/0x250 kernel/entry/common.c:208
__syscall_exit_to_user_mode_work kernel/entry/common.c:290 [inline]
syscall_exit_to_user_mode+0x19/0x60 kernel/entry/common.c:301
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x41926b
Code: 0f 05 48 3d 00 f0 ff ff 77 45 c3 0f 1f 40 00 48 83 ec 18 89 7c 24 0c e8 63 fc ff ff 8b 7c 24 0c 41 89 c0 b8 03 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 35 44 89 c7 89 44 24 0c e8 a1 fc ff ff 8b 44
RSP: 002b:00007ffdf2f05aa0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 000000000041926b
RDX: 0000000000570120 RSI: 0000000000000081 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000570120
R13: 00007ffdf2f05bc0 R14: 000000000056bf60 R15: 000000000001a667


Tested on:

commit: 1678e493 Merge tag 'lto-v5.12-rc6' of git://git.kernel.org..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=11afa831d00000
kernel config: https://syzkaller.appspot.com/x/.config?x=9d2151bdc689a286
dashboard link: https://syzkaller.appspot.com/bug?extid=43e93968b964e369db0b
compiler:
patch: https://syzkaller.appspot.com/x/patch.diff?x=15d54681d00000

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+43e939...@syzkaller.appspotmail.com

Tested on:

commit: d93a0d43 Merge tag 'block-5.12-2021-04-02' of git://git.ke..
git tree: upstream

kernel config: https://syzkaller.appspot.com/x/.config?x=9d2151bdc689a286
dashboard link: https://syzkaller.appspot.com/bug?extid=43e93968b964e369db0b
compiler:

patch: https://syzkaller.appspot.com/x/patch.diff?x=14e22311d00000

Note: testing is done by a robot and is best-effort only.

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

INFO: task hung in synchronize_rcu

INFO: task kworker/u4:3:125 blocked for more than 143 seconds.
Not tainted 5.12.0-rc6-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u4:3 state:D stack:25656 pid: 125 ppid: 2 flags:0x00004000
Workqueue: events_unbound fsnotify_mark_destroy_workfn
Call Trace:
context_switch kernel/sched/core.c:4322 [inline]
__schedule+0x911/0x21b0 kernel/sched/core.c:5073
schedule+0xcf/0x270 kernel/sched/core.c:5152
schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
__synchronize_srcu+0x1a6/0x280 kernel/rcu/srcutree.c:935
fsnotify_mark_destroy_workfn+0xfd/0x340 fs/notify/mark.c:836
process_one_work+0x98d/0x1600 kernel/workqueue.c:2275
worker_thread+0x64c/0x1120 kernel/workqueue.c:2421
kthread+0x3b1/0x4a0 kernel/kthread.c:292
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
INFO: task kworker/u4:4:467 blocked for more than 143 seconds.
Not tainted 5.12.0-rc6-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u4:4 state:D stack:24104 pid: 467 ppid: 2 flags:0x00004000
Workqueue: events_unbound fsnotify_connector_destroy_workfn
Call Trace:
context_switch kernel/sched/core.c:4322 [inline]
__schedule+0x911/0x21b0 kernel/sched/core.c:5073
schedule+0xcf/0x270 kernel/sched/core.c:5152
schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
__synchronize_srcu+0x1a6/0x280 kernel/rcu/srcutree.c:935
fsnotify_connector_destroy_workfn+0x49/0xa0 fs/notify/mark.c:164
process_one_work+0x98d/0x1600 kernel/workqueue.c:2275
worker_thread+0x64c/0x1120 kernel/workqueue.c:2421
kthread+0x3b1/0x4a0 kernel/kthread.c:292
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
INFO: task khugepaged:1636 blocked for more than 143 seconds.
Not tainted 5.12.0-rc6-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:khugepaged state:D stack:23816 pid: 1636 ppid: 2 flags:0x00004000
Call Trace:
context_switch kernel/sched/core.c:4322 [inline]
__schedule+0x911/0x21b0 kernel/sched/core.c:5073
schedule+0xcf/0x270 kernel/sched/core.c:5152
schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
__flush_work+0x527/0xac0 kernel/workqueue.c:3052
lru_add_drain_all+0x41f/0x6f0 mm/swap.c:826
khugepaged_do_scan mm/khugepaged.c:2213 [inline]
khugepaged+0x10c/0x5510 mm/khugepaged.c:2274
kthread+0x3b1/0x4a0 kernel/kthread.c:292
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294

Showing all locks held in the system:
3 locks held by kworker/0:2/8:
3 locks held by kworker/u4:0/9:
2 locks held by kworker/u4:3/125:
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2246
#1: ffffc90000f2fda8 ((reaper_work).work){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2250
2 locks held by kworker/u4:4/467:
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2246
#1: ffffc900026dfda8 (connector_reaper_work){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2250
1 lock held by khungtaskd/1611:
#0: ffffffff8b774320 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x260 kernel/locking/lockdep.c:6327
1 lock held by khugepaged/1636:
#0: ffffffff8b84eea8 (lock#5){+.+.}-{3:3}, at: lru_add_drain_all+0x5f/0x6f0 mm/swap.c:777
1 lock held by systemd-udevd/4831:
1 lock held by in:imklog/8084:
#0: ffff888014172af0 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100 fs/file.c:961
1 lock held by syz-executor.2/27884:
2 locks held by syz-executor.3/27880:
2 locks held by syz-executor.1/27882:
3 locks held by syz-executor.0/27883:

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

NMI backtrace for cpu 0
CPU: 0 PID: 1611 Comm: khungtaskd Not tainted 5.12.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120

nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:209 [inline]
watchdog+0xd48/0xfb0 kernel/hung_task.c:294
kthread+0x3b1/0x4a0 kernel/kthread.c:292
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 4831 Comm: systemd-udevd Not tainted 5.12.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011

RIP: 0010:__sanitizer_cov_trace_pc+0x37/0x60 kernel/kcov.c:197
Code: 81 e1 00 01 00 00 65 48 8b 14 25 00 f0 01 00 a9 00 01 ff 00 74 0e 85 c9 74 35 8b 82 34 15 00 00 85 c0 74 2b 8b 82 10 15 00 00 <83> f8 02 75 20 48 8b 8a 18 15 00 00 8b 92 14 15 00 00 48 8b 01 48
RSP: 0018:ffffc9000162f868 EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000000000007 RCX: 0000000000000000
RDX: ffff888012903880 RSI: ffffffff8392bd0a RDI: 0000000000000003
RBP: ffff8880207b2880 R08: 0000000000000000 R09: 0000000000000007
R10: ffffffff8392bcf7 R11: 0000000000000010 R12: 0000000000000002
R13: 00000000000002a8 R14: dffffc0000000000 R15: 0000000000000000
FS: 00007f78ffac78c0(0000) GS:ffff8880b9f00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000021e0808 CR3: 000000001351f000 CR4: 0000000000350ee0
Call Trace:
tomoyo_domain_quota_is_ok+0x31a/0x550 security/tomoyo/util.c:1092
tomoyo_supervisor+0x2f2/0xf00 security/tomoyo/common.c:2089
tomoyo_audit_path_log security/tomoyo/file.c:168 [inline]
tomoyo_path_permission security/tomoyo/file.c:587 [inline]
tomoyo_path_permission+0x270/0x3a0 security/tomoyo/file.c:573
tomoyo_path_perm+0x2f0/0x400 security/tomoyo/file.c:838
security_inode_getattr+0xcf/0x140 security/security.c:1288
vfs_getattr fs/stat.c:131 [inline]
vfs_statx+0x164/0x390 fs/stat.c:199
vfs_fstatat fs/stat.c:217 [inline]
vfs_lstat include/linux/fs.h:3240 [inline]
__do_sys_newlstat+0x91/0x110 fs/stat.c:372
do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f78fe939335
Code: 69 db 2b 00 64 c7 00 16 00 00 00 b8 ff ff ff ff c3 0f 1f 40 00 83 ff 01 48 89 f0 77 30 48 89 c7 48 89 d6 b8 06 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 03 f3 c3 90 48 8b 15 31 db 2b 00 f7 d8 64 89
RSP: 002b:00007ffd4455a7a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000006
RAX: ffffffffffffffda RBX: 00005564de016290 RCX: 00007f78fe939335
RDX: 00007ffd4455a7e0 RSI: 00007ffd4455a7e0 RDI: 00005564de015290
RBP: 00007ffd4455a8a0 R08: 00007f78febf8278 R09: 0000000000001010
R10: 0000000000000030 R11: 0000000000000246 R12: 00005564de015290
R13: 00005564de0152b0 R14: 00005564de003ddb R15: 00005564de003de0


Tested on:

commit: 2d743660 Merge branch 'fixes' of git://git.kernel.org/pub/..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=162f9fced00000
kernel config: https://syzkaller.appspot.com/x/.config?x=fef2f1c101970c84

dashboard link: https://syzkaller.appspot.com/bug?extid=43e93968b964e369db0b
compiler:

patch: https://syzkaller.appspot.com/x/patch.diff?x=145e4c9ad00000

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in synchronize_rcu

INFO: task kworker/u4:2:47 blocked for more than 143 seconds.

Not tainted 5.12.0-rc6-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/u4:2 state:D stack:25616 pid: 47 ppid: 2 flags:0x00004000

Workqueue: events_unbound fsnotify_mark_destroy_workfn
Call Trace:
context_switch kernel/sched/core.c:4322 [inline]
__schedule+0x911/0x21b0 kernel/sched/core.c:5073
schedule+0xcf/0x270 kernel/sched/core.c:5152
schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
__synchronize_srcu+0x1a6/0x280 kernel/rcu/srcutree.c:935
fsnotify_mark_destroy_workfn+0xfd/0x340 fs/notify/mark.c:836
process_one_work+0x98d/0x1600 kernel/workqueue.c:2275
worker_thread+0x64c/0x1120 kernel/workqueue.c:2421
kthread+0x3b1/0x4a0 kernel/kthread.c:292
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294

INFO: task kworker/u4:4:748 blocked for more than 143 seconds.

Not tainted 5.12.0-rc6-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/u4:4 state:D stack:25488 pid: 748 ppid: 2 flags:0x00004000

Workqueue: events_unbound fsnotify_connector_destroy_workfn
Call Trace:
context_switch kernel/sched/core.c:4322 [inline]
__schedule+0x911/0x21b0 kernel/sched/core.c:5073
schedule+0xcf/0x270 kernel/sched/core.c:5152
schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
__synchronize_srcu+0x1a6/0x280 kernel/rcu/srcutree.c:935
fsnotify_connector_destroy_workfn+0x49/0xa0 fs/notify/mark.c:164
process_one_work+0x98d/0x1600 kernel/workqueue.c:2275
worker_thread+0x64c/0x1120 kernel/workqueue.c:2421
kthread+0x3b1/0x4a0 kernel/kthread.c:292
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294

Showing all locks held in the system:

2 locks held by kworker/u4:2/47:

#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2246

#1: ffffc90000e7fda8 ((reaper_work).work){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2250
2 locks held by kworker/u4:4/748:

#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:616 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:643 [inline]
#0: ffff88800fc69138 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2246

#1: ffffc90002e7fda8 (connector_reaper_work){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2250
1 lock held by khungtaskd/1627:

#0: ffffffff8b774320 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x260 kernel/locking/lockdep.c:6327
1 lock held by khugepaged/1636:
#0: ffffffff8b84eea8 (lock#5){+.+.}-{3:3}, at: lru_add_drain_all+0x5f/0x6f0 mm/swap.c:777

1 lock held by systemd-udevd/4832:
1 lock held by in:imklog/8085:
#0: ffff8880114d2d70 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100 fs/file.c:961
3 locks held by kworker/1:5/10016:
2 locks held by syz-executor.1/27595:
3 locks held by syz-executor.5/27597:

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

NMI backtrace for cpu 1
CPU: 1 PID: 1627 Comm: khungtaskd Not tainted 5.12.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120
nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:209 [inline]
watchdog+0xd48/0xfb0 kernel/hung_task.c:294
kthread+0x3b1/0x4a0 kernel/kthread.c:292
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294

Sending NMI from CPU 1 to CPUs 0:

NMI backtrace for cpu 0

CPU: 0 PID: 4832 Comm: systemd-udevd Not tainted 5.12.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:__sanitizer_cov_trace_pc+0x37/0x60 kernel/kcov.c:197
Code: 81 e1 00 01 00 00 65 48 8b 14 25 00 f0 01 00 a9 00 01 ff 00 74 0e 85 c9 74 35 8b 82 34 15 00 00 85 c0 74 2b 8b 82 10 15 00 00 <83> f8 02 75 20 48 8b 8a 18 15 00 00 8b 92 14 15 00 00 48 8b 01 48

RSP: 0018:ffffc9000161f5a8 EFLAGS: 00000246
RAX: 0000000000000000 RBX: 000000000000000a RCX: 0000000000000000
RDX: ffff888016d48000 RSI: ffffffff8392bce1 RDI: 0000000000000003
RBP: ffff88801fb36a80 R08: 0000000000000000 R09: 000000000000000a
R10: ffffffff8392bd1a R11: 0000000000000010 R12: 0000000000000002
R13: 00000000000003b7 R14: dffffc0000000000 R15: 0000000000000000
FS: 00007f8b2ebc78c0(0000) GS:ffff8880b9e00000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 00000000004c957e CR3: 0000000016809000 CR4: 0000000000350ef0
Call Trace:
tomoyo_domain_quota_is_ok+0x2f1/0x550 security/tomoyo/util.c:1093

tomoyo_supervisor+0x2f2/0xf00 security/tomoyo/common.c:2089
tomoyo_audit_path_log security/tomoyo/file.c:168 [inline]
tomoyo_path_permission security/tomoyo/file.c:587 [inline]
tomoyo_path_permission+0x270/0x3a0 security/tomoyo/file.c:573

tomoyo_check_open_permission+0x33e/0x380 security/tomoyo/file.c:777
tomoyo_file_open security/tomoyo/tomoyo.c:313 [inline]
tomoyo_file_open+0xa3/0xd0 security/tomoyo/tomoyo.c:308
security_file_open+0x52/0x4f0 security/security.c:1589
do_dentry_open+0x358/0x11b0 fs/open.c:813
do_open fs/namei.c:3367 [inline]
path_openat+0x1c0e/0x27e0 fs/namei.c:3500
do_filp_open+0x190/0x3d0 fs/namei.c:3527
do_sys_openat2+0x16d/0x420 fs/open.c:1187
do_sys_open fs/open.c:1203 [inline]
__do_sys_open fs/open.c:1211 [inline]
__se_sys_open fs/open.c:1207 [inline]
__x64_sys_open+0x119/0x1c0 fs/open.c:1207
do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f8b2da119b1
Code: f7 d8 bf ff ff ff ff 64 89 02 eb cb 0f 1f 00 66 2e 0f 1f 84 00 00 00 00 00 80 3f 00 74 1b be 00 08 09 00 b8 02 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 1f 89 c7 e9 00 ff ff ff 48 8b 05 b1 54 2e 00
RSP: 002b:00007ffc4b21bbd8 EFLAGS: 00000202 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 00005610e74ca430 RCX: 00007f8b2da119b1
RDX: 00000000000000fd RSI: 0000000000090800 RDI: 00005610e74ad8e0
RBP: 00007f8b2ebc7710 R08: 00005610e74ab220 R09: 7269762f73656369
R10: 00007f8b2dcf7b58 R11: 0000000000000202 R12: 0000000000000000
R13: 00005610e74ad8e0 R14: 00000000000000fd R15: 00005610e74ad8e0

Tested on:

commit: 2d743660 Merge branch 'fixes' of git://git.kernel.org/pub/..
git tree: upstream

console output: https://syzkaller.appspot.com/x/log.txt?x=130c1316d00000

kernel config: https://syzkaller.appspot.com/x/.config?x=fef2f1c101970c84
dashboard link: https://syzkaller.appspot.com/bug?extid=43e93968b964e369db0b
compiler:

patch: https://syzkaller.appspot.com/x/patch.diff?x=11c5e07ed00000

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+43e939...@syzkaller.appspotmail.com

Tested on:

commit: 2d743660 Merge branch 'fixes' of git://git.kernel.org/pub/..
git tree: upstream

kernel config: https://syzkaller.appspot.com/x/.config?x=fef2f1c101970c84
dashboard link: https://syzkaller.appspot.com/bug?extid=43e93968b964e369db0b
compiler:

patch: https://syzkaller.appspot.com/x/patch.diff?x=14839931d00000

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+43e939...@syzkaller.appspotmail.com

Tested on:

commit: 50987bec Merge tag 'trace-v5.12-rc7' of git://git.kernel.o..
git tree: upstream
kernel config: https://syzkaller.appspot.com/x/.config?x=63186bf8a0b43ca2

dashboard link: https://syzkaller.appspot.com/bug?extid=43e93968b964e369db0b
compiler:

patch: https://syzkaller.appspot.com/x/patch.diff?x=17a522b1d00000

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+43e939...@syzkaller.appspotmail.com

Tested on:

commit: 7f75285c Merge tag 'for-5.12/dm-fixes-3' of git://git.kern..

git tree: upstream
kernel config: https://syzkaller.appspot.com/x/.config?x=63186bf8a0b43ca2
dashboard link: https://syzkaller.appspot.com/bug?extid=43e93968b964e369db0b
compiler:

patch: https://syzkaller.appspot.com/x/patch.diff?x=17bfa4ded00000