Peter, what is the canonical location to reference for this issue
(open bug or something)? When we get back to this report later, how
does one know if this is fixed or not and what's the status?
The C repro hanged the machine even faster, so it must be some other difference.
I would expect compiler to not make difference. qemu, number of CPUs
and maybe host kernel config (at least for interrupt granularity or
something?) may be relevant.
But if you want to run syzkaller reproducer with syz-execprog, there
is a docs link in the "syz repro" link.
# [ 38.881989] hrtimer: interrupt took 28594 ns
[ 91.730829] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0
nice=0 stuck for 51s!
[ 91.734505] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
nice=0 stuck for 51s!
[ 91.735403] BUG: workqueue lockup - pool cpus=2 node=0 flags=0x0
nice=0 stuck for 51s!
[ 91.736273] BUG: workqueue lockup - pool cpus=2 node=0 flags=0x0
nice=-20 stuck for 49s!
[ 91.737173] BUG: workqueue lockup - pool cpus=3 node=0 flags=0x0
nice=0 stuck for 51s!
[ 91.738044] BUG: workqueue lockup - pool cpus=0-3 flags=0x4 nice=0
stuck for 49s!
[ 91.738887] Showing busy workqueues and worker pools:
[ 91.739496] workqueue events: flags=0x0
[ 91.740012] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=3/256
[ 91.740784] pending: defense_work_handler, e1000_watchdog, cache_reap
[ 91.741584] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=2/256
[ 91.742237] pending: cache_reap, check_corruption
[ 91.742802] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[ 91.743451] pending: cache_reap
[ 91.743844] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=3/256
[ 91.744497] pending: vmstat_shepherd, cache_reap, psi_update_work
[ 91.745286] workqueue events_unbound: flags=0x2
[ 91.745872] pwq 8: cpus=0-3 flags=0x4 nice=0 active=1/512
[ 91.747586] pending: flush_to_ldisc
[ 91.748049]
[ 91.748052] ======================================================
[ 91.748055] WARNING: possible circular locking dependency detected
[ 91.748056] 5.0.0-rc7+ #7 Not tainted
[ 91.748058] ------------------------------------------------------
[ 91.748060] a.out/6057 is trying to acquire lock:
[ 91.748062] 00000000a11439e2 (console_owner){-.-.}, at:
console_unlock+0x4d3/0x11e0
[ 91.748068]
[ 91.748069] but task is already holding lock:
[ 91.748071] 0000000082e8b4f5 (&pool->lock/1){-.-.}, at:
show_workqueue_state.cold+0xac5/0x15a8
[ 91.748078]
[ 91.748080] which lock already depends on the new lock.
[ 91.748081]
[ 91.748082]
[ 91.748084] the existing dependency chain (in reverse order) is:
[ 91.748085]
[ 91.748086] -> #3 (&pool->lock/1){-.-.}:
[ 91.748092] _raw_spin_lock+0x2f/0x40
[ 91.748094] __queue_work+0x2d9/0x1450
[ 91.748095] queue_work_on+0x192/0x200
[ 91.748097] tty_schedule_flip+0x149/0x1e0
[ 91.748099] tty_flip_buffer_push+0x16/0x20
[ 91.748101] pty_write+0x1a6/0x200
[ 91.748102] n_tty_write+0xb9e/0x1220
[ 91.748104] tty_write+0x45b/0x7a0
[ 91.748105] __vfs_write+0x116/0xb40
[ 91.748107] vfs_write+0x20c/0x580
[ 91.748109] ksys_write+0x105/0x260
[ 91.748110] __x64_sys_write+0x73/0xb0
[ 91.748112] do_syscall_64+0x1a3/0x800
[ 91.748114] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 91.748115]
[ 91.748116] -> #2 (&(&port->lock)->rlock){-.-.}:
[ 91.748122] _raw_spin_lock_irqsave+0x95/0xd0
[ 91.748123] tty_port_tty_get+0x22/0x80
[ 91.748125] tty_port_default_wakeup+0x16/0x40
[ 91.748127] tty_port_tty_wakeup+0x5d/0x70
[ 91.748129] uart_write_wakeup+0x46/0x70
[ 91.748131] serial8250_tx_chars+0x4a4/0xcc0
[ 91.748133] serial8250_handle_irq.part.0+0x1be/0x2e0
[ 91.748135] serial8250_default_handle_irq+0xc5/0x150
[ 91.748136] serial8250_interrupt+0xfb/0x1a0
[ 91.748138] __handle_irq_event_percpu+0x1c6/0xb10
[ 91.748140] handle_irq_event_percpu+0xa0/0x1d0
[ 91.748142] handle_irq_event+0xa7/0x134
[ 91.748144] handle_edge_irq+0x232/0x8a0
[ 91.748145] handle_irq+0x252/0x3d8
[ 91.748147] do_IRQ+0x99/0x1d0
[ 91.748148] ret_from_intr+0x0/0x1e
[ 91.748150] native_safe_halt+0x2/0x10
[ 91.748152] arch_cpu_idle+0x10/0x20
[ 91.748153] default_idle_call+0x36/0x90
[ 91.748155] do_idle+0x386/0x5d0
[ 91.748157] cpu_startup_entry+0x1b/0x20
[ 91.748158] rest_init+0x245/0x37b
[ 91.748160] arch_call_rest_init+0xe/0x1b
[ 91.748161] start_kernel+0x877/0x8b2
[ 91.748163] x86_64_start_reservations+0x29/0x2b
[ 91.748165] x86_64_start_kernel+0x77/0x7b
[ 91.748167] secondary_startup_64+0xa4/0xb0
[ 91.748168]
[ 91.748169] -> #1 (&port_lock_key){-.-.}:
[ 91.748175] _raw_spin_lock_irqsave+0x95/0xd0
[ 91.748177] serial8250_console_write+0x253/0xab0
[ 91.748178] univ8250_console_write+0x5f/0x70
[ 91.748180] console_unlock+0xcff/0x11e0
[ 91.748182] vprintk_emit+0x370/0x960
[ 91.748183] vprintk_default+0x28/0x30
[ 91.748185] vprintk_func+0x7e/0x189
[ 91.748187] printk+0xba/0xed
[ 91.748189] register_console+0x74d/0xb50
[ 91.748190] univ8250_console_init+0x3e/0x4b
[ 91.748192] console_init+0x6af/0x9f3
[ 91.748194] start_kernel+0x5dc/0x8b2
[ 91.748196] x86_64_start_reservations+0x29/0x2b
[ 91.748198] x86_64_start_kernel+0x77/0x7b
[ 91.748200] secondary_startup_64+0xa4/0xb0
[ 91.748200]
[ 91.748201] -> #0 (console_owner){-.-.}:
[ 91.748207] lock_acquire+0x1db/0x570
[ 91.748209] console_unlock+0x53d/0x11e0
[ 91.748211] vprintk_emit+0x370/0x960
[ 91.748212] vprintk_default+0x28/0x30
[ 91.748214] vprintk_func+0x7e/0x189
[ 91.748215] printk+0xba/0xed
[ 91.748217] show_workqueue_state.cold+0xc5f/0x15a8
[ 91.748219] wq_watchdog_timer_fn+0x6bd/0x7e0
[ 91.748221] call_timer_fn+0x254/0x900
[ 91.748222] __run_timers+0x6fc/0xd50
[ 91.748224] run_timer_softirq+0x88/0xb0
[ 91.748226] __do_softirq+0x30b/0xb11
[ 91.748227] irq_exit+0x180/0x1d0
[ 91.748229] smp_apic_timer_interrupt+0x1b7/0x760
[ 91.748231] apic_timer_interrupt+0xf/0x20
[ 91.748233] __sanitizer_cov_trace_const_cmp8+0x13/0x20
[ 91.748234] sanity+0x109/0x330
[ 91.748236] copy_page_to_iter+0x634/0x1000
[ 91.748238] generic_file_read_iter+0xbb1/0x2d40
[ 91.748240] ext4_file_read_iter+0x180/0x3c0
[ 91.748242] generic_file_splice_read+0x5c4/0xa90
[ 91.748243] do_splice_to+0x12a/0x190
[ 91.748245] splice_direct_to_actor+0x31b/0x9d0
[ 91.748247] do_splice_direct+0x2c7/0x420
[ 91.748249] do_sendfile+0x61d/0xe60
[ 91.748250] __x64_sys_sendfile64+0x15a/0x240
[ 91.748252] do_syscall_64+0x1a3/0x800
[ 91.748254] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 91.748255]
[ 91.748257] other info that might help us debug this:
[ 91.748258]
[ 91.748259] Chain exists of:
[ 91.748260] console_owner --> &(&port->lock)->rlock --> &pool->lock/1
[ 91.748268]
[ 91.748270] Possible unsafe locking scenario:
[ 91.748271]
[ 91.748273] CPU0 CPU1
[ 91.748274] ---- ----
[ 91.748275] lock(&pool->lock/1);
[ 91.748280] lock(&(&port->lock)->rlock);
[ 91.748284] lock(&pool->lock/1);
[ 91.748288] lock(console_owner);
[ 91.748291]
[ 91.748293] *** DEADLOCK ***
[ 91.748293]
[ 91.748295] 5 locks held by a.out/6057:
[ 91.748296] #0: 00000000878cae3a (sb_writers#3){.+.+}, at:
do_sendfile+0xae0/0xe60
[ 91.748304] #1: 000000007b4589c2 ((&wq_watchdog_timer)){+.-.}, at:
call_timer_fn+0x1b4/0x900
[ 91.748311] #2: 0000000085eca237 (rcu_read_lock_sched){....}, at:
show_workqueue_state+0x0/0x180
[ 91.748318] #3: 0000000082e8b4f5 (&pool->lock/1){-.-.}, at:
show_workqueue_state.cold+0xac5/0x15a8
[ 91.748326] #4: 00000000fffd7726 (console_lock){+.+.}, at:
vprintk_emit+0x351/0x960
[ 91.748332]
[ 91.748334] stack backtrace:
[ 91.748336] CPU: 0 PID: 6057 Comm: a.out Not tainted 5.0.0-rc7+ #7
[ 91.748339] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.10.2-1 04/01/2014
[ 91.748340] Call Trace:
[ 91.748341] <IRQ>
[ 91.748343] dump_stack+0x1db/0x2d0
[ 91.748345] ? dump_stack_print_info.cold+0x20/0x20
[ 91.748347] ? print_stack_trace+0x77/0xb0
[ 91.748348] ? vprintk_func+0x86/0x189
[ 91.748350] print_circular_bug.isra.0.cold+0x1cc/0x28f
[ 91.748352] __lock_acquire+0x3014/0x4a30
[ 91.748354] ? mark_held_locks+0x100/0x100
[ 91.748355] ? memcpy+0x46/0x50
[ 91.748357] ? add_lock_to_list.isra.0+0x450/0x450
[ 91.748358] ? sprintf+0xc0/0x100
[ 91.748360] ? scnprintf+0x140/0x140
[ 91.748362] ? console_unlock+0x518/0x11e0
[ 91.748364] ? find_held_lock+0x35/0x120
[ 91.748365] lock_acquire+0x1db/0x570
[ 91.748367] ? console_unlock+0x4d3/0x11e0
[ 91.748369] ? lock_release+0xc40/0xc40
[ 91.748371] ? do_raw_spin_trylock+0x270/0x270
[ 91.748373] ? lock_acquire+0x1db/0x570
[ 91.748374] console_unlock+0x53d/0x11e0
[ 91.748376] ? console_unlock+0x4d3/0x11e0
[ 91.748378] ? kmsg_dump_rewind+0x2b0/0x2b0
[ 91.748380] ? _raw_spin_unlock_irqrestore+0xa4/0xe0
[ 91.748382] ? vprintk_emit+0x351/0x960
[ 91.748384] ? __down_trylock_console_sem+0x148/0x210
[ 91.748385] vprintk_emit+0x370/0x960
[ 91.748387] ? wake_up_klogd+0x180/0x180
[ 91.748389] ? lockdep_hardirqs_on+0x19b/0x5d0
[ 91.748390] ? retint_kernel+0x2d/0x2d
[ 91.748392] ? trace_hardirqs_on_caller+0xc0/0x310
[ 91.748394] vprintk_default+0x28/0x30
[ 91.748396] vprintk_func+0x7e/0x189
[ 91.748397] ? printk+0xba/0xed
[ 91.748398] printk+0xba/0xed
[ 91.748400] ? kmsg_dump_rewind_nolock+0xe4/0xe4
[ 91.748402] ? wq_watchdog_touch+0xb0/0x102
[ 91.748404] show_workqueue_state.cold+0xc5f/0x15a8
[ 91.748406] ? print_worker_info+0x540/0x540
[ 91.748408] ? add_lock_to_list.isra.0+0x450/0x450
[ 91.748409] ? retint_kernel+0x2d/0x2d
[ 91.748411] ? trace_hardirqs_on_thunk+0x1a/0x1c
[ 91.748413] ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[ 91.748415] ? lock_downgrade+0x910/0x910
[ 91.748416] ? kasan_check_read+0x11/0x20
[ 91.748418] ? rcu_dynticks_curr_cpu_in_eqs+0xa2/0x170
[ 91.748420] ? rcu_read_unlock_special+0x380/0x380
[ 91.748422] ? wq_watchdog_timer_fn+0x4f4/0x7e0
[ 91.748424] wq_watchdog_timer_fn+0x6bd/0x7e0
[ 91.748426] ? show_workqueue_state+0x180/0x180
[ 91.748428] ? add_lock_to_list.isra.0+0x450/0x450
[ 91.748430] ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[ 91.748432] ? check_preemption_disabled+0x48/0x290
[ 91.748433] ? __lock_is_held+0xb6/0x140
[ 91.748435] call_timer_fn+0x254/0x900
[ 91.748437] ? show_workqueue_state+0x180/0x180
[ 91.748438] ? process_timeout+0x40/0x40
[ 91.748440] ? retint_kernel+0x2d/0x2d
[ 91.748442] ? show_workqueue_state+0x180/0x180
[ 91.748443] ? _raw_spin_unlock_irq+0x54/0x90
[ 91.748445] ? show_workqueue_state+0x180/0x180
[ 91.748447] __run_timers+0x6fc/0xd50
[ 91.748449] ? __bpf_trace_timer_expire_entry+0x30/0x30
[ 91.748451] ? print_usage_bug+0xd0/0xd0
[ 91.748452] ? find_held_lock+0x35/0x120
[ 91.748454] ? clockevents_program_event+0x15f/0x380
[ 91.748456] ? add_lock_to_list.isra.0+0x450/0x450
[ 91.748458] ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[ 91.748460] ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[ 91.748462] ? check_preemption_disabled+0x48/0x290
[ 91.748464] ? __lock_is_held+0xb6/0x140
[ 91.748466] ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[ 91.748468] ? check_preemption_disabled+0x48/0x290
[ 91.748469] run_timer_softirq+0x88/0xb0
[ 91.748471] ? rcu_read_lock_sched_held+0x110/0x130
[ 91.748473] __do_softirq+0x30b/0xb11
[ 91.748475] ? __irqentry_text_end+0x1f96c2/0x1f96c2
[ 91.748477] ? kvm_clock_read+0x18/0x30
[ 91.748478] ? kvm_sched_clock_read+0x9/0x20
[ 91.748480] ? sched_clock+0x2e/0x50
[ 91.748482] ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[ 91.748484] ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[ 91.748486] ? check_preemption_disabled+0x48/0x290
[ 91.748487] irq_exit+0x180/0x1d0
[ 91.748489] smp_apic_timer_interrupt+0x1b7/0x760
[ 91.748491] ? trace_hardirqs_off_thunk+0x1a/0x1c
[ 91.748493] ? smp_call_function_single_interrupt+0x640/0x640
[ 91.748495] ? trace_hardirqs_off+0x310/0x310
[ 91.748497] ? task_prio+0x50/0x50
[ 91.748499] ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[ 91.748501] ? check_preemption_disabled+0x48/0x290
[ 91.748502] ? trace_hardirqs_off_thunk+0x1a/0x1c
[ 91.748504] apic_timer_interrupt+0xf/0x20
[ 91.748505] </IRQ>
[ 91.748508] RIP: 0010:__sanitizer_cov_trace_const_cmp8+0x13/0x20
[ 91.748509] Code: 00
[ 91.748512] Lost 71 message(s)!
[ 91.866234] workqueue events_power_efficient: flags=0x80
[ 91.866863] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=2/256
[ 91.867568] pending: gc_worker, neigh_periodic_work
[ 91.868202] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=3/256
[ 91.868911] pending: crda_timeout_work, neigh_periodic_work,
do_cache_clean
[ 91.869781] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[ 91.870488] pending: fb_flashcursor
[ 91.870963] workqueue mm_percpu_wq: flags=0x8
[ 91.871482] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[ 91.872188] pending: vmstat_update
[ 91.872644] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
[ 91.873353] pending: vmstat_update
[ 91.873806] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
[ 91.874512] pending: vmstat_update
[ 91.874964] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256
[ 91.875670] pending: vmstat_update
[ 91.876131] workqueue writeback: flags=0x4e
[ 91.876631] pwq 8: cpus=0-3 flags=0x4 nice=0 active=1/256
[ 91.877292] pending: wb_workfn
[ 91.877716] workqueue kblockd: flags=0x18
[ 91.878201] pwq 5: cpus=2 node=0 flags=0x0 nice=-20 active=1/256
[ 91.878930] pending: blk_mq_timeout_work
[ 91.879513] workqueue dm_bufio_cache: flags=0x8
[ 91.880053] pwq 6: cpus=3 node=0 flags=0x0 nice=0 active=1/256
[ 91.880761] pending: work_fn