* [PATCH] Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
@ 2023-12-04 7:02 Hyunwoo Kim
2023-12-04 7:32 ` bluez.test.bot
2023-12-06 14:48 ` [PATCH] " Luiz Augusto von Dentz
0 siblings, 2 replies; 7+ messages in thread
From: Hyunwoo Kim @ 2023-12-04 7:02 UTC (permalink / raw)
To: marcel; +Cc: v4bel, imv4bel, johan.hedberg, luiz.dentz, linux-bluetooth
This can cause a race with bt_sock_ioctl() because
bt_sock_recvmsg() gets the skb from sk->sk_receive_queue
and then frees it without holding lock_sock.
A use-after-free for a skb occurs with the following flow.
```
bt_sock_recvmsg() -> skb_recv_datagram() -> skb_free_datagram()
bt_sock_ioctl() -> skb_peek()
```
Add lock_sock to bt_sock_recvmsg() to fix this issue.
Signed-off-by: Hyunwoo Kim <v4bel@theori.io>
---
net/bluetooth/af_bluetooth.c | 9 ++++++++-
1 file changed, 8 insertions(+), 1 deletion(-)
diff --git a/net/bluetooth/af_bluetooth.c b/net/bluetooth/af_bluetooth.c
index 336a76165454..9def13ac816e 100644
--- a/net/bluetooth/af_bluetooth.c
+++ b/net/bluetooth/af_bluetooth.c
@@ -309,11 +309,16 @@ int bt_sock_recvmsg(struct socket *sock, struct msghdr *msg, size_t len,
if (flags & MSG_OOB)
return -EOPNOTSUPP;
+ lock_sock(sk);
+
skb = skb_recv_datagram(sk, flags, &err);
if (!skb) {
- if (sk->sk_shutdown & RCV_SHUTDOWN)
+ if (sk->sk_shutdown & RCV_SHUTDOWN) {
+ release_sock(sk);
return 0;
+ }
+ release_sock(sk);
return err;
}
@@ -343,6 +348,8 @@ int bt_sock_recvmsg(struct socket *sock, struct msghdr *msg, size_t len,
skb_free_datagram(sk, skb);
+ release_sock(sk);
+
if (flags & MSG_TRUNC)
copied = skblen;
--
2.25.1
^ permalink raw reply related [flat|nested] 7+ messages in thread
* RE: Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
2023-12-04 7:02 [PATCH] Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg Hyunwoo Kim
@ 2023-12-04 7:32 ` bluez.test.bot
2023-12-06 14:48 ` [PATCH] " Luiz Augusto von Dentz
1 sibling, 0 replies; 7+ messages in thread
From: bluez.test.bot @ 2023-12-04 7:32 UTC (permalink / raw)
To: linux-bluetooth, v4bel
[-- Attachment #1: Type: text/plain, Size: 1668 bytes --]
This is automated email and please do not reply to this email!
Dear submitter,
Thank you for submitting the patches to the linux bluetooth mailing list.
This is a CI test results with your patch series:
PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=806468
---Test result---
Test Summary:
CheckPatch PASS 0.48 seconds
GitLint PASS 0.22 seconds
SubjectPrefix PASS 0.07 seconds
BuildKernel PASS 28.01 seconds
CheckAllWarning PASS 31.13 seconds
CheckSparse WARNING 36.27 seconds
CheckSmatch PASS 100.31 seconds
BuildKernel32 PASS 27.37 seconds
TestRunnerSetup PASS 423.62 seconds
TestRunner_l2cap-tester PASS 23.57 seconds
TestRunner_iso-tester PASS 46.96 seconds
TestRunner_bnep-tester PASS 6.88 seconds
TestRunner_mgmt-tester PASS 164.14 seconds
TestRunner_rfcomm-tester PASS 11.08 seconds
TestRunner_sco-tester PASS 14.63 seconds
TestRunner_ioctl-tester PASS 12.31 seconds
TestRunner_mesh-tester PASS 9.04 seconds
TestRunner_smp-tester PASS 10.05 seconds
TestRunner_userchan-tester PASS 7.49 seconds
IncrementalBuild PASS 26.74 seconds
Details
##############################
Test: CheckSparse - WARNING
Desc: Run sparse tool with linux kernel
Output:
net/bluetooth/af_bluetooth.c:223:25: warning: context imbalance in 'bt_accept_enqueue' - different lock contexts for basic block
---
Regards,
Linux Bluetooth
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH] Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
2023-12-04 7:02 [PATCH] Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg Hyunwoo Kim
2023-12-04 7:32 ` bluez.test.bot
@ 2023-12-06 14:48 ` Luiz Augusto von Dentz
1 sibling, 0 replies; 7+ messages in thread
From: Luiz Augusto von Dentz @ 2023-12-06 14:48 UTC (permalink / raw)
To: Hyunwoo Kim; +Cc: marcel, imv4bel, johan.hedberg, linux-bluetooth
Hi Kim,
On Mon, Dec 4, 2023 at 2:02 AM Hyunwoo Kim <v4bel@theori.io> wrote:
>
> This can cause a race with bt_sock_ioctl() because
> bt_sock_recvmsg() gets the skb from sk->sk_receive_queue
> and then frees it without holding lock_sock.
> A use-after-free for a skb occurs with the following flow.
> ```
> bt_sock_recvmsg() -> skb_recv_datagram() -> skb_free_datagram()
> bt_sock_ioctl() -> skb_peek()
> ```
> Add lock_sock to bt_sock_recvmsg() to fix this issue.
>
> Signed-off-by: Hyunwoo Kim <v4bel@theori.io>
> ---
> net/bluetooth/af_bluetooth.c | 9 ++++++++-
> 1 file changed, 8 insertions(+), 1 deletion(-)
>
> diff --git a/net/bluetooth/af_bluetooth.c b/net/bluetooth/af_bluetooth.c
> index 336a76165454..9def13ac816e 100644
> --- a/net/bluetooth/af_bluetooth.c
> +++ b/net/bluetooth/af_bluetooth.c
> @@ -309,11 +309,16 @@ int bt_sock_recvmsg(struct socket *sock, struct msghdr *msg, size_t len,
> if (flags & MSG_OOB)
> return -EOPNOTSUPP;
>
> + lock_sock(sk);
> +
> skb = skb_recv_datagram(sk, flags, &err);
> if (!skb) {
> - if (sk->sk_shutdown & RCV_SHUTDOWN)
> + if (sk->sk_shutdown & RCV_SHUTDOWN) {
> + release_sock(sk);
We could just reset the with err = 0 then we don't need to duplicate
the release_sock line.
> return 0;
> + }
>
> + release_sock(sk);
> return err;
> }
>
> @@ -343,6 +348,8 @@ int bt_sock_recvmsg(struct socket *sock, struct msghdr *msg, size_t len,
>
> skb_free_datagram(sk, skb);
>
> + release_sock(sk);
> +
> if (flags & MSG_TRUNC)
> copied = skblen;
>
> --
> 2.25.1
>
--
Luiz Augusto von Dentz
^ permalink raw reply [flat|nested] 7+ messages in thread
* RE: Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
@ 2024-02-26 21:38 Simon Kirby
2024-02-29 8:40 ` Thorsten Leemhuis
2024-03-01 5:53 ` Linux regression tracking #adding (Thorsten Leemhuis)
0 siblings, 2 replies; 7+ messages in thread
From: Simon Kirby @ 2024-02-26 21:38 UTC (permalink / raw)
To: linux-bluetooth, Hyunwoo Kim; +Cc: stable, regressions
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-
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
2024-02-26 21:38 Simon Kirby
@ 2024-02-29 8:40 ` Thorsten Leemhuis
2024-02-29 17:49 ` Simon Kirby
2024-03-01 5:53 ` Linux regression tracking #adding (Thorsten Leemhuis)
1 sibling, 1 reply; 7+ messages in thread
From: Thorsten Leemhuis @ 2024-02-29 8:40 UTC (permalink / raw)
To: Simon Kirby, linux-bluetooth, Hyunwoo Kim
Cc: stable, regressions, Luiz Augusto von Dentz, Johan Hedberg,
Marcel Holtmann
[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-
>
>
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
2024-02-29 8:40 ` Thorsten Leemhuis
@ 2024-02-29 17:49 ` Simon Kirby
0 siblings, 0 replies; 7+ messages in thread
From: Simon Kirby @ 2024-02-29 17:49 UTC (permalink / raw)
To: Thorsten Leemhuis
Cc: linux-bluetooth, Hyunwoo Kim, stable, regressions,
Luiz Augusto von Dentz, Johan Hedberg, Marcel Holtmann
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-
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg
2024-02-26 21:38 Simon Kirby
2024-02-29 8:40 ` Thorsten Leemhuis
@ 2024-03-01 5:53 ` Linux regression tracking #adding (Thorsten Leemhuis)
1 sibling, 0 replies; 7+ messages in thread
From: Linux regression tracking #adding (Thorsten Leemhuis) @ 2024-03-01 5:53 UTC (permalink / raw)
To: linux-bluetooth; +Cc: stable, regressions
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.
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2024-03-01 5:53 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2023-12-04 7:02 [PATCH] Bluetooth: af_bluetooth: Fix Use-After-Free in bt_sock_recvmsg Hyunwoo Kim
2023-12-04 7:32 ` bluez.test.bot
2023-12-06 14:48 ` [PATCH] " Luiz Augusto von Dentz
-- strict thread matches above, loose matches on Subject: below --
2024-02-26 21:38 Simon Kirby
2024-02-29 8:40 ` Thorsten Leemhuis
2024-02-29 17:49 ` Simon Kirby
2024-03-01 5:53 ` Linux regression tracking #adding (Thorsten Leemhuis)
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).