syzbot


INFO: task hung in fsnotify_mark_destroy_workfn

Status: fixed on 2018/09/08 03:03
Reported-by: syzbot+e38306788a2e7102a3b6@syzkaller.appspotmail.com
Fix commit: 128f38041035 android: binder: Rate-limit debug and userspace triggered err msgs
First crash: 1752d, last: 1638d
duplicates (1):
Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
INFO: task hung in fsnotify_connector_destroy_workfn syz 7 1655d 1734d 0/24 closed as dup on 2018/07/18 14:05
similar bugs (5):
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: task hung in fsnotify_mark_destroy_workfn (2) 42 1205d 1605d 0/24 closed as invalid on 2019/10/23 07:21
linux-4.19 INFO: task hung in fsnotify_mark_destroy_workfn syz done 3 1144d 1332d 1/1 fixed on 2020/01/16 11:28
upstream INFO: task hung in fsnotify_mark_destroy_workfn (3) 15 989d 1030d 0/24 auto-closed as invalid on 2020/08/18 06:03
android-414 INFO: task hung in fsnotify_mark_destroy_workfn 9 1166d 1391d 0/1 auto-closed as invalid on 2020/03/23 16:47
linux-4.19 INFO: task hung in fsnotify_mark_destroy_workfn (2) 1 1021d 1021d 0/1 auto-closed as invalid on 2020/08/15 10:12

Sample crash report:
binder: 28330:28330 transaction failed 29189/-22, size 0-0 line 2852
binder: undelivered TRANSACTION_ERROR: 29189
binder: 28332:28332 transaction failed 29189/-22, size 0-0 line 2852
binder: undelivered TRANSACTION_ERROR: 29189
binder: 28335:28335 transaction failed 29189/-22, size 0-0 line 2852
INFO: task kworker/u4:4:1880 blocked for more than 140 seconds.
      Not tainted 4.18.0-rc6+ #160
binder: 28336:28336 transaction failed 29189/-22, size 0-0 line 2852
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/u4:4    D21992  1880      2 0x80000000
Workqueue: events_unbound fsnotify_mark_destroy_workfn
binder: undelivered TRANSACTION_ERROR: 29189
Call Trace:
 context_switch kernel/sched/core.c:2853 [inline]
 __schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
 schedule+0xfb/0x450 kernel/sched/core.c:3545
binder: undelivered TRANSACTION_ERROR: 29189
 schedule_timeout+0x1cc/0x260 kernel/time/timer.c:1777
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
 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+0x430/0x8d0 kernel/sched/completion.c:136
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
binder: 28339:28339 transaction failed 29189/-22, size 0-0 line 2852
 __synchronize_srcu+0x189/0x240 kernel/rcu/srcutree.c:928
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
 synchronize_srcu+0x41c/0x56f kernel/rcu/srcutree.c:1006
binder: undelivered TRANSACTION_ERROR: 29189
 fsnotify_mark_destroy_workfn+0x1be/0x550 fs/notify/mark.c:765
binder: 28340:28340 transaction failed 29189/-22, size 0-0 line 2852
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
 process_one_work+0xc73/0x1ba0 kernel/workqueue.c:2153
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
binder: 28346:28346 transaction failed 29189/-22, size 0-0 line 2852
binder: 28348:28348 transaction failed 29189/-22, size 0-0 line 2852
binder: 28349:28349 transaction failed 29189/-22, size 0-0 line 2852
 worker_thread+0x189/0x13c0 kernel/workqueue.c:2296
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
 kthread+0x345/0x410 kernel/kthread.c:246
binder: 28341:28341 transaction failed 29189/-22, size 0-0 line 2852
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
INFO: task kworker/u4:0:4647 blocked for more than 140 seconds.
binder: 28342:28342 transaction failed 29189/-22, size 0-0 line 2852
      Not tainted 4.18.0-rc6+ #160
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/u4:0    D23896  4647      2 0x80000000
Workqueue: events_unbound fsnotify_connector_destroy_workfn
binder: 28360:28360 transaction failed 29189/-22, size 0-0 line 2852
Call Trace:
 context_switch kernel/sched/core.c:2853 [inline]
 __schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
binder: 28359:28359 transaction failed 29189/-22, size 0-0 line 2852
binder: 28362:28362 transaction failed 29189/-22, size 0-0 line 2852
 schedule+0xfb/0x450 kernel/sched/core.c:3545
binder: undelivered TRANSACTION_ERROR: 29189
 schedule_timeout+0x1cc/0x260 kernel/time/timer.c:1777
binder: 28365:28365 transaction failed 29189/-22, size 0-0 line 2852
binder: 28364:28364 transaction failed 29189/-22, size 0-0 line 2852
 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+0x430/0x8d0 kernel/sched/completion.c:136
binder: undelivered TRANSACTION_ERROR: 29189
binder: 28367:28367 transaction failed 29189/-22, size 0-0 line 2852
 __synchronize_srcu+0x189/0x240 kernel/rcu/srcutree.c:928
binder: 28368:28368 transaction failed 29189/-22, size 0-0 line 2852
 synchronize_srcu_expedited kernel/rcu/srcutree.c:953 [inline]
 synchronize_srcu+0x335/0x56f kernel/rcu/srcutree.c:1004
binder: undelivered TRANSACTION_ERROR: 29189
 fsnotify_connector_destroy_workfn+0x44/0xa0 fs/notify/mark.c:156
binder: 28370:28370 transaction failed 29189/-22, size 0-0 line 2852
 process_one_work+0xc73/0x1ba0 kernel/workqueue.c:2153
binder: 28371:28371 transaction failed 29189/-22, size 0-0 line 2852
binder: undelivered TRANSACTION_ERROR: 29189
binder: 28343:28343 transaction failed 29189/-22, size 0-0 line 2852
binder: 28375:28375 transaction failed 29189/-22, size 0-0 line 2852
binder: 28374:28374 transaction failed 29189/-22, size 0-0 line 2852
 worker_thread+0x189/0x13c0 kernel/workqueue.c:2296
binder: undelivered TRANSACTION_ERROR: 29189
binder: 28344:28344 transaction failed 29189/-22, size 0-0 line 2852
binder: 28345:28345 transaction failed 29189/-22, size 0-0 line 2852
binder: 28379:28379 transaction failed 29189/-22, size 0-0 line 2852
binder: undelivered TRANSACTION_ERROR: 29189
 kthread+0x345/0x410 kernel/kthread.c:246
binder: 28380:28380 transaction failed 29189/-22, size 0-0 line 2852
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
binder: 28382:28382 transaction failed 29189/-22, size 0-0 line 2852

Showing all locks held in the system:
binder: 28383:28383 transaction failed 29189/-22, size 0-0 line 2852
2 locks held by kworker/0:2/26:
1 lock held by khungtaskd/901:
 #0: 00000000b90aad90 (rcu_read_lock){....}
binder: 28386:28386 transaction failed 29189/-22, size 0-0 line 2852
, at: debug_show_all_locks+0xd0/0x428 kernel/locking/lockdep.c:4461
2 locks held by kworker/u4:4/1880:
 #0: 
binder: undelivered TRANSACTION_ERROR: 29189
0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: __write_once_size include/linux/compiler.h:215 [inline]
0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:59 [inline]
0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: process_one_work+0xb44/0x1ba0 kernel/workqueue.c:2124
 #1: 00000000f05f76fd ((reaper_work).work){+.+.}, at: process_one_work+0xb9b/0x1ba0 kernel/workqueue.c:2128
1 lock held by rsyslogd/4404:
binder: 28388:28388 transaction failed 29189/-22, size 0-0 line 2852
2 locks held by getty/4494:
 #0: 0000000053fdd7dd (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 00000000fde23e13 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4495:
 #0: 00000000c2578c69 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 000000003cda7e20 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4496:
 #0: 00000000811b7e4b (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 000000007b605873 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4497:
 #0: 0000000079dc5d75 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 00000000e502aab6 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4498:
 #0: 000000005a7cc9c3 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 
binder: undelivered TRANSACTION_ERROR: 29189
00000000ddfcd04c (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4499:
binder: 28390:28390 transaction failed 29189/-22, size 0-0 line 2852
 #0: 0000000077ec1cea (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 00000000ed933ff6 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4500:
binder: 28392:28392 transaction failed 29189/-22, size 0-0 line 2852
 #0: 000000001b7e2d98 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 
binder: 28393:28393 transaction failed 29189/-22, size 0-0 line 2852
00000000bdd52aa2 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
1 lock held by syz-executor0/4537:
binder: 28394:28394 transaction failed 29189/-22, size 0-0 line 2852
2 locks held by kworker/u4:0/4647:
 #0: 0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: __write_once_size include/linux/compiler.h:215 [inline]
 #0: 0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: 0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
 #0: 0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:59 [inline]
 #0: 0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
 #0: 0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
 #0: 0000000004f09101 ((wq_completion)"events_unbound"){+.+.}, at: process_one_work+0xb44/0x1ba0 kernel/workqueue.c:2124
 #1: 
binder: 28395:28395 transaction failed 29189/-22, size 0-0 line 2852
000000009b2a6aec (connector_reaper_work){+.+.}, at: process_one_work+0xb9b/0x1ba0 kernel/workqueue.c:2128
1 lock held by udevd/28381:
binder: undelivered TRANSACTION_ERROR: 29189

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

NMI backtrace for cpu 1
CPU: 1 PID: 901 Comm: khungtaskd Not tainted 4.18.0-rc6+ #160
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
binder: 28397:28397 transaction failed 29189/-22, size 0-0 line 2852
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x1c9/0x2b4 lib/dump_stack.c:113
binder: 28399:28399 transaction failed 29189/-22, size 0-0 line 2852
 nmi_cpu_backtrace.cold.4+0x19/0xce lib/nmi_backtrace.c:103
binder: 28400:28400 transaction failed 29189/-22, size 0-0 line 2852
 nmi_trigger_cpumask_backtrace+0x151/0x192 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:138 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:196 [inline]
 watchdog+0x9c4/0xf80 kernel/hung_task.c:252
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
binder: undelivered TRANSACTION_ERROR: 29189
 kthread+0x345/0x410 kernel/kthread.c:246
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
binder: undelivered TRANSACTION_ERROR: 29189
Sending NMI from CPU 1 to CPUs 0:
binder: undelivered TRANSACTION_ERROR: 29189
NMI backtrace for cpu 0
CPU: 0 PID: 26 Comm: kworker/0:2 Not tainted 4.18.0-rc6+ #160
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: events binder_deferred_func
RIP: 0010:match_held_lock+0xb7/0x8d0 kernel/locking/lockdep.c:3499
Code: 00 0f 85 19 05 00 00 49 39 75 10 0f 84 77 02 00 00 48 b8 00 00 00 00 00 fc ff df 49 8d 7d 22 48 89 fa 48 c1 ea 03 0f b6 14 02 <48> 89 f8 83 e0 07 83 c0 01 38 d0 7c 08 84 d2 0f 85 ac 04 00 00 66 
RSP: 0018:ffff8801dae071d8 EFLAGS: 00000802
RAX: dffffc0000000000 RBX: 1ffff1003b5c0e40 RCX: ffffffff88fb1120
RDX: 0000000000000000 RSI: ffffffff88fb3558 RDI: ffff8801d9436fba
RBP: ffff8801dae072c8 R08: ffffed003b5c46d7 R09: ffffed003b5c46d6
R10: ffffed003b5c46d6 R11: ffff8801dae236b3 R12: ffff8801d94366c0
R13: ffff8801d9436f98 R14: ffff8801dae072a0 R15: 0000000000000004
FS:  0000000000000000(0000) GS:ffff8801dae00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000007e37d0 CR3: 00000001ac238000 CR4: 00000000001406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 __lock_is_held+0xb5/0x140 kernel/locking/lockdep.c:3744
 lock_is_held_type+0x121/0x210 kernel/locking/lockdep.c:3962
 lock_is_held include/linux/lockdep.h:344 [inline]
 task_css_set include/linux/cgroup.h:464 [inline]
 task_dfl_cgroup include/linux/cgroup.h:527 [inline]
 cgroup_account_cputime include/linux/cgroup.h:727 [inline]
 update_curr+0x822/0xc00 kernel/sched/fair.c:832
 enqueue_entity+0x40d/0x2130 kernel/sched/fair.c:4187
 enqueue_task_fair+0x22d/0x910 kernel/sched/fair.c:5407
 enqueue_task kernel/sched/core.c:750 [inline]
 activate_task+0x123/0x2e0 kernel/sched/core.c:769
 ttwu_activate kernel/sched/core.c:1658 [inline]
 ttwu_do_activate+0xd5/0x1f0 kernel/sched/core.c:1717
 ttwu_queue kernel/sched/core.c:1862 [inline]
 try_to_wake_up+0x948/0x12b0 kernel/sched/core.c:2075
 wake_up_process+0x10/0x20 kernel/sched/core.c:2148
 hrtimer_wakeup+0x48/0x60 kernel/time/hrtimer.c:1647
 __run_hrtimer kernel/time/hrtimer.c:1398 [inline]
 __hrtimer_run_queues+0x3eb/0x10c0 kernel/time/hrtimer.c:1460
 hrtimer_interrupt+0x2f3/0x750 kernel/time/hrtimer.c:1518
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1025 [inline]
 smp_apic_timer_interrupt+0x165/0x730 arch/x86/kernel/apic/apic.c:1050
 apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:863
 </IRQ>
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783 [inline]
RIP: 0010:console_trylock_spinning kernel/printk/printk.c:1678 [inline]
RIP: 0010:vprintk_emit+0xbe9/0xdf0 kernel/printk/printk.c:1906
Code: fc ff df 41 80 3c 04 00 0f 85 d4 01 00 00 48 83 3d 63 b5 8e 07 00 0f 84 fe 00 00 00 e8 80 1c 19 00 48 8b bd a8 fe ff ff 57 9d <0f> 1f 44 00 00 e9 18 fe ff ff 41 80 fd 64 0f 84 eb f9 ff ff e9 ef 
RSP: 0018:ffff8801d9446fc8 EFLAGS: 00000293 ORIG_RAX: ffffffffffffff13
RAX: ffff8801d94366c0 RBX: 0000000000000200 RCX: 1ffff1003b286de8
RDX: 0000000000000000 RSI: ffffffff8162fb50 RDI: 0000000000000293
RBP: ffff8801d9447158 R08: ffff8801d9436ef8 R09: 0000000000000006
R10: ffff8801d94366c0 R11: 0000000000000000 R12: 1ffffffff11e3615
R13: 000000000000002c R14: ffffed003b288e16 R15: ffffffff8aa0c4a0
 vprintk_default+0x28/0x30 kernel/printk/printk.c:1948
 vprintk_func+0x7a/0xe7 kernel/printk/printk_safe.c:382
 printk+0xa7/0xcf kernel/printk/printk.c:1981
 binder_release_work.cold.64+0x2c/0xa2 drivers/android/binder.c:4213
 binder_thread_release+0x525/0x680 drivers/android/binder.c:4401
 binder_deferred_release drivers/android/binder.c:4946 [inline]
 binder_deferred_func+0x6d6/0x1340 drivers/android/binder.c:5029
 process_one_work+0xc73/0x1ba0 kernel/workqueue.c:2153
 worker_thread+0x189/0x13c0 kernel/workqueue.c:2296
 kthread+0x345/0x410 kernel/kthread.c:246
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412

Crashes (13):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets Title
ci-upstream-kasan-gce 2018/07/23 15:09 upstream d72e90f33aa4 f69c5fcd .config console log report syz
ci-upstream-kasan-gce-root 2018/07/22 01:44 upstream 490fc053865c 8cc079c3 .config console log report syz
ci-upstream-kasan-gce 2018/07/21 06:12 upstream 28c20cc73b9c af255b09 .config console log report syz
ci-upstream-kasan-gce-root 2018/07/18 05:51 upstream 3c53776e29f8 6d5bd5b5 .config console log report syz
ci-upstream-kasan-gce 2018/07/10 16:03 upstream 092150a25cb7 9fa03fa5 .config console log report syz
ci-upstream-kasan-gce-root 2018/07/09 08:30 upstream ca04b3cca11a f25e5770 .config console log report syz
ci-upstream-kasan-gce-root 2018/06/27 07:41 upstream 813835028e9a b0294c53 .config console log report syz
ci-upstream-kasan-gce-root 2018/06/04 07:08 upstream 325e14f97e0c 2f93b54f .config console log report syz
ci-upstream-kasan-gce 2018/06/04 03:03 upstream 325e14f97e0c 2f93b54f .config console log report syz
ci-upstream-kasan-gce-root 2018/05/05 09:56 upstream 625e2001e99e 9ce14f4b .config console log report syz
ci-upstream-kasan-gce-root 2018/04/17 22:06 upstream a27fc14219f2 b80fd3b5 .config console log report syz
ci-upstream-kasan-gce-386 2018/06/27 10:03 upstream 813835028e9a 43e60f7e .config console log report syz
ci-upstream-kasan-gce-root 2018/08/10 01:16 upstream 112cbae26d18 1fb62d58 .config console log report
* Struck through repros no longer work on HEAD.