Hi,
I bisected a regression where reading from a Bluetooth device gets stuck
in recvfrom() calls. The device here is a Wii Balance Board, using
https://github.com/initialstate/beerfridge/blob/master/wiiboard_test.py;
this worked fine in v6.6.1 and v6.6.8, but when I tried on a v6.6.14
build, the script no longer outputs any readings.
1d576c3a5af850bf11fbd103f9ba11aa6d6061fb is the first bad commit
which maps to upstream commit 2e07e8348ea454615e268222ae3fc240421be768:
Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
With this commit in place, as also in v6.7 and v6.7.6, the script does
not output anything _unless_ I strace the process, in which case a bunch
of recvmsg() syscalls are shown, and then it hangs again. If I ^C the
strace and run it a few times, eventually the script will get enough data
and output a reading.
If I don't strace the script, a hung task warning appears:
INFO: task kworker/u9:1:121 blocked for more than 30 seconds.
Not tainted 6.7.6-lemon #183
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u9:1 state:D stack:0 pid:121 tgid:121 ppid:2 flags:0x00004000
Workqueue: hci0 hci_rx_work
Call Trace:
<TASK>
__schedule+0x37d/0xa00
schedule+0x32/0xe0
__lock_sock+0x68/0xa0
? __pfx_autoremove_wake_function+0x10/0x10
lock_sock_nested+0x43/0x50
l2cap_sock_recv_cb+0x21/0xa0
l2cap_recv_frame+0x55b/0x30a0
? psi_task_switch+0xeb/0x270
? finish_task_switch.isra.0+0x93/0x2a0
hci_rx_work+0x33a/0x3f0
process_one_work+0x13a/0x2f0
worker_thread+0x2f0/0x410
? __pfx_worker_thread+0x10/0x10
kthread+0xe0/0x110
? __pfx_kthread+0x10/0x10
ret_from_fork+0x2c/0x50
? __pfx_kthread+0x10/0x10
ret_from_fork_asm+0x1b/0x30
</TASK>
On 6.8-rc6 with lockdep enabled, I get the following output:
[ 22.122337] wlan0: associated
[ 4547.622339] INFO: task kworker/u9:1:3528 blocked for more than 30 seconds.
[ 4547.622530] =====================================================
[ 4547.622531] WARNING: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected
[ 4547.622535] 6.8.0-rc6-lemon #190 Not tainted
[ 4547.622538] -----------------------------------------------------
[ 4547.622540] khungtaskd/39 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
[ 4547.622546] ffff888101554cf8 ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}, at: __flush_work+0x4b/0x3f0
[ 4547.622569]
and this task is already holding:
[ 4547.622571] ffffffff8367e600 (console_owner){....}-{0:0}, at: console_flush_all+0x1c9/0x4e0
[ 4547.622586] which would create a new lock dependency:
[ 4547.622587] (console_owner){....}-{0:0} -> ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}
[ 4547.622596]
but this new dependency connects a SOFTIRQ-irq-safe lock:
[ 4547.622598] (&trans_pcie->irq_lock){+.-.}-{3:3}
[ 4547.622601]
... which became SOFTIRQ-irq-safe at:
[ 4547.622603] lock_acquire+0xb0/0x280
[ 4547.622611] _raw_spin_lock+0x2b/0x40
[ 4547.622618] iwl_pcie_napi_poll+0x7a/0x130
[ 4547.622627] __napi_poll.constprop.0+0x23/0x1e0
[ 4547.622634] net_rx_action+0x137/0x2a0
[ 4547.622639] __do_softirq+0xc7/0x402
[ 4547.622645] do_softirq+0x42/0xa0
[ 4547.622651] __local_bh_enable_ip+0xb8/0xd0
[ 4547.622657] iwl_pcie_irq_handler+0x539/0xb70
[ 4547.622665] irq_thread_fn+0x1b/0x60
[ 4547.622670] irq_thread+0xe0/0x190
[ 4547.622675] kthread+0xe3/0x120
[ 4547.622679] ret_from_fork+0x2c/0x50
[ 4547.622684] ret_from_fork_asm+0x1b/0x30
[ 4547.622692]
to a SOFTIRQ-irq-unsafe lock:
[ 4547.622694] ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}
[ 4547.622698]
... which became SOFTIRQ-irq-unsafe at:
[ 4547.622699] ...
[ 4547.622700] lock_acquire+0xb0/0x280
[ 4547.622706] process_one_work+0x199/0x480
[ 4547.622713] worker_thread+0x1be/0x3b0
[ 4547.622719] kthread+0xe3/0x120
[ 4547.622722] ret_from_fork+0x2c/0x50
[ 4547.622725] ret_from_fork_asm+0x1b/0x30
[ 4547.622731]
other info that might help us debug this:
[ 4547.622732] Chain exists of:
&trans_pcie->irq_lock --> console_owner --> (work_completion)(&(&ops->cursor_work)->work)
[ 4547.622739] Possible interrupt unsafe locking scenario:
[ 4547.622741] CPU0 CPU1
[ 4547.622742] ---- ----
[ 4547.622742] lock((work_completion)(&(&ops->cursor_work)->work));
[ 4547.622745] local_irq_disable();
[ 4547.622746] lock(&trans_pcie->irq_lock);
[ 4547.622749] lock(console_owner);
[ 4547.622751] <Interrupt>
[ 4547.622752] lock(&trans_pcie->irq_lock);
[ 4547.622754]
*** DEADLOCK ***
[ 4547.622755] 5 locks held by khungtaskd/39:
[ 4547.622759] #0: ffffffff836f14e0 (rcu_read_lock){....}-{1:3}, at: watchdog+0xd8/0x7b0
[ 4547.622778] #1: ffffffff836ee820 (console_lock){+.+.}-{0:0}, at: _printk+0x47/0x50
[ 4547.622789] #2: ffffffff836ee870 (console_srcu){....}-{0:0}, at: console_flush_all+0x74/0x4e0
[ 4547.622800] #3: ffffffff8367e600 (console_owner){....}-{0:0}, at: console_flush_all+0x1c9/0x4e0
[ 4547.622810] #4: ffffffff837d8758 (printing_lock){....}-{3:3}, at: vt_console_print+0x47/0x430
[ 4547.622822]
the dependencies between SOFTIRQ-irq-safe lock and the holding lock:
[ 4547.622824] -> (&trans_pcie->irq_lock){+.-.}-{3:3} {
[ 4547.622830] HARDIRQ-ON-W at:
[ 4547.622833] lock_acquire+0xb0/0x280
[ 4547.622839] _raw_spin_lock_bh+0x33/0x40
[ 4547.622845] iwl_trans_pcie_alloc+0x2fd/0x990
[ 4547.622853] iwl_pci_probe+0x28/0x810
[ 4547.622859] pci_device_probe+0x94/0x120
[ 4547.622865] really_probe+0x15e/0x2f0
[ 4547.622872] __driver_probe_device+0x6e/0x110
[ 4547.622878] driver_probe_device+0x1a/0xe0
[ 4547.622884] __driver_attach+0x87/0x190
[ 4547.622890] bus_for_each_dev+0x66/0xb0
[ 4547.622894] bus_add_driver+0xea/0x1f0
[ 4547.622898] driver_register+0x54/0x100
[ 4547.622905] iwl_pci_register_driver+0x1a/0x40
[ 4547.622911] do_one_initcall+0x50/0x250
[ 4547.622918] kernel_init_freeable+0x243/0x3e0
[ 4547.622927] kernel_init+0x15/0x1a0
[ 4547.622931] ret_from_fork+0x2c/0x50
[ 4547.622935] ret_from_fork_asm+0x1b/0x30
[ 4547.622941] IN-SOFTIRQ-W at:
[ 4547.622943] lock_acquire+0xb0/0x280
[ 4547.622948] _raw_spin_lock+0x2b/0x40
[ 4547.622953] iwl_pcie_napi_poll+0x7a/0x130
[ 4547.622961] __napi_poll.constprop.0+0x23/0x1e0
[ 4547.622966] net_rx_action+0x137/0x2a0
[ 4547.622971] __do_softirq+0xc7/0x402
[ 4547.622978] do_softirq+0x42/0xa0
[ 4547.622983] __local_bh_enable_ip+0xb8/0xd0
[ 4547.622989] iwl_pcie_irq_handler+0x539/0xb70
[ 4547.622996] irq_thread_fn+0x1b/0x60
[ 4547.623002] irq_thread+0xe0/0x190
[ 4547.623006] kthread+0xe3/0x120
[ 4547.623011] ret_from_fork+0x2c/0x50
[ 4547.623014] ret_from_fork_asm+0x1b/0x30
[ 4547.623020] INITIAL USE at:
[ 4547.623022] lock_acquire+0xb0/0x280
[ 4547.623027] _raw_spin_lock_bh+0x33/0x40
[ 4547.623032] iwl_trans_pcie_alloc+0x2fd/0x990
[ 4547.623038] iwl_pci_probe+0x28/0x810
[ 4547.623043] pci_device_probe+0x94/0x120
[ 4547.623047] really_probe+0x15e/0x2f0
[ 4547.623053] __driver_probe_device+0x6e/0x110
[ 4547.623059] driver_probe_device+0x1a/0xe0
[ 4547.623064] __driver_attach+0x87/0x190
[ 4547.623070] bus_for_each_dev+0x66/0xb0
[ 4547.623073] bus_add_driver+0xea/0x1f0
[ 4547.623077] driver_register+0x54/0x100
[ 4547.623084] iwl_pci_register_driver+0x1a/0x40
[ 4547.623090] do_one_initcall+0x50/0x250
[ 4547.623096] kernel_init_freeable+0x243/0x3e0
[ 4547.623103] kernel_init+0x15/0x1a0
[ 4547.623107] ret_from_fork+0x2c/0x50
[ 4547.623110] ret_from_fork_asm+0x1b/0x30
[ 4547.623116] }
[ 4547.623118] ... key at: [<ffffffff8502fe90>] __key.20+0x0/0x10
[ 4547.623129] -> (&trans_pcie->reg_lock){+...}-{3:3} {
[ 4547.623134] HARDIRQ-ON-W at:
[ 4547.623137] lock_acquire+0xb0/0x280
[ 4547.623142] _raw_spin_lock_bh+0x33/0x40
[ 4547.623147] iwl_trans_pcie_set_bits_mask+0x25/0x60
[ 4547.623151] iwl_pcie_set_hw_ready+0x1e/0xa0
[ 4547.623160] iwl_pcie_prepare_card_hw+0x33/0x100
[ 4547.623165] iwl_pci_probe+0x42/0x810
[ 4547.623171] pci_device_probe+0x94/0x120
[ 4547.623175] really_probe+0x15e/0x2f0
[ 4547.623181] __driver_probe_device+0x6e/0x110
[ 4547.623186] driver_probe_device+0x1a/0xe0
[ 4547.623192] __driver_attach+0x87/0x190
[ 4547.623197] bus_for_each_dev+0x66/0xb0
[ 4547.623201] bus_add_driver+0xea/0x1f0
[ 4547.623205] driver_register+0x54/0x100
[ 4547.623211] iwl_pci_register_driver+0x1a/0x40
[ 4547.623217] do_one_initcall+0x50/0x250
[ 4547.623223] kernel_init_freeable+0x243/0x3e0
[ 4547.623229] kernel_init+0x15/0x1a0
[ 4547.623233] ret_from_fork+0x2c/0x50
[ 4547.623236] ret_from_fork_asm+0x1b/0x30
[ 4547.623242] INITIAL USE at:
[ 4547.623244] lock_acquire+0xb0/0x280
[ 4547.623249] _raw_spin_lock_bh+0x33/0x40
[ 4547.623254] iwl_trans_pcie_set_bits_mask+0x25/0x60
[ 4547.623257] iwl_pcie_set_hw_ready+0x1e/0xa0
[ 4547.623266] iwl_pcie_prepare_card_hw+0x33/0x100
[ 4547.623271] iwl_pci_probe+0x42/0x810
[ 4547.623277] pci_device_probe+0x94/0x120
[ 4547.623281] really_probe+0x15e/0x2f0
[ 4547.623286] __driver_probe_device+0x6e/0x110
[ 4547.623292] driver_probe_device+0x1a/0xe0
[ 4547.623297] __driver_attach+0x87/0x190
[ 4547.623303] bus_for_each_dev+0x66/0xb0
[ 4547.623306] bus_add_driver+0xea/0x1f0
[ 4547.623310] driver_register+0x54/0x100
[ 4547.623316] iwl_pci_register_driver+0x1a/0x40
[ 4547.623323] do_one_initcall+0x50/0x250
[ 4547.623328] kernel_init_freeable+0x243/0x3e0
[ 4547.623334] kernel_init+0x15/0x1a0
[ 4547.623338] ret_from_fork+0x2c/0x50
[ 4547.623342] ret_from_fork_asm+0x1b/0x30
[ 4547.623347] }
[ 4547.623348] ... key at: [<ffffffff8502fe80>] __key.19+0x0/0x10
[ 4547.623358] ... acquired at:
[ 4547.623359] _raw_spin_lock_bh+0x33/0x40
[ 4547.623364] iwl_trans_pcie_set_bits_mask+0x25/0x60
[ 4547.623368] iwl_pcie_apm_init+0x6e/0x1c0
[ 4547.623372] iwl_trans_pcie_start_fw+0x224/0x670
[ 4547.623377] iwl_mvm_load_ucode_wait_alive+0xd3/0x5a0
[ 4547.623383] iwl_run_init_mvm_ucode+0x8c/0x3a0
[ 4547.623387] iwl_mvm_start_get_nvm+0x87/0x210
[ 4547.623393] iwl_op_mode_mvm_start+0x962/0xb30
[ 4547.623399] _iwl_op_mode_start.isra.0+0x72/0xb0
[ 4547.623403] iwl_opmode_register+0x6a/0xe0
[ 4547.623408] iwl_mvm_init+0x21/0x60
[ 4547.623413] do_one_initcall+0x50/0x250
[ 4547.623419] kernel_init_freeable+0x243/0x3e0
[ 4547.623425] kernel_init+0x15/0x1a0
[ 4547.623429] ret_from_fork+0x2c/0x50
[ 4547.623432] ret_from_fork_asm+0x1b/0x30
[ 4547.623441] -> (console_owner){....}-{0:0} {
[ 4547.623446] INITIAL USE at:
[ 4547.623452] lock_acquire+0xb0/0x280
[ 4547.623457] console_flush_all+0x1f2/0x4e0
[ 4547.623463] console_unlock+0x33/0x110
[ 4547.623469] vprintk_emit+0x9f/0x320
[ 4547.623475] _printk+0x47/0x50
[ 4547.623479] register_console+0x34b/0x4d0
[ 4547.623485] con_init+0x200/0x270
[ 4547.623494] console_init+0x4a/0x1e0
[ 4547.623504] start_kernel+0x2b9/0x660
[ 4547.623510] x86_64_start_reservations+0x18/0x30
[ 4547.623517] x86_64_start_kernel+0xad/0xc0
[ 4547.623522] secondary_startup_64_no_verify+0x170/0x17b
[ 4547.623528] }
[ 4547.623529] ... key at: [<ffffffff8367e600>] console_owner_dep_map+0x0/0x28
[ 4547.623538] ... acquired at:
[ 4547.623540] console_flush_all+0x1f2/0x4e0
[ 4547.623545] console_unlock+0x33/0x110
[ 4547.623551] vprintk_emit+0x9f/0x320
[ 4547.623557] dev_vprintk_emit+0xce/0x160
[ 4547.623562] dev_printk_emit+0x3d/0x50
[ 4547.623566] _dev_info+0x5b/0x70
[ 4547.623572] __iwl_info+0x58/0x60
[ 4547.623576] iwl_pci_probe+0x11c/0x810
[ 4547.623582] pci_device_probe+0x94/0x120
[ 4547.623587] really_probe+0x15e/0x2f0
[ 4547.623592] __driver_probe_device+0x6e/0x110
[ 4547.623598] driver_probe_device+0x1a/0xe0
[ 4547.623603] __driver_attach+0x87/0x190
[ 4547.623609] bus_for_each_dev+0x66/0xb0
[ 4547.623612] bus_add_driver+0xea/0x1f0
[ 4547.623616] driver_register+0x54/0x100
[ 4547.623622] iwl_pci_register_driver+0x1a/0x40
[ 4547.623629] do_one_initcall+0x50/0x250
[ 4547.623634] kernel_init_freeable+0x243/0x3e0
[ 4547.623640] kernel_init+0x15/0x1a0
[ 4547.623644] ret_from_fork+0x2c/0x50
[ 4547.623648] ret_from_fork_asm+0x1b/0x30
[ 4547.623654]
the dependencies between the lock to be acquired
[ 4547.623655] and SOFTIRQ-irq-unsafe lock:
[ 4547.623665] -> ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0} {
[ 4547.623670] HARDIRQ-ON-W at:
[ 4547.623672] lock_acquire+0xb0/0x280
[ 4547.623677] process_one_work+0x199/0x480
[ 4547.623684] worker_thread+0x1be/0x3b0
[ 4547.623690] kthread+0xe3/0x120
[ 4547.623694] ret_from_fork+0x2c/0x50
[ 4547.623698] ret_from_fork_asm+0x1b/0x30
[ 4547.623704] SOFTIRQ-ON-W at:
[ 4547.623705] lock_acquire+0xb0/0x280
[ 4547.623710] process_one_work+0x199/0x480
[ 4547.623716] worker_thread+0x1be/0x3b0
[ 4547.623722] kthread+0xe3/0x120
[ 4547.623725] ret_from_fork+0x2c/0x50
[ 4547.623729] ret_from_fork_asm+0x1b/0x30
[ 4547.623734] INITIAL USE at:
[ 4547.623736] lock_acquire+0xb0/0x280
[ 4547.623741] process_one_work+0x199/0x480
[ 4547.623747] worker_thread+0x1be/0x3b0
[ 4547.623753] kthread+0xe3/0x120
[ 4547.623757] ret_from_fork+0x2c/0x50
[ 4547.623760] ret_from_fork_asm+0x1b/0x30
[ 4547.623766] }
[ 4547.623767] ... key at: [<ffffffff850211b0>] __key.1+0x0/0x10
[ 4547.623775] ... acquired at:
[ 4547.623777] lock_acquire+0xb0/0x280
[ 4547.623781] __flush_work+0x56/0x3f0
[ 4547.623789] __cancel_work_timer+0xd3/0x160
[ 4547.623796] fbcon_cursor+0x138/0x170
[ 4547.623802] hide_cursor+0x26/0xc0
[ 4547.623807] vt_console_print+0x41e/0x430
[ 4547.623814] console_flush_all+0x206/0x4e0
[ 4547.623820] console_unlock+0x33/0x110
[ 4547.623825] vprintk_emit+0x9f/0x320
[ 4547.623831] _printk+0x47/0x50
[ 4547.623834] watchdog+0x53a/0x7b0
[ 4547.623838] kthread+0xe3/0x120
[ 4547.623841] ret_from_fork+0x2c/0x50
[ 4547.623845] ret_from_fork_asm+0x1b/0x30
[ 4547.623851]
stack backtrace:
[ 4547.623854] CPU: 2 PID: 39 Comm: khungtaskd Not tainted 6.8.0-rc6-lemon #190
[ 4547.623860] Hardware name: LENOVO 80MK/VIUU4, BIOS C6CN29WW 09/02/2015
[ 4547.623862] Call Trace:
[ 4547.623865] <TASK>
[ 4547.623867] dump_stack_lvl+0x4a/0x80
[ 4547.623879] check_irq_usage+0x8aa/0xb10
[ 4547.623886] ? check_path.constprop.0+0x24/0x50
[ 4547.623896] ? check_noncircular+0x6d/0x120
[ 4547.623902] ? __lock_acquire+0x146a/0x25c0
[ 4547.623907] __lock_acquire+0x146a/0x25c0
[ 4547.623913] lock_acquire+0xb0/0x280
[ 4547.623918] ? __flush_work+0x4b/0x3f0
[ 4547.623925] ? __flush_work+0x4b/0x3f0
[ 4547.623932] __flush_work+0x56/0x3f0
[ 4547.623939] ? __flush_work+0x4b/0x3f0
[ 4547.623946] ? __lock_acquire+0x3ef/0x25c0
[ 4547.623952] __cancel_work_timer+0xd3/0x160
[ 4547.623960] fbcon_cursor+0x138/0x170
[ 4547.623965] hide_cursor+0x26/0xc0
[ 4547.623971] vt_console_print+0x41e/0x430
[ 4547.623977] ? lock_release+0xb5/0x230
[ 4547.623982] ? console_flush_all+0x1c9/0x4e0
[ 4547.623988] console_flush_all+0x206/0x4e0
[ 4547.623994] ? console_flush_all+0x1c9/0x4e0
[ 4547.624001] console_unlock+0x33/0x110
[ 4547.624007] vprintk_emit+0x9f/0x320
[ 4547.624013] _printk+0x47/0x50
[ 4547.624017] watchdog+0x53a/0x7b0
[ 4547.624021] ? __pfx_watchdog+0x10/0x10
[ 4547.624025] kthread+0xe3/0x120
[ 4547.624029] ? __pfx_kthread+0x10/0x10
[ 4547.624033] ret_from_fork+0x2c/0x50
[ 4547.624037] ? __pfx_kthread+0x10/0x10
[ 4547.624041] ret_from_fork_asm+0x1b/0x30
[ 4547.624049] </TASK>
[ 4548.028173] Not tainted 6.8.0-rc6-lemon #190
[ 4548.029491] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4548.031047] task:kworker/u9:1 state:D stack:0 pid:3528 tgid:3528 ppid:2 flags:0x00004000
[ 4548.032620] Workqueue: hci0 hci_rx_work
[ 4548.034099] Call Trace:
[ 4548.035572] <TASK>
[ 4548.036925] __schedule+0x427/0xd10
[ 4548.038382] ? schedule+0xf7/0x140
[ 4548.039822] schedule+0x45/0x140
[ 4548.041201] __lock_sock+0x86/0xf0
[ 4548.042601] ? __pfx_autoremove_wake_function+0x10/0x10
[ 4548.044030] lock_sock_nested+0x61/0x70
[ 4548.045390] l2cap_sock_recv_cb+0x21/0xa0
[ 4548.046842] l2cap_recv_frame+0x5be/0x2e70
[ 4548.048283] ? hci_rx_work+0x431/0x830
[ 4548.049701] ? lock_release+0xb5/0x230
[ 4548.051145] ? __mutex_unlock_slowpath+0x25/0x270
[ 4548.052524] hci_rx_work+0x457/0x830
[ 4548.053945] ? process_one_work+0x157/0x480
[ 4548.055460] process_one_work+0x1ca/0x480
[ 4548.056862] worker_thread+0x1be/0x3b0
[ 4548.058281] ? __pfx_worker_thread+0x10/0x10
[ 4548.059783] kthread+0xe3/0x120
[ 4548.061141] ? __pfx_kthread+0x10/0x10
[ 4548.062600] ret_from_fork+0x2c/0x50
[ 4548.064064] ? __pfx_kthread+0x10/0x10
[ 4548.065436] ret_from_fork_asm+0x1b/0x30
[ 4548.066867] </TASK>
[ 4548.068313] INFO: lockdep is turned off.
# cat /proc/3526/stack
[<0>] __skb_wait_for_more_packets+0xfa/0x150
[<0>] __skb_recv_datagram+0x59/0xa0
[<0>] skb_recv_datagram+0x29/0x40
[<0>] bt_sock_recvmsg+0x42/0x1c0
[<0>] l2cap_sock_recvmsg+0x5d/0x170
[<0>] __sys_recvfrom+0x14e/0x160
[<0>] __x64_sys_recvfrom+0x1f/0x30
[<0>] do_syscall_64+0x75/0x150
[<0>] entry_SYSCALL_64_after_hwframe+0x6e/0x76
This is on my laptop with iwlwifi, but at first I saw it on my desktop
with Ethernet (and Intel 9260 Bluetooth). I can get another lockdep
capture if that would be helpful.
Simon-
[CCing the bluetooth maintainers]
On 26.02.24 22:38, Simon Kirby wrote:
>
> I bisected a regression where reading from a Bluetooth device gets stuck
> in recvfrom() calls. The device here is a Wii Balance Board, using
> https://github.com/initialstate/beerfridge/blob/master/wiiboard_test.py;
> this worked fine in v6.6.1 and v6.6.8, but when I tried on a v6.6.14
> build, the script no longer outputs any readings.
>
> 1d576c3a5af850bf11fbd103f9ba11aa6d6061fb is the first bad commit
>
> which maps to upstream commit 2e07e8348ea454615e268222ae3fc240421be768:
Could you please check if this problem only occurs with the latest 6.6.y
versions, or also with mainline (6.8-rc8)? That's important to know, as
that in the end determines who and how this needs to be is handled.
Ciao, Thorsten
> Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
>
> With this commit in place, as also in v6.7 and v6.7.6, the script does
> not output anything _unless_ I strace the process, in which case a bunch
> of recvmsg() syscalls are shown, and then it hangs again. If I ^C the
> strace and run it a few times, eventually the script will get enough data
> and output a reading.
>
> If I don't strace the script, a hung task warning appears:
>
> INFO: task kworker/u9:1:121 blocked for more than 30 seconds.
> Not tainted 6.7.6-lemon #183
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/u9:1 state:D stack:0 pid:121 tgid:121 ppid:2 flags:0x00004000
> Workqueue: hci0 hci_rx_work
> Call Trace:
> <TASK>
> __schedule+0x37d/0xa00
> schedule+0x32/0xe0
> __lock_sock+0x68/0xa0
> ? __pfx_autoremove_wake_function+0x10/0x10
> lock_sock_nested+0x43/0x50
> l2cap_sock_recv_cb+0x21/0xa0
> l2cap_recv_frame+0x55b/0x30a0
> ? psi_task_switch+0xeb/0x270
> ? finish_task_switch.isra.0+0x93/0x2a0
> hci_rx_work+0x33a/0x3f0
> process_one_work+0x13a/0x2f0
> worker_thread+0x2f0/0x410
> ? __pfx_worker_thread+0x10/0x10
> kthread+0xe0/0x110
> ? __pfx_kthread+0x10/0x10
> ret_from_fork+0x2c/0x50
> ? __pfx_kthread+0x10/0x10
> ret_from_fork_asm+0x1b/0x30
> </TASK>
>
> On 6.8-rc6 with lockdep enabled, I get the following output:
>
> [ 22.122337] wlan0: associated
> [ 4547.622339] INFO: task kworker/u9:1:3528 blocked for more than 30 seconds.
>
> [ 4547.622530] =====================================================
> [ 4547.622531] WARNING: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected
> [ 4547.622535] 6.8.0-rc6-lemon #190 Not tainted
> [ 4547.622538] -----------------------------------------------------
> [ 4547.622540] khungtaskd/39 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
> [ 4547.622546] ffff888101554cf8 ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}, at: __flush_work+0x4b/0x3f0
> [ 4547.622569]
> and this task is already holding:
> [ 4547.622571] ffffffff8367e600 (console_owner){....}-{0:0}, at: console_flush_all+0x1c9/0x4e0
> [ 4547.622586] which would create a new lock dependency:
> [ 4547.622587] (console_owner){....}-{0:0} -> ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}
> [ 4547.622596]
> but this new dependency connects a SOFTIRQ-irq-safe lock:
> [ 4547.622598] (&trans_pcie->irq_lock){+.-.}-{3:3}
> [ 4547.622601]
> ... which became SOFTIRQ-irq-safe at:
> [ 4547.622603] lock_acquire+0xb0/0x280
> [ 4547.622611] _raw_spin_lock+0x2b/0x40
> [ 4547.622618] iwl_pcie_napi_poll+0x7a/0x130
> [ 4547.622627] __napi_poll.constprop.0+0x23/0x1e0
> [ 4547.622634] net_rx_action+0x137/0x2a0
> [ 4547.622639] __do_softirq+0xc7/0x402
> [ 4547.622645] do_softirq+0x42/0xa0
> [ 4547.622651] __local_bh_enable_ip+0xb8/0xd0
> [ 4547.622657] iwl_pcie_irq_handler+0x539/0xb70
> [ 4547.622665] irq_thread_fn+0x1b/0x60
> [ 4547.622670] irq_thread+0xe0/0x190
> [ 4547.622675] kthread+0xe3/0x120
> [ 4547.622679] ret_from_fork+0x2c/0x50
> [ 4547.622684] ret_from_fork_asm+0x1b/0x30
> [ 4547.622692]
> to a SOFTIRQ-irq-unsafe lock:
> [ 4547.622694] ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}
> [ 4547.622698]
> ... which became SOFTIRQ-irq-unsafe at:
> [ 4547.622699] ...
> [ 4547.622700] lock_acquire+0xb0/0x280
> [ 4547.622706] process_one_work+0x199/0x480
> [ 4547.622713] worker_thread+0x1be/0x3b0
> [ 4547.622719] kthread+0xe3/0x120
> [ 4547.622722] ret_from_fork+0x2c/0x50
> [ 4547.622725] ret_from_fork_asm+0x1b/0x30
> [ 4547.622731]
> other info that might help us debug this:
>
> [ 4547.622732] Chain exists of:
> &trans_pcie->irq_lock --> console_owner --> (work_completion)(&(&ops->cursor_work)->work)
>
> [ 4547.622739] Possible interrupt unsafe locking scenario:
>
> [ 4547.622741] CPU0 CPU1
> [ 4547.622742] ---- ----
> [ 4547.622742] lock((work_completion)(&(&ops->cursor_work)->work));
> [ 4547.622745] local_irq_disable();
> [ 4547.622746] lock(&trans_pcie->irq_lock);
> [ 4547.622749] lock(console_owner);
> [ 4547.622751] <Interrupt>
> [ 4547.622752] lock(&trans_pcie->irq_lock);
> [ 4547.622754]
> *** DEADLOCK ***
>
> [ 4547.622755] 5 locks held by khungtaskd/39:
> [ 4547.622759] #0: ffffffff836f14e0 (rcu_read_lock){....}-{1:3}, at: watchdog+0xd8/0x7b0
> [ 4547.622778] #1: ffffffff836ee820 (console_lock){+.+.}-{0:0}, at: _printk+0x47/0x50
> [ 4547.622789] #2: ffffffff836ee870 (console_srcu){....}-{0:0}, at: console_flush_all+0x74/0x4e0
> [ 4547.622800] #3: ffffffff8367e600 (console_owner){....}-{0:0}, at: console_flush_all+0x1c9/0x4e0
> [ 4547.622810] #4: ffffffff837d8758 (printing_lock){....}-{3:3}, at: vt_console_print+0x47/0x430
> [ 4547.622822]
> the dependencies between SOFTIRQ-irq-safe lock and the holding lock:
> [ 4547.622824] -> (&trans_pcie->irq_lock){+.-.}-{3:3} {
> [ 4547.622830] HARDIRQ-ON-W at:
> [ 4547.622833] lock_acquire+0xb0/0x280
> [ 4547.622839] _raw_spin_lock_bh+0x33/0x40
> [ 4547.622845] iwl_trans_pcie_alloc+0x2fd/0x990
> [ 4547.622853] iwl_pci_probe+0x28/0x810
> [ 4547.622859] pci_device_probe+0x94/0x120
> [ 4547.622865] really_probe+0x15e/0x2f0
> [ 4547.622872] __driver_probe_device+0x6e/0x110
> [ 4547.622878] driver_probe_device+0x1a/0xe0
> [ 4547.622884] __driver_attach+0x87/0x190
> [ 4547.622890] bus_for_each_dev+0x66/0xb0
> [ 4547.622894] bus_add_driver+0xea/0x1f0
> [ 4547.622898] driver_register+0x54/0x100
> [ 4547.622905] iwl_pci_register_driver+0x1a/0x40
> [ 4547.622911] do_one_initcall+0x50/0x250
> [ 4547.622918] kernel_init_freeable+0x243/0x3e0
> [ 4547.622927] kernel_init+0x15/0x1a0
> [ 4547.622931] ret_from_fork+0x2c/0x50
> [ 4547.622935] ret_from_fork_asm+0x1b/0x30
> [ 4547.622941] IN-SOFTIRQ-W at:
> [ 4547.622943] lock_acquire+0xb0/0x280
> [ 4547.622948] _raw_spin_lock+0x2b/0x40
> [ 4547.622953] iwl_pcie_napi_poll+0x7a/0x130
> [ 4547.622961] __napi_poll.constprop.0+0x23/0x1e0
> [ 4547.622966] net_rx_action+0x137/0x2a0
> [ 4547.622971] __do_softirq+0xc7/0x402
> [ 4547.622978] do_softirq+0x42/0xa0
> [ 4547.622983] __local_bh_enable_ip+0xb8/0xd0
> [ 4547.622989] iwl_pcie_irq_handler+0x539/0xb70
> [ 4547.622996] irq_thread_fn+0x1b/0x60
> [ 4547.623002] irq_thread+0xe0/0x190
> [ 4547.623006] kthread+0xe3/0x120
> [ 4547.623011] ret_from_fork+0x2c/0x50
> [ 4547.623014] ret_from_fork_asm+0x1b/0x30
> [ 4547.623020] INITIAL USE at:
> [ 4547.623022] lock_acquire+0xb0/0x280
> [ 4547.623027] _raw_spin_lock_bh+0x33/0x40
> [ 4547.623032] iwl_trans_pcie_alloc+0x2fd/0x990
> [ 4547.623038] iwl_pci_probe+0x28/0x810
> [ 4547.623043] pci_device_probe+0x94/0x120
> [ 4547.623047] really_probe+0x15e/0x2f0
> [ 4547.623053] __driver_probe_device+0x6e/0x110
> [ 4547.623059] driver_probe_device+0x1a/0xe0
> [ 4547.623064] __driver_attach+0x87/0x190
> [ 4547.623070] bus_for_each_dev+0x66/0xb0
> [ 4547.623073] bus_add_driver+0xea/0x1f0
> [ 4547.623077] driver_register+0x54/0x100
> [ 4547.623084] iwl_pci_register_driver+0x1a/0x40
> [ 4547.623090] do_one_initcall+0x50/0x250
> [ 4547.623096] kernel_init_freeable+0x243/0x3e0
> [ 4547.623103] kernel_init+0x15/0x1a0
> [ 4547.623107] ret_from_fork+0x2c/0x50
> [ 4547.623110] ret_from_fork_asm+0x1b/0x30
> [ 4547.623116] }
> [ 4547.623118] ... key at: [<ffffffff8502fe90>] __key.20+0x0/0x10
> [ 4547.623129] -> (&trans_pcie->reg_lock){+...}-{3:3} {
> [ 4547.623134] HARDIRQ-ON-W at:
> [ 4547.623137] lock_acquire+0xb0/0x280
> [ 4547.623142] _raw_spin_lock_bh+0x33/0x40
> [ 4547.623147] iwl_trans_pcie_set_bits_mask+0x25/0x60
> [ 4547.623151] iwl_pcie_set_hw_ready+0x1e/0xa0
> [ 4547.623160] iwl_pcie_prepare_card_hw+0x33/0x100
> [ 4547.623165] iwl_pci_probe+0x42/0x810
> [ 4547.623171] pci_device_probe+0x94/0x120
> [ 4547.623175] really_probe+0x15e/0x2f0
> [ 4547.623181] __driver_probe_device+0x6e/0x110
> [ 4547.623186] driver_probe_device+0x1a/0xe0
> [ 4547.623192] __driver_attach+0x87/0x190
> [ 4547.623197] bus_for_each_dev+0x66/0xb0
> [ 4547.623201] bus_add_driver+0xea/0x1f0
> [ 4547.623205] driver_register+0x54/0x100
> [ 4547.623211] iwl_pci_register_driver+0x1a/0x40
> [ 4547.623217] do_one_initcall+0x50/0x250
> [ 4547.623223] kernel_init_freeable+0x243/0x3e0
> [ 4547.623229] kernel_init+0x15/0x1a0
> [ 4547.623233] ret_from_fork+0x2c/0x50
> [ 4547.623236] ret_from_fork_asm+0x1b/0x30
> [ 4547.623242] INITIAL USE at:
> [ 4547.623244] lock_acquire+0xb0/0x280
> [ 4547.623249] _raw_spin_lock_bh+0x33/0x40
> [ 4547.623254] iwl_trans_pcie_set_bits_mask+0x25/0x60
> [ 4547.623257] iwl_pcie_set_hw_ready+0x1e/0xa0
> [ 4547.623266] iwl_pcie_prepare_card_hw+0x33/0x100
> [ 4547.623271] iwl_pci_probe+0x42/0x810
> [ 4547.623277] pci_device_probe+0x94/0x120
> [ 4547.623281] really_probe+0x15e/0x2f0
> [ 4547.623286] __driver_probe_device+0x6e/0x110
> [ 4547.623292] driver_probe_device+0x1a/0xe0
> [ 4547.623297] __driver_attach+0x87/0x190
> [ 4547.623303] bus_for_each_dev+0x66/0xb0
> [ 4547.623306] bus_add_driver+0xea/0x1f0
> [ 4547.623310] driver_register+0x54/0x100
> [ 4547.623316] iwl_pci_register_driver+0x1a/0x40
> [ 4547.623323] do_one_initcall+0x50/0x250
> [ 4547.623328] kernel_init_freeable+0x243/0x3e0
> [ 4547.623334] kernel_init+0x15/0x1a0
> [ 4547.623338] ret_from_fork+0x2c/0x50
> [ 4547.623342] ret_from_fork_asm+0x1b/0x30
> [ 4547.623347] }
> [ 4547.623348] ... key at: [<ffffffff8502fe80>] __key.19+0x0/0x10
> [ 4547.623358] ... acquired at:
> [ 4547.623359] _raw_spin_lock_bh+0x33/0x40
> [ 4547.623364] iwl_trans_pcie_set_bits_mask+0x25/0x60
> [ 4547.623368] iwl_pcie_apm_init+0x6e/0x1c0
> [ 4547.623372] iwl_trans_pcie_start_fw+0x224/0x670
> [ 4547.623377] iwl_mvm_load_ucode_wait_alive+0xd3/0x5a0
> [ 4547.623383] iwl_run_init_mvm_ucode+0x8c/0x3a0
> [ 4547.623387] iwl_mvm_start_get_nvm+0x87/0x210
> [ 4547.623393] iwl_op_mode_mvm_start+0x962/0xb30
> [ 4547.623399] _iwl_op_mode_start.isra.0+0x72/0xb0
> [ 4547.623403] iwl_opmode_register+0x6a/0xe0
> [ 4547.623408] iwl_mvm_init+0x21/0x60
> [ 4547.623413] do_one_initcall+0x50/0x250
> [ 4547.623419] kernel_init_freeable+0x243/0x3e0
> [ 4547.623425] kernel_init+0x15/0x1a0
> [ 4547.623429] ret_from_fork+0x2c/0x50
> [ 4547.623432] ret_from_fork_asm+0x1b/0x30
>
> [ 4547.623441] -> (console_owner){....}-{0:0} {
> [ 4547.623446] INITIAL USE at:
> [ 4547.623452] lock_acquire+0xb0/0x280
> [ 4547.623457] console_flush_all+0x1f2/0x4e0
> [ 4547.623463] console_unlock+0x33/0x110
> [ 4547.623469] vprintk_emit+0x9f/0x320
> [ 4547.623475] _printk+0x47/0x50
> [ 4547.623479] register_console+0x34b/0x4d0
> [ 4547.623485] con_init+0x200/0x270
> [ 4547.623494] console_init+0x4a/0x1e0
> [ 4547.623504] start_kernel+0x2b9/0x660
> [ 4547.623510] x86_64_start_reservations+0x18/0x30
> [ 4547.623517] x86_64_start_kernel+0xad/0xc0
> [ 4547.623522] secondary_startup_64_no_verify+0x170/0x17b
> [ 4547.623528] }
> [ 4547.623529] ... key at: [<ffffffff8367e600>] console_owner_dep_map+0x0/0x28
> [ 4547.623538] ... acquired at:
> [ 4547.623540] console_flush_all+0x1f2/0x4e0
> [ 4547.623545] console_unlock+0x33/0x110
> [ 4547.623551] vprintk_emit+0x9f/0x320
> [ 4547.623557] dev_vprintk_emit+0xce/0x160
> [ 4547.623562] dev_printk_emit+0x3d/0x50
> [ 4547.623566] _dev_info+0x5b/0x70
> [ 4547.623572] __iwl_info+0x58/0x60
> [ 4547.623576] iwl_pci_probe+0x11c/0x810
> [ 4547.623582] pci_device_probe+0x94/0x120
> [ 4547.623587] really_probe+0x15e/0x2f0
> [ 4547.623592] __driver_probe_device+0x6e/0x110
> [ 4547.623598] driver_probe_device+0x1a/0xe0
> [ 4547.623603] __driver_attach+0x87/0x190
> [ 4547.623609] bus_for_each_dev+0x66/0xb0
> [ 4547.623612] bus_add_driver+0xea/0x1f0
> [ 4547.623616] driver_register+0x54/0x100
> [ 4547.623622] iwl_pci_register_driver+0x1a/0x40
> [ 4547.623629] do_one_initcall+0x50/0x250
> [ 4547.623634] kernel_init_freeable+0x243/0x3e0
> [ 4547.623640] kernel_init+0x15/0x1a0
> [ 4547.623644] ret_from_fork+0x2c/0x50
> [ 4547.623648] ret_from_fork_asm+0x1b/0x30
>
> [ 4547.623654]
> the dependencies between the lock to be acquired
> [ 4547.623655] and SOFTIRQ-irq-unsafe lock:
> [ 4547.623665] -> ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0} {
> [ 4547.623670] HARDIRQ-ON-W at:
> [ 4547.623672] lock_acquire+0xb0/0x280
> [ 4547.623677] process_one_work+0x199/0x480
> [ 4547.623684] worker_thread+0x1be/0x3b0
> [ 4547.623690] kthread+0xe3/0x120
> [ 4547.623694] ret_from_fork+0x2c/0x50
> [ 4547.623698] ret_from_fork_asm+0x1b/0x30
> [ 4547.623704] SOFTIRQ-ON-W at:
> [ 4547.623705] lock_acquire+0xb0/0x280
> [ 4547.623710] process_one_work+0x199/0x480
> [ 4547.623716] worker_thread+0x1be/0x3b0
> [ 4547.623722] kthread+0xe3/0x120
> [ 4547.623725] ret_from_fork+0x2c/0x50
> [ 4547.623729] ret_from_fork_asm+0x1b/0x30
> [ 4547.623734] INITIAL USE at:
> [ 4547.623736] lock_acquire+0xb0/0x280
> [ 4547.623741] process_one_work+0x199/0x480
> [ 4547.623747] worker_thread+0x1be/0x3b0
> [ 4547.623753] kthread+0xe3/0x120
> [ 4547.623757] ret_from_fork+0x2c/0x50
> [ 4547.623760] ret_from_fork_asm+0x1b/0x30
> [ 4547.623766] }
> [ 4547.623767] ... key at: [<ffffffff850211b0>] __key.1+0x0/0x10
> [ 4547.623775] ... acquired at:
> [ 4547.623777] lock_acquire+0xb0/0x280
> [ 4547.623781] __flush_work+0x56/0x3f0
> [ 4547.623789] __cancel_work_timer+0xd3/0x160
> [ 4547.623796] fbcon_cursor+0x138/0x170
> [ 4547.623802] hide_cursor+0x26/0xc0
> [ 4547.623807] vt_console_print+0x41e/0x430
> [ 4547.623814] console_flush_all+0x206/0x4e0
> [ 4547.623820] console_unlock+0x33/0x110
> [ 4547.623825] vprintk_emit+0x9f/0x320
> [ 4547.623831] _printk+0x47/0x50
> [ 4547.623834] watchdog+0x53a/0x7b0
> [ 4547.623838] kthread+0xe3/0x120
> [ 4547.623841] ret_from_fork+0x2c/0x50
> [ 4547.623845] ret_from_fork_asm+0x1b/0x30
>
> [ 4547.623851]
> stack backtrace:
> [ 4547.623854] CPU: 2 PID: 39 Comm: khungtaskd Not tainted 6.8.0-rc6-lemon #190
> [ 4547.623860] Hardware name: LENOVO 80MK/VIUU4, BIOS C6CN29WW 09/02/2015
> [ 4547.623862] Call Trace:
> [ 4547.623865] <TASK>
> [ 4547.623867] dump_stack_lvl+0x4a/0x80
> [ 4547.623879] check_irq_usage+0x8aa/0xb10
> [ 4547.623886] ? check_path.constprop.0+0x24/0x50
> [ 4547.623896] ? check_noncircular+0x6d/0x120
> [ 4547.623902] ? __lock_acquire+0x146a/0x25c0
> [ 4547.623907] __lock_acquire+0x146a/0x25c0
> [ 4547.623913] lock_acquire+0xb0/0x280
> [ 4547.623918] ? __flush_work+0x4b/0x3f0
> [ 4547.623925] ? __flush_work+0x4b/0x3f0
> [ 4547.623932] __flush_work+0x56/0x3f0
> [ 4547.623939] ? __flush_work+0x4b/0x3f0
> [ 4547.623946] ? __lock_acquire+0x3ef/0x25c0
> [ 4547.623952] __cancel_work_timer+0xd3/0x160
> [ 4547.623960] fbcon_cursor+0x138/0x170
> [ 4547.623965] hide_cursor+0x26/0xc0
> [ 4547.623971] vt_console_print+0x41e/0x430
> [ 4547.623977] ? lock_release+0xb5/0x230
> [ 4547.623982] ? console_flush_all+0x1c9/0x4e0
> [ 4547.623988] console_flush_all+0x206/0x4e0
> [ 4547.623994] ? console_flush_all+0x1c9/0x4e0
> [ 4547.624001] console_unlock+0x33/0x110
> [ 4547.624007] vprintk_emit+0x9f/0x320
> [ 4547.624013] _printk+0x47/0x50
> [ 4547.624017] watchdog+0x53a/0x7b0
> [ 4547.624021] ? __pfx_watchdog+0x10/0x10
> [ 4547.624025] kthread+0xe3/0x120
> [ 4547.624029] ? __pfx_kthread+0x10/0x10
> [ 4547.624033] ret_from_fork+0x2c/0x50
> [ 4547.624037] ? __pfx_kthread+0x10/0x10
> [ 4547.624041] ret_from_fork_asm+0x1b/0x30
> [ 4547.624049] </TASK>
> [ 4548.028173] Not tainted 6.8.0-rc6-lemon #190
> [ 4548.029491] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 4548.031047] task:kworker/u9:1 state:D stack:0 pid:3528 tgid:3528 ppid:2 flags:0x00004000
> [ 4548.032620] Workqueue: hci0 hci_rx_work
> [ 4548.034099] Call Trace:
> [ 4548.035572] <TASK>
> [ 4548.036925] __schedule+0x427/0xd10
> [ 4548.038382] ? schedule+0xf7/0x140
> [ 4548.039822] schedule+0x45/0x140
> [ 4548.041201] __lock_sock+0x86/0xf0
> [ 4548.042601] ? __pfx_autoremove_wake_function+0x10/0x10
> [ 4548.044030] lock_sock_nested+0x61/0x70
> [ 4548.045390] l2cap_sock_recv_cb+0x21/0xa0
> [ 4548.046842] l2cap_recv_frame+0x5be/0x2e70
> [ 4548.048283] ? hci_rx_work+0x431/0x830
> [ 4548.049701] ? lock_release+0xb5/0x230
> [ 4548.051145] ? __mutex_unlock_slowpath+0x25/0x270
> [ 4548.052524] hci_rx_work+0x457/0x830
> [ 4548.053945] ? process_one_work+0x157/0x480
> [ 4548.055460] process_one_work+0x1ca/0x480
> [ 4548.056862] worker_thread+0x1be/0x3b0
> [ 4548.058281] ? __pfx_worker_thread+0x10/0x10
> [ 4548.059783] kthread+0xe3/0x120
> [ 4548.061141] ? __pfx_kthread+0x10/0x10
> [ 4548.062600] ret_from_fork+0x2c/0x50
> [ 4548.064064] ? __pfx_kthread+0x10/0x10
> [ 4548.065436] ret_from_fork_asm+0x1b/0x30
> [ 4548.066867] </TASK>
> [ 4548.068313] INFO: lockdep is turned off.
>
> # cat /proc/3526/stack
> [<0>] __skb_wait_for_more_packets+0xfa/0x150
> [<0>] __skb_recv_datagram+0x59/0xa0
> [<0>] skb_recv_datagram+0x29/0x40
> [<0>] bt_sock_recvmsg+0x42/0x1c0
> [<0>] l2cap_sock_recvmsg+0x5d/0x170
> [<0>] __sys_recvfrom+0x14e/0x160
> [<0>] __x64_sys_recvfrom+0x1f/0x30
> [<0>] do_syscall_64+0x75/0x150
> [<0>] entry_SYSCALL_64_after_hwframe+0x6e/0x76
>
> This is on my laptop with iwlwifi, but at first I saw it on my desktop
> with Ethernet (and Intel 9260 Bluetooth). I can get another lockdep
> capture if that would be helpful.
>
> Simon-
>
>
On Thu, Feb 29, 2024 at 09:40:42AM +0100, Thorsten Leemhuis wrote:
> [CCing the bluetooth maintainers]
>
> On 26.02.24 22:38, Simon Kirby wrote:
> >
> > I bisected a regression where reading from a Bluetooth device gets stuck
> > in recvfrom() calls. The device here is a Wii Balance Board, using
> > https://github.com/initialstate/beerfridge/blob/master/wiiboard_test.py;
> > this worked fine in v6.6.1 and v6.6.8, but when I tried on a v6.6.14
> > build, the script no longer outputs any readings.
> >
> > 1d576c3a5af850bf11fbd103f9ba11aa6d6061fb is the first bad commit
> >
> > which maps to upstream commit 2e07e8348ea454615e268222ae3fc240421be768:
>
> Could you please check if this problem only occurs with the latest 6.6.y
> versions, or also with mainline (6.8-rc8)? That's important to know, as
> that in the end determines who and how this needs to be is handled.
It occurs with 6.6.14, 6.6.18, and also with Linus head (805d849d7c3cc1).
The lockdep output below was from 6.8-rc6; the behaviour is the same.
Simon-
> Ciao, Thorsten
>
> > Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
> >
> > With this commit in place, as also in v6.7 and v6.7.6, the script does
> > not output anything _unless_ I strace the process, in which case a bunch
> > of recvmsg() syscalls are shown, and then it hangs again. If I ^C the
> > strace and run it a few times, eventually the script will get enough data
> > and output a reading.
> >
> > If I don't strace the script, a hung task warning appears:
> >
> > INFO: task kworker/u9:1:121 blocked for more than 30 seconds.
> > Not tainted 6.7.6-lemon #183
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > task:kworker/u9:1 state:D stack:0 pid:121 tgid:121 ppid:2 flags:0x00004000
> > Workqueue: hci0 hci_rx_work
> > Call Trace:
> > <TASK>
> > __schedule+0x37d/0xa00
> > schedule+0x32/0xe0
> > __lock_sock+0x68/0xa0
> > ? __pfx_autoremove_wake_function+0x10/0x10
> > lock_sock_nested+0x43/0x50
> > l2cap_sock_recv_cb+0x21/0xa0
> > l2cap_recv_frame+0x55b/0x30a0
> > ? psi_task_switch+0xeb/0x270
> > ? finish_task_switch.isra.0+0x93/0x2a0
> > hci_rx_work+0x33a/0x3f0
> > process_one_work+0x13a/0x2f0
> > worker_thread+0x2f0/0x410
> > ? __pfx_worker_thread+0x10/0x10
> > kthread+0xe0/0x110
> > ? __pfx_kthread+0x10/0x10
> > ret_from_fork+0x2c/0x50
> > ? __pfx_kthread+0x10/0x10
> > ret_from_fork_asm+0x1b/0x30
> > </TASK>
> >
> > On 6.8-rc6 with lockdep enabled, I get the following output:
> >
> > [ 22.122337] wlan0: associated
> > [ 4547.622339] INFO: task kworker/u9:1:3528 blocked for more than 30 seconds.
> >
> > [ 4547.622530] =====================================================
> > [ 4547.622531] WARNING: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected
> > [ 4547.622535] 6.8.0-rc6-lemon #190 Not tainted
> > [ 4547.622538] -----------------------------------------------------
> > [ 4547.622540] khungtaskd/39 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
> > [ 4547.622546] ffff888101554cf8 ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}, at: __flush_work+0x4b/0x3f0
> > [ 4547.622569]
> > and this task is already holding:
> > [ 4547.622571] ffffffff8367e600 (console_owner){....}-{0:0}, at: console_flush_all+0x1c9/0x4e0
> > [ 4547.622586] which would create a new lock dependency:
> > [ 4547.622587] (console_owner){....}-{0:0} -> ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}
> > [ 4547.622596]
> > but this new dependency connects a SOFTIRQ-irq-safe lock:
> > [ 4547.622598] (&trans_pcie->irq_lock){+.-.}-{3:3}
> > [ 4547.622601]
> > ... which became SOFTIRQ-irq-safe at:
> > [ 4547.622603] lock_acquire+0xb0/0x280
> > [ 4547.622611] _raw_spin_lock+0x2b/0x40
> > [ 4547.622618] iwl_pcie_napi_poll+0x7a/0x130
> > [ 4547.622627] __napi_poll.constprop.0+0x23/0x1e0
> > [ 4547.622634] net_rx_action+0x137/0x2a0
> > [ 4547.622639] __do_softirq+0xc7/0x402
> > [ 4547.622645] do_softirq+0x42/0xa0
> > [ 4547.622651] __local_bh_enable_ip+0xb8/0xd0
> > [ 4547.622657] iwl_pcie_irq_handler+0x539/0xb70
> > [ 4547.622665] irq_thread_fn+0x1b/0x60
> > [ 4547.622670] irq_thread+0xe0/0x190
> > [ 4547.622675] kthread+0xe3/0x120
> > [ 4547.622679] ret_from_fork+0x2c/0x50
> > [ 4547.622684] ret_from_fork_asm+0x1b/0x30
> > [ 4547.622692]
> > to a SOFTIRQ-irq-unsafe lock:
> > [ 4547.622694] ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0}
> > [ 4547.622698]
> > ... which became SOFTIRQ-irq-unsafe at:
> > [ 4547.622699] ...
> > [ 4547.622700] lock_acquire+0xb0/0x280
> > [ 4547.622706] process_one_work+0x199/0x480
> > [ 4547.622713] worker_thread+0x1be/0x3b0
> > [ 4547.622719] kthread+0xe3/0x120
> > [ 4547.622722] ret_from_fork+0x2c/0x50
> > [ 4547.622725] ret_from_fork_asm+0x1b/0x30
> > [ 4547.622731]
> > other info that might help us debug this:
> >
> > [ 4547.622732] Chain exists of:
> > &trans_pcie->irq_lock --> console_owner --> (work_completion)(&(&ops->cursor_work)->work)
> >
> > [ 4547.622739] Possible interrupt unsafe locking scenario:
> >
> > [ 4547.622741] CPU0 CPU1
> > [ 4547.622742] ---- ----
> > [ 4547.622742] lock((work_completion)(&(&ops->cursor_work)->work));
> > [ 4547.622745] local_irq_disable();
> > [ 4547.622746] lock(&trans_pcie->irq_lock);
> > [ 4547.622749] lock(console_owner);
> > [ 4547.622751] <Interrupt>
> > [ 4547.622752] lock(&trans_pcie->irq_lock);
> > [ 4547.622754]
> > *** DEADLOCK ***
> >
> > [ 4547.622755] 5 locks held by khungtaskd/39:
> > [ 4547.622759] #0: ffffffff836f14e0 (rcu_read_lock){....}-{1:3}, at: watchdog+0xd8/0x7b0
> > [ 4547.622778] #1: ffffffff836ee820 (console_lock){+.+.}-{0:0}, at: _printk+0x47/0x50
> > [ 4547.622789] #2: ffffffff836ee870 (console_srcu){....}-{0:0}, at: console_flush_all+0x74/0x4e0
> > [ 4547.622800] #3: ffffffff8367e600 (console_owner){....}-{0:0}, at: console_flush_all+0x1c9/0x4e0
> > [ 4547.622810] #4: ffffffff837d8758 (printing_lock){....}-{3:3}, at: vt_console_print+0x47/0x430
> > [ 4547.622822]
> > the dependencies between SOFTIRQ-irq-safe lock and the holding lock:
> > [ 4547.622824] -> (&trans_pcie->irq_lock){+.-.}-{3:3} {
> > [ 4547.622830] HARDIRQ-ON-W at:
> > [ 4547.622833] lock_acquire+0xb0/0x280
> > [ 4547.622839] _raw_spin_lock_bh+0x33/0x40
> > [ 4547.622845] iwl_trans_pcie_alloc+0x2fd/0x990
> > [ 4547.622853] iwl_pci_probe+0x28/0x810
> > [ 4547.622859] pci_device_probe+0x94/0x120
> > [ 4547.622865] really_probe+0x15e/0x2f0
> > [ 4547.622872] __driver_probe_device+0x6e/0x110
> > [ 4547.622878] driver_probe_device+0x1a/0xe0
> > [ 4547.622884] __driver_attach+0x87/0x190
> > [ 4547.622890] bus_for_each_dev+0x66/0xb0
> > [ 4547.622894] bus_add_driver+0xea/0x1f0
> > [ 4547.622898] driver_register+0x54/0x100
> > [ 4547.622905] iwl_pci_register_driver+0x1a/0x40
> > [ 4547.622911] do_one_initcall+0x50/0x250
> > [ 4547.622918] kernel_init_freeable+0x243/0x3e0
> > [ 4547.622927] kernel_init+0x15/0x1a0
> > [ 4547.622931] ret_from_fork+0x2c/0x50
> > [ 4547.622935] ret_from_fork_asm+0x1b/0x30
> > [ 4547.622941] IN-SOFTIRQ-W at:
> > [ 4547.622943] lock_acquire+0xb0/0x280
> > [ 4547.622948] _raw_spin_lock+0x2b/0x40
> > [ 4547.622953] iwl_pcie_napi_poll+0x7a/0x130
> > [ 4547.622961] __napi_poll.constprop.0+0x23/0x1e0
> > [ 4547.622966] net_rx_action+0x137/0x2a0
> > [ 4547.622971] __do_softirq+0xc7/0x402
> > [ 4547.622978] do_softirq+0x42/0xa0
> > [ 4547.622983] __local_bh_enable_ip+0xb8/0xd0
> > [ 4547.622989] iwl_pcie_irq_handler+0x539/0xb70
> > [ 4547.622996] irq_thread_fn+0x1b/0x60
> > [ 4547.623002] irq_thread+0xe0/0x190
> > [ 4547.623006] kthread+0xe3/0x120
> > [ 4547.623011] ret_from_fork+0x2c/0x50
> > [ 4547.623014] ret_from_fork_asm+0x1b/0x30
> > [ 4547.623020] INITIAL USE at:
> > [ 4547.623022] lock_acquire+0xb0/0x280
> > [ 4547.623027] _raw_spin_lock_bh+0x33/0x40
> > [ 4547.623032] iwl_trans_pcie_alloc+0x2fd/0x990
> > [ 4547.623038] iwl_pci_probe+0x28/0x810
> > [ 4547.623043] pci_device_probe+0x94/0x120
> > [ 4547.623047] really_probe+0x15e/0x2f0
> > [ 4547.623053] __driver_probe_device+0x6e/0x110
> > [ 4547.623059] driver_probe_device+0x1a/0xe0
> > [ 4547.623064] __driver_attach+0x87/0x190
> > [ 4547.623070] bus_for_each_dev+0x66/0xb0
> > [ 4547.623073] bus_add_driver+0xea/0x1f0
> > [ 4547.623077] driver_register+0x54/0x100
> > [ 4547.623084] iwl_pci_register_driver+0x1a/0x40
> > [ 4547.623090] do_one_initcall+0x50/0x250
> > [ 4547.623096] kernel_init_freeable+0x243/0x3e0
> > [ 4547.623103] kernel_init+0x15/0x1a0
> > [ 4547.623107] ret_from_fork+0x2c/0x50
> > [ 4547.623110] ret_from_fork_asm+0x1b/0x30
> > [ 4547.623116] }
> > [ 4547.623118] ... key at: [<ffffffff8502fe90>] __key.20+0x0/0x10
> > [ 4547.623129] -> (&trans_pcie->reg_lock){+...}-{3:3} {
> > [ 4547.623134] HARDIRQ-ON-W at:
> > [ 4547.623137] lock_acquire+0xb0/0x280
> > [ 4547.623142] _raw_spin_lock_bh+0x33/0x40
> > [ 4547.623147] iwl_trans_pcie_set_bits_mask+0x25/0x60
> > [ 4547.623151] iwl_pcie_set_hw_ready+0x1e/0xa0
> > [ 4547.623160] iwl_pcie_prepare_card_hw+0x33/0x100
> > [ 4547.623165] iwl_pci_probe+0x42/0x810
> > [ 4547.623171] pci_device_probe+0x94/0x120
> > [ 4547.623175] really_probe+0x15e/0x2f0
> > [ 4547.623181] __driver_probe_device+0x6e/0x110
> > [ 4547.623186] driver_probe_device+0x1a/0xe0
> > [ 4547.623192] __driver_attach+0x87/0x190
> > [ 4547.623197] bus_for_each_dev+0x66/0xb0
> > [ 4547.623201] bus_add_driver+0xea/0x1f0
> > [ 4547.623205] driver_register+0x54/0x100
> > [ 4547.623211] iwl_pci_register_driver+0x1a/0x40
> > [ 4547.623217] do_one_initcall+0x50/0x250
> > [ 4547.623223] kernel_init_freeable+0x243/0x3e0
> > [ 4547.623229] kernel_init+0x15/0x1a0
> > [ 4547.623233] ret_from_fork+0x2c/0x50
> > [ 4547.623236] ret_from_fork_asm+0x1b/0x30
> > [ 4547.623242] INITIAL USE at:
> > [ 4547.623244] lock_acquire+0xb0/0x280
> > [ 4547.623249] _raw_spin_lock_bh+0x33/0x40
> > [ 4547.623254] iwl_trans_pcie_set_bits_mask+0x25/0x60
> > [ 4547.623257] iwl_pcie_set_hw_ready+0x1e/0xa0
> > [ 4547.623266] iwl_pcie_prepare_card_hw+0x33/0x100
> > [ 4547.623271] iwl_pci_probe+0x42/0x810
> > [ 4547.623277] pci_device_probe+0x94/0x120
> > [ 4547.623281] really_probe+0x15e/0x2f0
> > [ 4547.623286] __driver_probe_device+0x6e/0x110
> > [ 4547.623292] driver_probe_device+0x1a/0xe0
> > [ 4547.623297] __driver_attach+0x87/0x190
> > [ 4547.623303] bus_for_each_dev+0x66/0xb0
> > [ 4547.623306] bus_add_driver+0xea/0x1f0
> > [ 4547.623310] driver_register+0x54/0x100
> > [ 4547.623316] iwl_pci_register_driver+0x1a/0x40
> > [ 4547.623323] do_one_initcall+0x50/0x250
> > [ 4547.623328] kernel_init_freeable+0x243/0x3e0
> > [ 4547.623334] kernel_init+0x15/0x1a0
> > [ 4547.623338] ret_from_fork+0x2c/0x50
> > [ 4547.623342] ret_from_fork_asm+0x1b/0x30
> > [ 4547.623347] }
> > [ 4547.623348] ... key at: [<ffffffff8502fe80>] __key.19+0x0/0x10
> > [ 4547.623358] ... acquired at:
> > [ 4547.623359] _raw_spin_lock_bh+0x33/0x40
> > [ 4547.623364] iwl_trans_pcie_set_bits_mask+0x25/0x60
> > [ 4547.623368] iwl_pcie_apm_init+0x6e/0x1c0
> > [ 4547.623372] iwl_trans_pcie_start_fw+0x224/0x670
> > [ 4547.623377] iwl_mvm_load_ucode_wait_alive+0xd3/0x5a0
> > [ 4547.623383] iwl_run_init_mvm_ucode+0x8c/0x3a0
> > [ 4547.623387] iwl_mvm_start_get_nvm+0x87/0x210
> > [ 4547.623393] iwl_op_mode_mvm_start+0x962/0xb30
> > [ 4547.623399] _iwl_op_mode_start.isra.0+0x72/0xb0
> > [ 4547.623403] iwl_opmode_register+0x6a/0xe0
> > [ 4547.623408] iwl_mvm_init+0x21/0x60
> > [ 4547.623413] do_one_initcall+0x50/0x250
> > [ 4547.623419] kernel_init_freeable+0x243/0x3e0
> > [ 4547.623425] kernel_init+0x15/0x1a0
> > [ 4547.623429] ret_from_fork+0x2c/0x50
> > [ 4547.623432] ret_from_fork_asm+0x1b/0x30
> >
> > [ 4547.623441] -> (console_owner){....}-{0:0} {
> > [ 4547.623446] INITIAL USE at:
> > [ 4547.623452] lock_acquire+0xb0/0x280
> > [ 4547.623457] console_flush_all+0x1f2/0x4e0
> > [ 4547.623463] console_unlock+0x33/0x110
> > [ 4547.623469] vprintk_emit+0x9f/0x320
> > [ 4547.623475] _printk+0x47/0x50
> > [ 4547.623479] register_console+0x34b/0x4d0
> > [ 4547.623485] con_init+0x200/0x270
> > [ 4547.623494] console_init+0x4a/0x1e0
> > [ 4547.623504] start_kernel+0x2b9/0x660
> > [ 4547.623510] x86_64_start_reservations+0x18/0x30
> > [ 4547.623517] x86_64_start_kernel+0xad/0xc0
> > [ 4547.623522] secondary_startup_64_no_verify+0x170/0x17b
> > [ 4547.623528] }
> > [ 4547.623529] ... key at: [<ffffffff8367e600>] console_owner_dep_map+0x0/0x28
> > [ 4547.623538] ... acquired at:
> > [ 4547.623540] console_flush_all+0x1f2/0x4e0
> > [ 4547.623545] console_unlock+0x33/0x110
> > [ 4547.623551] vprintk_emit+0x9f/0x320
> > [ 4547.623557] dev_vprintk_emit+0xce/0x160
> > [ 4547.623562] dev_printk_emit+0x3d/0x50
> > [ 4547.623566] _dev_info+0x5b/0x70
> > [ 4547.623572] __iwl_info+0x58/0x60
> > [ 4547.623576] iwl_pci_probe+0x11c/0x810
> > [ 4547.623582] pci_device_probe+0x94/0x120
> > [ 4547.623587] really_probe+0x15e/0x2f0
> > [ 4547.623592] __driver_probe_device+0x6e/0x110
> > [ 4547.623598] driver_probe_device+0x1a/0xe0
> > [ 4547.623603] __driver_attach+0x87/0x190
> > [ 4547.623609] bus_for_each_dev+0x66/0xb0
> > [ 4547.623612] bus_add_driver+0xea/0x1f0
> > [ 4547.623616] driver_register+0x54/0x100
> > [ 4547.623622] iwl_pci_register_driver+0x1a/0x40
> > [ 4547.623629] do_one_initcall+0x50/0x250
> > [ 4547.623634] kernel_init_freeable+0x243/0x3e0
> > [ 4547.623640] kernel_init+0x15/0x1a0
> > [ 4547.623644] ret_from_fork+0x2c/0x50
> > [ 4547.623648] ret_from_fork_asm+0x1b/0x30
> >
> > [ 4547.623654]
> > the dependencies between the lock to be acquired
> > [ 4547.623655] and SOFTIRQ-irq-unsafe lock:
> > [ 4547.623665] -> ((work_completion)(&(&ops->cursor_work)->work)){+.+.}-{0:0} {
> > [ 4547.623670] HARDIRQ-ON-W at:
> > [ 4547.623672] lock_acquire+0xb0/0x280
> > [ 4547.623677] process_one_work+0x199/0x480
> > [ 4547.623684] worker_thread+0x1be/0x3b0
> > [ 4547.623690] kthread+0xe3/0x120
> > [ 4547.623694] ret_from_fork+0x2c/0x50
> > [ 4547.623698] ret_from_fork_asm+0x1b/0x30
> > [ 4547.623704] SOFTIRQ-ON-W at:
> > [ 4547.623705] lock_acquire+0xb0/0x280
> > [ 4547.623710] process_one_work+0x199/0x480
> > [ 4547.623716] worker_thread+0x1be/0x3b0
> > [ 4547.623722] kthread+0xe3/0x120
> > [ 4547.623725] ret_from_fork+0x2c/0x50
> > [ 4547.623729] ret_from_fork_asm+0x1b/0x30
> > [ 4547.623734] INITIAL USE at:
> > [ 4547.623736] lock_acquire+0xb0/0x280
> > [ 4547.623741] process_one_work+0x199/0x480
> > [ 4547.623747] worker_thread+0x1be/0x3b0
> > [ 4547.623753] kthread+0xe3/0x120
> > [ 4547.623757] ret_from_fork+0x2c/0x50
> > [ 4547.623760] ret_from_fork_asm+0x1b/0x30
> > [ 4547.623766] }
> > [ 4547.623767] ... key at: [<ffffffff850211b0>] __key.1+0x0/0x10
> > [ 4547.623775] ... acquired at:
> > [ 4547.623777] lock_acquire+0xb0/0x280
> > [ 4547.623781] __flush_work+0x56/0x3f0
> > [ 4547.623789] __cancel_work_timer+0xd3/0x160
> > [ 4547.623796] fbcon_cursor+0x138/0x170
> > [ 4547.623802] hide_cursor+0x26/0xc0
> > [ 4547.623807] vt_console_print+0x41e/0x430
> > [ 4547.623814] console_flush_all+0x206/0x4e0
> > [ 4547.623820] console_unlock+0x33/0x110
> > [ 4547.623825] vprintk_emit+0x9f/0x320
> > [ 4547.623831] _printk+0x47/0x50
> > [ 4547.623834] watchdog+0x53a/0x7b0
> > [ 4547.623838] kthread+0xe3/0x120
> > [ 4547.623841] ret_from_fork+0x2c/0x50
> > [ 4547.623845] ret_from_fork_asm+0x1b/0x30
> >
> > [ 4547.623851]
> > stack backtrace:
> > [ 4547.623854] CPU: 2 PID: 39 Comm: khungtaskd Not tainted 6.8.0-rc6-lemon #190
> > [ 4547.623860] Hardware name: LENOVO 80MK/VIUU4, BIOS C6CN29WW 09/02/2015
> > [ 4547.623862] Call Trace:
> > [ 4547.623865] <TASK>
> > [ 4547.623867] dump_stack_lvl+0x4a/0x80
> > [ 4547.623879] check_irq_usage+0x8aa/0xb10
> > [ 4547.623886] ? check_path.constprop.0+0x24/0x50
> > [ 4547.623896] ? check_noncircular+0x6d/0x120
> > [ 4547.623902] ? __lock_acquire+0x146a/0x25c0
> > [ 4547.623907] __lock_acquire+0x146a/0x25c0
> > [ 4547.623913] lock_acquire+0xb0/0x280
> > [ 4547.623918] ? __flush_work+0x4b/0x3f0
> > [ 4547.623925] ? __flush_work+0x4b/0x3f0
> > [ 4547.623932] __flush_work+0x56/0x3f0
> > [ 4547.623939] ? __flush_work+0x4b/0x3f0
> > [ 4547.623946] ? __lock_acquire+0x3ef/0x25c0
> > [ 4547.623952] __cancel_work_timer+0xd3/0x160
> > [ 4547.623960] fbcon_cursor+0x138/0x170
> > [ 4547.623965] hide_cursor+0x26/0xc0
> > [ 4547.623971] vt_console_print+0x41e/0x430
> > [ 4547.623977] ? lock_release+0xb5/0x230
> > [ 4547.623982] ? console_flush_all+0x1c9/0x4e0
> > [ 4547.623988] console_flush_all+0x206/0x4e0
> > [ 4547.623994] ? console_flush_all+0x1c9/0x4e0
> > [ 4547.624001] console_unlock+0x33/0x110
> > [ 4547.624007] vprintk_emit+0x9f/0x320
> > [ 4547.624013] _printk+0x47/0x50
> > [ 4547.624017] watchdog+0x53a/0x7b0
> > [ 4547.624021] ? __pfx_watchdog+0x10/0x10
> > [ 4547.624025] kthread+0xe3/0x120
> > [ 4547.624029] ? __pfx_kthread+0x10/0x10
> > [ 4547.624033] ret_from_fork+0x2c/0x50
> > [ 4547.624037] ? __pfx_kthread+0x10/0x10
> > [ 4547.624041] ret_from_fork_asm+0x1b/0x30
> > [ 4547.624049] </TASK>
> > [ 4548.028173] Not tainted 6.8.0-rc6-lemon #190
> > [ 4548.029491] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > [ 4548.031047] task:kworker/u9:1 state:D stack:0 pid:3528 tgid:3528 ppid:2 flags:0x00004000
> > [ 4548.032620] Workqueue: hci0 hci_rx_work
> > [ 4548.034099] Call Trace:
> > [ 4548.035572] <TASK>
> > [ 4548.036925] __schedule+0x427/0xd10
> > [ 4548.038382] ? schedule+0xf7/0x140
> > [ 4548.039822] schedule+0x45/0x140
> > [ 4548.041201] __lock_sock+0x86/0xf0
> > [ 4548.042601] ? __pfx_autoremove_wake_function+0x10/0x10
> > [ 4548.044030] lock_sock_nested+0x61/0x70
> > [ 4548.045390] l2cap_sock_recv_cb+0x21/0xa0
> > [ 4548.046842] l2cap_recv_frame+0x5be/0x2e70
> > [ 4548.048283] ? hci_rx_work+0x431/0x830
> > [ 4548.049701] ? lock_release+0xb5/0x230
> > [ 4548.051145] ? __mutex_unlock_slowpath+0x25/0x270
> > [ 4548.052524] hci_rx_work+0x457/0x830
> > [ 4548.053945] ? process_one_work+0x157/0x480
> > [ 4548.055460] process_one_work+0x1ca/0x480
> > [ 4548.056862] worker_thread+0x1be/0x3b0
> > [ 4548.058281] ? __pfx_worker_thread+0x10/0x10
> > [ 4548.059783] kthread+0xe3/0x120
> > [ 4548.061141] ? __pfx_kthread+0x10/0x10
> > [ 4548.062600] ret_from_fork+0x2c/0x50
> > [ 4548.064064] ? __pfx_kthread+0x10/0x10
> > [ 4548.065436] ret_from_fork_asm+0x1b/0x30
> > [ 4548.066867] </TASK>
> > [ 4548.068313] INFO: lockdep is turned off.
> >
> > # cat /proc/3526/stack
> > [<0>] __skb_wait_for_more_packets+0xfa/0x150
> > [<0>] __skb_recv_datagram+0x59/0xa0
> > [<0>] skb_recv_datagram+0x29/0x40
> > [<0>] bt_sock_recvmsg+0x42/0x1c0
> > [<0>] l2cap_sock_recvmsg+0x5d/0x170
> > [<0>] __sys_recvfrom+0x14e/0x160
> > [<0>] __x64_sys_recvfrom+0x1f/0x30
> > [<0>] do_syscall_64+0x75/0x150
> > [<0>] entry_SYSCALL_64_after_hwframe+0x6e/0x76
> >
> > This is on my laptop with iwlwifi, but at first I saw it on my desktop
> > with Ethernet (and Intel 9260 Bluetooth). I can get another lockdep
> > capture if that would be helpful.
> >
> > Simon-
On 26.02.24 22:38, Simon Kirby wrote:
>
> I bisected a regression where reading from a Bluetooth device gets stuck
> in recvfrom() calls. The device here is a Wii Balance Board, using
> https://github.com/initialstate/beerfridge/blob/master/wiiboard_test.py;
> this worked fine in v6.6.1 and v6.6.8, but when I tried on a v6.6.14
> build, the script no longer outputs any readings.
>
> 1d576c3a5af850bf11fbd103f9ba11aa6d6061fb is the first bad commit
>
> which maps to upstream commit 2e07e8348ea454615e268222ae3fc240421be768:
>
> Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
>
> With this commit in place, as also in v6.7 and v6.7.6, the script does
> not output anything _unless_ I strace the process, in which case a bunch
> of recvmsg() syscalls are shown, and then it hangs again. If I ^C the
> strace and run it a few times, eventually the script will get enough data
> and output a reading.
Thanks for the report. To be sure the issue doesn't fall through the
cracks unnoticed, I'm adding it to regzbot, the Linux kernel regression
tracking bot:
#regzbot ^introduced 2e07e8348ea454
#regzbot title af_bluetooth: reading from a device gets stuck in
recvfrom() calls
#regzbot ignore-activity
Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)
--
Everything you wanna know about Linux kernel regression tracking:
https://linux-regtracking.leemhuis.info/about/#tldr
That page also explains what to do if mails like this annoy you.