2022-01-03 22:02:33

by Soenke Huster

[permalink] [raw]
Subject: [BUG] Page Fault in hci_inquiry_result_with_rssi_evt

Hello,

While fuzzing bluetooth-next I found the following bug:

[ 27.333034] BUG: unable to handle page fault for address: fffff61a1a1a1a1a
[ 27.333241] #PF: supervisor read access in kernel mode
[ 27.333241] #PF: error_code(0x0000) - not-present page
[ 27.333241] PGD 6dfd2067 P4D 6dfd2067 PUD 0
[ 27.333241] Oops: 0000 [#1] PREEMPT SMP KASAN NOPTI
[ 27.333241] CPU: 0 PID: 45 Comm: kworker/u3:2 Not tainted 5.16.0-rc1+ #81
[ 27.333241] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
[ 27.333241] Workqueue: hci0 hci_rx_work
[ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
[ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
[ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
[ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
[ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
[ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
[ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
[ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
[ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
[ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
[ 27.333241] Call Trace:
[ 27.333241] <TASK>
[ 27.333241] ? wait_for_completion_io+0x270/0x270
[ 27.333241] ? hci_inquiry_result_evt+0x4b0/0x4b0
[ 27.333241] hci_event_packet+0x3b11/0x7b10
[ 27.333241] ? lock_chain_count+0x20/0x20
[ 27.333241] ? hci_cmd_status_evt.constprop.0+0x4ea0/0x4ea0
[ 27.333241] ? sysvec_reboot+0x50/0xc0
[ 27.333241] ? find_held_lock+0x2c/0x110
[ 27.333241] ? lock_release+0x3b2/0x6f0
[ 27.333241] ? skb_dequeue+0x110/0x1a0
[ 27.333241] ? mark_held_locks+0x9e/0xe0
[ 27.333241] ? lockdep_hardirqs_on_prepare+0x17b/0x400
[ 27.333241] hci_rx_work+0x4d3/0xb90
[ 27.333241] process_one_work+0x904/0x1590
[ 27.333241] ? lock_release+0x6f0/0x6f0
[ 27.333241] ? pwq_dec_nr_in_flight+0x230/0x230
[ 27.333241] ? rwlock_bug.part.0+0x90/0x90
[ 27.333241] ? _raw_spin_lock_irq+0x41/0x50
[ 27.333241] worker_thread+0x578/0x1310
[ 27.333241] ? process_one_work+0x1590/0x1590
[ 27.333241] kthread+0x3b2/0x490
[ 27.333241] ? _raw_spin_unlock_irq+0x1f/0x40
[ 27.333241] ? set_kthread_struct+0x100/0x100
[ 27.333241] ret_from_fork+0x22/0x30
[ 27.333241] </TASK>
[ 27.333241] Modules linked in:
[ 27.333241] CR2: fffff61a1a1a1a1a
[ 27.333241] ---[ end trace 6a6825484c8fefa6 ]---
[ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
[ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
[ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
[ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
[ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
[ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
[ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
[ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
[ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
[ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
[ 27.379996] kworker/u3:2 (45) used greatest stack depth: 27736 bytes left

It occurs when sending the following frame to the kernel:

$ xxd crashes/hci_inquiry_result_with_rssi_evt
00000000: 0422 24d0 d0d0 d0d0 d0ff ff ."$........

The bug was introduced with the commit "Bluetooth: HCI: Use skb_pull_data to parse Inquiry Result with RSSI event" (https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/commit/?id=8d08d324fdcb7).


2022-01-04 00:38:29

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [BUG] Page Fault in hci_inquiry_result_with_rssi_evt

Hi Sönke,

On Mon, Jan 3, 2022 at 3:41 PM Sönke Huster <[email protected]> wrote:
>
> Hello,
>
> While fuzzing bluetooth-next I found the following bug:
>
> [ 27.333034] BUG: unable to handle page fault for address: fffff61a1a1a1a1a
> [ 27.333241] #PF: supervisor read access in kernel mode
> [ 27.333241] #PF: error_code(0x0000) - not-present page
> [ 27.333241] PGD 6dfd2067 P4D 6dfd2067 PUD 0
> [ 27.333241] Oops: 0000 [#1] PREEMPT SMP KASAN NOPTI
> [ 27.333241] CPU: 0 PID: 45 Comm: kworker/u3:2 Not tainted 5.16.0-rc1+ #81
> [ 27.333241] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> [ 27.333241] Workqueue: hci0 hci_rx_work
> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
> [ 27.333241] Call Trace:
> [ 27.333241] <TASK>
> [ 27.333241] ? wait_for_completion_io+0x270/0x270
> [ 27.333241] ? hci_inquiry_result_evt+0x4b0/0x4b0
> [ 27.333241] hci_event_packet+0x3b11/0x7b10
> [ 27.333241] ? lock_chain_count+0x20/0x20
> [ 27.333241] ? hci_cmd_status_evt.constprop.0+0x4ea0/0x4ea0
> [ 27.333241] ? sysvec_reboot+0x50/0xc0
> [ 27.333241] ? find_held_lock+0x2c/0x110
> [ 27.333241] ? lock_release+0x3b2/0x6f0
> [ 27.333241] ? skb_dequeue+0x110/0x1a0
> [ 27.333241] ? mark_held_locks+0x9e/0xe0
> [ 27.333241] ? lockdep_hardirqs_on_prepare+0x17b/0x400
> [ 27.333241] hci_rx_work+0x4d3/0xb90
> [ 27.333241] process_one_work+0x904/0x1590
> [ 27.333241] ? lock_release+0x6f0/0x6f0
> [ 27.333241] ? pwq_dec_nr_in_flight+0x230/0x230
> [ 27.333241] ? rwlock_bug.part.0+0x90/0x90
> [ 27.333241] ? _raw_spin_lock_irq+0x41/0x50
> [ 27.333241] worker_thread+0x578/0x1310
> [ 27.333241] ? process_one_work+0x1590/0x1590
> [ 27.333241] kthread+0x3b2/0x490
> [ 27.333241] ? _raw_spin_unlock_irq+0x1f/0x40
> [ 27.333241] ? set_kthread_struct+0x100/0x100
> [ 27.333241] ret_from_fork+0x22/0x30
> [ 27.333241] </TASK>
> [ 27.333241] Modules linked in:
> [ 27.333241] CR2: fffff61a1a1a1a1a
> [ 27.333241] ---[ end trace 6a6825484c8fefa6 ]---
> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
> [ 27.379996] kworker/u3:2 (45) used greatest stack depth: 27736 bytes left
>
> It occurs when sending the following frame to the kernel:
>
> $ xxd crashes/hci_inquiry_result_with_rssi_evt
> 00000000: 0422 24d0 d0d0 d0d0 d0ff ff ."$........
>
> The bug was introduced with the commit "Bluetooth: HCI: Use skb_pull_data to parse Inquiry Result with RSSI event" (https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/commit/?id=8d08d324fdcb7).

That is pretty weird, the data seems to be the following:

04 -> HCI_EVENT_PKT
22 -> HCI_EV_INQUIRY_RESULT_WITH_RSSI
24 -> hci_ev_inquiry_result_rssi.num
d0 d0d0 d0d0 d0ff ff

But this should never evaluate to true for:

if (skb->len == flex_array_size(ev, res2->info, ev->res2->num)) {
...
} else if (skb->len == flex_array_size(ev, res1->info, ev->res1->num)) {

These requires the data to be multiple of sizeof(struct
inquiry_info_rssi_pscan) = 15 bytes or sizeof(struct
inquiry_info_rssi) = 14 bytes respectively where the data left is just
8 bytes long, besides with the number of entries being 0x24 this shall
be well beyond skb->len which shall have cause the else clause:

} else {
bt_dev_err(hdev, "Malformed HCI Event: 0x%2.2x",
HCI_EV_INQUIRY_RESULT_WITH_RSSI);
}

Anyway the bluetooth-next has been updated since last week so I first
attempt to reproduce with a fresh clone of it since we did some fixups
since then.

--
Luiz Augusto von Dentz

2022-01-04 11:50:51

by Soenke Huster

[permalink] [raw]
Subject: Re: [BUG] Page Fault in hci_inquiry_result_with_rssi_evt

Hi Luiz,

On 04.01.22 01:38, Luiz Augusto von Dentz wrote:
> Hi Sönke,
>
> On Mon, Jan 3, 2022 at 3:41 PM Sönke Huster <[email protected]> wrote:
>>
>> Hello,
>>
>> While fuzzing bluetooth-next I found the following bug:
>>
>> [ 27.333034] BUG: unable to handle page fault for address: fffff61a1a1a1a1a
>> [ 27.333241] #PF: supervisor read access in kernel mode
>> [ 27.333241] #PF: error_code(0x0000) - not-present page
>> [ 27.333241] PGD 6dfd2067 P4D 6dfd2067 PUD 0
>> [ 27.333241] Oops: 0000 [#1] PREEMPT SMP KASAN NOPTI
>> [ 27.333241] CPU: 0 PID: 45 Comm: kworker/u3:2 Not tainted 5.16.0-rc1+ #81
>> [ 27.333241] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
>> [ 27.333241] Workqueue: hci0 hci_rx_work
>> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
>> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
>> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
>> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
>> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
>> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
>> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
>> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
>> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
>> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
>> [ 27.333241] Call Trace:
>> [ 27.333241] <TASK>
>> [ 27.333241] ? wait_for_completion_io+0x270/0x270
>> [ 27.333241] ? hci_inquiry_result_evt+0x4b0/0x4b0
>> [ 27.333241] hci_event_packet+0x3b11/0x7b10
>> [ 27.333241] ? lock_chain_count+0x20/0x20
>> [ 27.333241] ? hci_cmd_status_evt.constprop.0+0x4ea0/0x4ea0
>> [ 27.333241] ? sysvec_reboot+0x50/0xc0
>> [ 27.333241] ? find_held_lock+0x2c/0x110
>> [ 27.333241] ? lock_release+0x3b2/0x6f0
>> [ 27.333241] ? skb_dequeue+0x110/0x1a0
>> [ 27.333241] ? mark_held_locks+0x9e/0xe0
>> [ 27.333241] ? lockdep_hardirqs_on_prepare+0x17b/0x400
>> [ 27.333241] hci_rx_work+0x4d3/0xb90
>> [ 27.333241] process_one_work+0x904/0x1590
>> [ 27.333241] ? lock_release+0x6f0/0x6f0
>> [ 27.333241] ? pwq_dec_nr_in_flight+0x230/0x230
>> [ 27.333241] ? rwlock_bug.part.0+0x90/0x90
>> [ 27.333241] ? _raw_spin_lock_irq+0x41/0x50
>> [ 27.333241] worker_thread+0x578/0x1310
>> [ 27.333241] ? process_one_work+0x1590/0x1590
>> [ 27.333241] kthread+0x3b2/0x490
>> [ 27.333241] ? _raw_spin_unlock_irq+0x1f/0x40
>> [ 27.333241] ? set_kthread_struct+0x100/0x100
>> [ 27.333241] ret_from_fork+0x22/0x30
>> [ 27.333241] </TASK>
>> [ 27.333241] Modules linked in:
>> [ 27.333241] CR2: fffff61a1a1a1a1a
>> [ 27.333241] ---[ end trace 6a6825484c8fefa6 ]---
>> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
>> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
>> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
>> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
>> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
>> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
>> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
>> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
>> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
>> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
>> [ 27.379996] kworker/u3:2 (45) used greatest stack depth: 27736 bytes left
>>
>> It occurs when sending the following frame to the kernel:
>>
>> $ xxd crashes/hci_inquiry_result_with_rssi_evt
>> 00000000: 0422 24d0 d0d0 d0d0 d0ff ff ."$........
>>
>> The bug was introduced with the commit "Bluetooth: HCI: Use skb_pull_data to parse Inquiry Result with RSSI event" (https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/commit/?id=8d08d324fdcb7).
>
> That is pretty weird, the data seems to be the following:
>
> 04 -> HCI_EVENT_PKT
> 22 -> HCI_EV_INQUIRY_RESULT_WITH_RSSI
> 24 -> hci_ev_inquiry_result_rssi.num
> d0 d0d0 d0d0 d0ff ff
>
> But this should never evaluate to true for:
>
> if (skb->len == flex_array_size(ev, res2->info, ev->res2->num)) {
> ...
> } else if (skb->len == flex_array_size(ev, res1->info, ev->res1->num)) {
>

I'm sorry, I forgot to mention the affected source code, the check seems to be too late. GDB says it is already happening in net/bluetooth/hci_event.c:4519:

(gdb) list *hci_inquiry_result_with_rssi_evt+0x9b
0xffffffff83470d8b is in hci_inquiry_result_with_rssi_evt (net/bluetooth/hci_event.c:4519).
4514 struct inquiry_data data;
4515 int i;
4516
4517 bt_dev_dbg(hdev, "num_rsp %d", ev->res1->num);
4518
4519 if (!ev->res1->num) # <- page fault here
4520 return;

I just reproduced it on the HEAD of bluetooth-next (for-net-next-2021-12-29).


> These requires the data to be multiple of sizeof(struct
> inquiry_info_rssi_pscan) = 15 bytes or sizeof(struct
> inquiry_info_rssi) = 14 bytes respectively where the data left is just
> 8 bytes long, besides with the number of entries being 0x24 this shall
> be well beyond skb->len which shall have cause the else clause:
>
> } else {
> bt_dev_err(hdev, "Malformed HCI Event: 0x%2.2x",
> HCI_EV_INQUIRY_RESULT_WITH_RSSI);
> }
>

I think prior to the commit that introduced that, the check was made before casting it to the struct, so from the "raw" skb->data:

- int num_rsp = *((__u8 *) skb->data);
- if ((skb->len - 1) / num_rsp != sizeof(struct inquiry_info_with_rssi)) {

> Anyway the bluetooth-next has been updated since last week so I first
> attempt to reproduce with a fresh clone of it since we did some fixups
> since then.
>

Btw, what is the best way to provide an easily reproducible bug report here, I did not figure that out yet.

Also, when searching for bugs (to ideally provide patches), I am currently searching on the HEAD of bluetooth-next. As far as I understood it, the tags "for-net-..." should be more or less stable, as they are merged to net-next which makes its way to mainline, right?

2022-01-04 19:32:00

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [BUG] Page Fault in hci_inquiry_result_with_rssi_evt

Hi Sönke,

On Tue, Jan 4, 2022 at 3:50 AM Sönke Huster <[email protected]> wrote:
>
> Hi Luiz,
>
> On 04.01.22 01:38, Luiz Augusto von Dentz wrote:
> > Hi Sönke,
> >
> > On Mon, Jan 3, 2022 at 3:41 PM Sönke Huster <[email protected]> wrote:
> >>
> >> Hello,
> >>
> >> While fuzzing bluetooth-next I found the following bug:
> >>
> >> [ 27.333034] BUG: unable to handle page fault for address: fffff61a1a1a1a1a
> >> [ 27.333241] #PF: supervisor read access in kernel mode
> >> [ 27.333241] #PF: error_code(0x0000) - not-present page
> >> [ 27.333241] PGD 6dfd2067 P4D 6dfd2067 PUD 0
> >> [ 27.333241] Oops: 0000 [#1] PREEMPT SMP KASAN NOPTI
> >> [ 27.333241] CPU: 0 PID: 45 Comm: kworker/u3:2 Not tainted 5.16.0-rc1+ #81
> >> [ 27.333241] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> >> [ 27.333241] Workqueue: hci0 hci_rx_work
> >> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
> >> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
> >> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
> >> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
> >> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
> >> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
> >> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
> >> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
> >> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
> >> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
> >> [ 27.333241] Call Trace:
> >> [ 27.333241] <TASK>
> >> [ 27.333241] ? wait_for_completion_io+0x270/0x270
> >> [ 27.333241] ? hci_inquiry_result_evt+0x4b0/0x4b0
> >> [ 27.333241] hci_event_packet+0x3b11/0x7b10
> >> [ 27.333241] ? lock_chain_count+0x20/0x20
> >> [ 27.333241] ? hci_cmd_status_evt.constprop.0+0x4ea0/0x4ea0
> >> [ 27.333241] ? sysvec_reboot+0x50/0xc0
> >> [ 27.333241] ? find_held_lock+0x2c/0x110
> >> [ 27.333241] ? lock_release+0x3b2/0x6f0
> >> [ 27.333241] ? skb_dequeue+0x110/0x1a0
> >> [ 27.333241] ? mark_held_locks+0x9e/0xe0
> >> [ 27.333241] ? lockdep_hardirqs_on_prepare+0x17b/0x400
> >> [ 27.333241] hci_rx_work+0x4d3/0xb90
> >> [ 27.333241] process_one_work+0x904/0x1590
> >> [ 27.333241] ? lock_release+0x6f0/0x6f0
> >> [ 27.333241] ? pwq_dec_nr_in_flight+0x230/0x230
> >> [ 27.333241] ? rwlock_bug.part.0+0x90/0x90
> >> [ 27.333241] ? _raw_spin_lock_irq+0x41/0x50
> >> [ 27.333241] worker_thread+0x578/0x1310
> >> [ 27.333241] ? process_one_work+0x1590/0x1590
> >> [ 27.333241] kthread+0x3b2/0x490
> >> [ 27.333241] ? _raw_spin_unlock_irq+0x1f/0x40
> >> [ 27.333241] ? set_kthread_struct+0x100/0x100
> >> [ 27.333241] ret_from_fork+0x22/0x30
> >> [ 27.333241] </TASK>
> >> [ 27.333241] Modules linked in:
> >> [ 27.333241] CR2: fffff61a1a1a1a1a
> >> [ 27.333241] ---[ end trace 6a6825484c8fefa6 ]---
> >> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
> >> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
> >> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
> >> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
> >> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
> >> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
> >> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
> >> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
> >> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
> >> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
> >> [ 27.379996] kworker/u3:2 (45) used greatest stack depth: 27736 bytes left
> >>
> >> It occurs when sending the following frame to the kernel:
> >>
> >> $ xxd crashes/hci_inquiry_result_with_rssi_evt
> >> 00000000: 0422 24d0 d0d0 d0d0 d0ff ff ."$........
> >>
> >> The bug was introduced with the commit "Bluetooth: HCI: Use skb_pull_data to parse Inquiry Result with RSSI event" (https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/commit/?id=8d08d324fdcb7).
> >
> > That is pretty weird, the data seems to be the following:
> >
> > 04 -> HCI_EVENT_PKT
> > 22 -> HCI_EV_INQUIRY_RESULT_WITH_RSSI
> > 24 -> hci_ev_inquiry_result_rssi.num
> > d0 d0d0 d0d0 d0ff ff
> >
> > But this should never evaluate to true for:
> >
> > if (skb->len == flex_array_size(ev, res2->info, ev->res2->num)) {
> > ...
> > } else if (skb->len == flex_array_size(ev, res1->info, ev->res1->num)) {
> >
>
> I'm sorry, I forgot to mention the affected source code, the check seems to be too late. GDB says it is already happening in net/bluetooth/hci_event.c:4519:
>
> (gdb) list *hci_inquiry_result_with_rssi_evt+0x9b
> 0xffffffff83470d8b is in hci_inquiry_result_with_rssi_evt (net/bluetooth/hci_event.c:4519).
> 4514 struct inquiry_data data;
> 4515 int i;
> 4516
> 4517 bt_dev_dbg(hdev, "num_rsp %d", ev->res1->num);
> 4518
> 4519 if (!ev->res1->num) # <- page fault here
> 4520 return;
>
> I just reproduced it on the HEAD of bluetooth-next (for-net-next-2021-12-29).

That would mean there is less data than the hci_ev.min_len, but that
is checked in hci_event_func prior to calling the hci_ev.func:

if (skb->len < ev->min_len) {
bt_dev_err(hdev, "unexpected event 0x%2.2x length: %u < %u",
event, skb->len, ev->min_len);
return;
}

>
> > These requires the data to be multiple of sizeof(struct
> > inquiry_info_rssi_pscan) = 15 bytes or sizeof(struct
> > inquiry_info_rssi) = 14 bytes respectively where the data left is just
> > 8 bytes long, besides with the number of entries being 0x24 this shall
> > be well beyond skb->len which shall have cause the else clause:
> >
> > } else {
> > bt_dev_err(hdev, "Malformed HCI Event: 0x%2.2x",
> > HCI_EV_INQUIRY_RESULT_WITH_RSSI);
> > }
> >
>
> I think prior to the commit that introduced that, the check was made before casting it to the struct, so from the "raw" skb->data:
>
> - int num_rsp = *((__u8 *) skb->data);
> - if ((skb->len - 1) / num_rsp != sizeof(struct inquiry_info_with_rssi)) {

That is still being checked, anyway that would cause a page fault when
accessing num_rsp so I don't understand why it would cause a page
fault now when previously it didn't even check if there were any bytes
to be read, perhaps there is some memory alignment at play.

> > Anyway the bluetooth-next has been updated since last week so I first
> > attempt to reproduce with a fresh clone of it since we did some fixups
> > since then.
> >
>
> Btw, what is the best way to provide an easily reproducible bug report here, I did not figure that out yet.
>
> Also, when searching for bugs (to ideally provide patches), I am currently searching on the HEAD of bluetooth-next. As far as I understood it, the tags "for-net-..." should be more or less stable, as they are merged to net-next which makes its way to mainline, right?

Yep, those are the tags we sent to net-next but in general
bluetooth-next shall also be stable since we run CI on every patch
nowadays.

--
Luiz Augusto von Dentz

2022-01-04 21:04:15

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [BUG] Page Fault in hci_inquiry_result_with_rssi_evt

Hi Sönke,

On Tue, Jan 4, 2022 at 11:31 AM Luiz Augusto von Dentz
<[email protected]> wrote:
>
> Hi Sönke,
>
> On Tue, Jan 4, 2022 at 3:50 AM Sönke Huster <[email protected]> wrote:
> >
> > Hi Luiz,
> >
> > On 04.01.22 01:38, Luiz Augusto von Dentz wrote:
> > > Hi Sönke,
> > >
> > > On Mon, Jan 3, 2022 at 3:41 PM Sönke Huster <[email protected]> wrote:
> > >>
> > >> Hello,
> > >>
> > >> While fuzzing bluetooth-next I found the following bug:
> > >>
> > >> [ 27.333034] BUG: unable to handle page fault for address: fffff61a1a1a1a1a
> > >> [ 27.333241] #PF: supervisor read access in kernel mode
> > >> [ 27.333241] #PF: error_code(0x0000) - not-present page
> > >> [ 27.333241] PGD 6dfd2067 P4D 6dfd2067 PUD 0
> > >> [ 27.333241] Oops: 0000 [#1] PREEMPT SMP KASAN NOPTI
> > >> [ 27.333241] CPU: 0 PID: 45 Comm: kworker/u3:2 Not tainted 5.16.0-rc1+ #81
> > >> [ 27.333241] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> > >> [ 27.333241] Workqueue: hci0 hci_rx_work
> > >> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
> > >> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
> > >> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
> > >> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
> > >> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
> > >> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
> > >> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
> > >> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
> > >> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
> > >> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > >> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
> > >> [ 27.333241] Call Trace:
> > >> [ 27.333241] <TASK>
> > >> [ 27.333241] ? wait_for_completion_io+0x270/0x270
> > >> [ 27.333241] ? hci_inquiry_result_evt+0x4b0/0x4b0
> > >> [ 27.333241] hci_event_packet+0x3b11/0x7b10
> > >> [ 27.333241] ? lock_chain_count+0x20/0x20
> > >> [ 27.333241] ? hci_cmd_status_evt.constprop.0+0x4ea0/0x4ea0
> > >> [ 27.333241] ? sysvec_reboot+0x50/0xc0
> > >> [ 27.333241] ? find_held_lock+0x2c/0x110
> > >> [ 27.333241] ? lock_release+0x3b2/0x6f0
> > >> [ 27.333241] ? skb_dequeue+0x110/0x1a0
> > >> [ 27.333241] ? mark_held_locks+0x9e/0xe0
> > >> [ 27.333241] ? lockdep_hardirqs_on_prepare+0x17b/0x400
> > >> [ 27.333241] hci_rx_work+0x4d3/0xb90
> > >> [ 27.333241] process_one_work+0x904/0x1590
> > >> [ 27.333241] ? lock_release+0x6f0/0x6f0
> > >> [ 27.333241] ? pwq_dec_nr_in_flight+0x230/0x230
> > >> [ 27.333241] ? rwlock_bug.part.0+0x90/0x90
> > >> [ 27.333241] ? _raw_spin_lock_irq+0x41/0x50
> > >> [ 27.333241] worker_thread+0x578/0x1310
> > >> [ 27.333241] ? process_one_work+0x1590/0x1590
> > >> [ 27.333241] kthread+0x3b2/0x490
> > >> [ 27.333241] ? _raw_spin_unlock_irq+0x1f/0x40
> > >> [ 27.333241] ? set_kthread_struct+0x100/0x100
> > >> [ 27.333241] ret_from_fork+0x22/0x30
> > >> [ 27.333241] </TASK>
> > >> [ 27.333241] Modules linked in:
> > >> [ 27.333241] CR2: fffff61a1a1a1a1a
> > >> [ 27.333241] ---[ end trace 6a6825484c8fefa6 ]---
> > >> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
> > >> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
> > >> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
> > >> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
> > >> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
> > >> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
> > >> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
> > >> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
> > >> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
> > >> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > >> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
> > >> [ 27.379996] kworker/u3:2 (45) used greatest stack depth: 27736 bytes left
> > >>
> > >> It occurs when sending the following frame to the kernel:
> > >>
> > >> $ xxd crashes/hci_inquiry_result_with_rssi_evt
> > >> 00000000: 0422 24d0 d0d0 d0d0 d0ff ff ."$........
> > >>
> > >> The bug was introduced with the commit "Bluetooth: HCI: Use skb_pull_data to parse Inquiry Result with RSSI event" (https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/commit/?id=8d08d324fdcb7).
> > >
> > > That is pretty weird, the data seems to be the following:
> > >
> > > 04 -> HCI_EVENT_PKT
> > > 22 -> HCI_EV_INQUIRY_RESULT_WITH_RSSI
> > > 24 -> hci_ev_inquiry_result_rssi.num
> > > d0 d0d0 d0d0 d0ff ff
> > >
> > > But this should never evaluate to true for:
> > >
> > > if (skb->len == flex_array_size(ev, res2->info, ev->res2->num)) {
> > > ...
> > > } else if (skb->len == flex_array_size(ev, res1->info, ev->res1->num)) {
> > >
> >
> > I'm sorry, I forgot to mention the affected source code, the check seems to be too late. GDB says it is already happening in net/bluetooth/hci_event.c:4519:
> >
> > (gdb) list *hci_inquiry_result_with_rssi_evt+0x9b
> > 0xffffffff83470d8b is in hci_inquiry_result_with_rssi_evt (net/bluetooth/hci_event.c:4519).
> > 4514 struct inquiry_data data;
> > 4515 int i;
> > 4516
> > 4517 bt_dev_dbg(hdev, "num_rsp %d", ev->res1->num);
> > 4518
> > 4519 if (!ev->res1->num) # <- page fault here
> > 4520 return;
> >
> > I just reproduced it on the HEAD of bluetooth-next (for-net-next-2021-12-29).
>
> That would mean there is less data than the hci_ev.min_len, but that
> is checked in hci_event_func prior to calling the hci_ev.func:
>
> if (skb->len < ev->min_len) {
> bt_dev_err(hdev, "unexpected event 0x%2.2x length: %u < %u",
> event, skb->len, ev->min_len);
> return;
> }
>
> >
> > > These requires the data to be multiple of sizeof(struct
> > > inquiry_info_rssi_pscan) = 15 bytes or sizeof(struct
> > > inquiry_info_rssi) = 14 bytes respectively where the data left is just
> > > 8 bytes long, besides with the number of entries being 0x24 this shall
> > > be well beyond skb->len which shall have cause the else clause:
> > >
> > > } else {
> > > bt_dev_err(hdev, "Malformed HCI Event: 0x%2.2x",
> > > HCI_EV_INQUIRY_RESULT_WITH_RSSI);
> > > }
> > >
> >
> > I think prior to the commit that introduced that, the check was made before casting it to the struct, so from the "raw" skb->data:
> >
> > - int num_rsp = *((__u8 *) skb->data);
> > - if ((skb->len - 1) / num_rsp != sizeof(struct inquiry_info_with_rssi)) {
>
> That is still being checked, anyway that would cause a page fault when
> accessing num_rsp so I don't understand why it would cause a page
> fault now when previously it didn't even check if there were any bytes
> to be read, perhaps there is some memory alignment at play.
>
> > > Anyway the bluetooth-next has been updated since last week so I first
> > > attempt to reproduce with a fresh clone of it since we did some fixups
> > > since then.
> > >
> >
> > Btw, what is the best way to provide an easily reproducible bug report here, I did not figure that out yet.
> >
> > Also, when searching for bugs (to ideally provide patches), I am currently searching on the HEAD of bluetooth-next. As far as I understood it, the tags "for-net-..." should be more or less stable, as they are merged to net-next which makes its way to mainline, right?
>
> Yep, those are the tags we sent to net-next but in general
> bluetooth-next shall also be stable since we run CI on every patch
> nowadays.

Ive just sent a patch trying to eliminate the use of the union since
that perhaps cause the compiler to use a different alignment, Im also
thinking on introducing some mechanism to our emulator to generate
arbitrary events in a form a command that generates an event based on
its parameter.

https://patchwork.kernel.org/project/bluetooth/patch/[email protected]/

--
Luiz Augusto von Dentz

2022-01-04 21:31:16

by Soenke Huster

[permalink] [raw]
Subject: Re: [BUG] Page Fault in hci_inquiry_result_with_rssi_evt

Hi Luiz,

On 04.01.22 22:04, Luiz Augusto von Dentz wrote:
> Hi Sönke,
>
> On Tue, Jan 4, 2022 at 11:31 AM Luiz Augusto von Dentz
> <[email protected]> wrote:
>>
>> Hi Sönke,
>>
>> On Tue, Jan 4, 2022 at 3:50 AM Sönke Huster <[email protected]> wrote:
>>>
>>> Hi Luiz,
>>>
>>> On 04.01.22 01:38, Luiz Augusto von Dentz wrote:
>>>> Hi Sönke,
>>>>
>>>> On Mon, Jan 3, 2022 at 3:41 PM Sönke Huster <[email protected]> wrote:
>>>>>
>>>>> Hello,
>>>>>
>>>>> While fuzzing bluetooth-next I found the following bug:
>>>>>
>>>>> [ 27.333034] BUG: unable to handle page fault for address: fffff61a1a1a1a1a
>>>>> [ 27.333241] #PF: supervisor read access in kernel mode
>>>>> [ 27.333241] #PF: error_code(0x0000) - not-present page
>>>>> [ 27.333241] PGD 6dfd2067 P4D 6dfd2067 PUD 0
>>>>> [ 27.333241] Oops: 0000 [#1] PREEMPT SMP KASAN NOPTI
>>>>> [ 27.333241] CPU: 0 PID: 45 Comm: kworker/u3:2 Not tainted 5.16.0-rc1+ #81
>>>>> [ 27.333241] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
>>>>> [ 27.333241] Workqueue: hci0 hci_rx_work
>>>>> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
>>>>> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
>>>>> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
>>>>> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
>>>>> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
>>>>> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
>>>>> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
>>>>> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
>>>>> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
>>>>> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>>>>> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
>>>>> [ 27.333241] Call Trace:
>>>>> [ 27.333241] <TASK>
>>>>> [ 27.333241] ? wait_for_completion_io+0x270/0x270
>>>>> [ 27.333241] ? hci_inquiry_result_evt+0x4b0/0x4b0
>>>>> [ 27.333241] hci_event_packet+0x3b11/0x7b10
>>>>> [ 27.333241] ? lock_chain_count+0x20/0x20
>>>>> [ 27.333241] ? hci_cmd_status_evt.constprop.0+0x4ea0/0x4ea0
>>>>> [ 27.333241] ? sysvec_reboot+0x50/0xc0
>>>>> [ 27.333241] ? find_held_lock+0x2c/0x110
>>>>> [ 27.333241] ? lock_release+0x3b2/0x6f0
>>>>> [ 27.333241] ? skb_dequeue+0x110/0x1a0
>>>>> [ 27.333241] ? mark_held_locks+0x9e/0xe0
>>>>> [ 27.333241] ? lockdep_hardirqs_on_prepare+0x17b/0x400
>>>>> [ 27.333241] hci_rx_work+0x4d3/0xb90
>>>>> [ 27.333241] process_one_work+0x904/0x1590
>>>>> [ 27.333241] ? lock_release+0x6f0/0x6f0
>>>>> [ 27.333241] ? pwq_dec_nr_in_flight+0x230/0x230
>>>>> [ 27.333241] ? rwlock_bug.part.0+0x90/0x90
>>>>> [ 27.333241] ? _raw_spin_lock_irq+0x41/0x50
>>>>> [ 27.333241] worker_thread+0x578/0x1310
>>>>> [ 27.333241] ? process_one_work+0x1590/0x1590
>>>>> [ 27.333241] kthread+0x3b2/0x490
>>>>> [ 27.333241] ? _raw_spin_unlock_irq+0x1f/0x40
>>>>> [ 27.333241] ? set_kthread_struct+0x100/0x100
>>>>> [ 27.333241] ret_from_fork+0x22/0x30
>>>>> [ 27.333241] </TASK>
>>>>> [ 27.333241] Modules linked in:
>>>>> [ 27.333241] CR2: fffff61a1a1a1a1a
>>>>> [ 27.333241] ---[ end trace 6a6825484c8fefa6 ]---
>>>>> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
>>>>> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
>>>>> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
>>>>> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
>>>>> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
>>>>> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
>>>>> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
>>>>> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
>>>>> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
>>>>> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>>>>> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
>>>>> [ 27.379996] kworker/u3:2 (45) used greatest stack depth: 27736 bytes left
>>>>>
>>>>> It occurs when sending the following frame to the kernel:
>>>>>
>>>>> $ xxd crashes/hci_inquiry_result_with_rssi_evt
>>>>> 00000000: 0422 24d0 d0d0 d0d0 d0ff ff ."$........
>>>>>
>>>>> The bug was introduced with the commit "Bluetooth: HCI: Use skb_pull_data to parse Inquiry Result with RSSI event" (https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/commit/?id=8d08d324fdcb7).
>>>>
>>>> That is pretty weird, the data seems to be the following:
>>>>
>>>> 04 -> HCI_EVENT_PKT
>>>> 22 -> HCI_EV_INQUIRY_RESULT_WITH_RSSI
>>>> 24 -> hci_ev_inquiry_result_rssi.num
>>>> d0 d0d0 d0d0 d0ff ff
>>>>
>>>> But this should never evaluate to true for:
>>>>
>>>> if (skb->len == flex_array_size(ev, res2->info, ev->res2->num)) {
>>>> ...
>>>> } else if (skb->len == flex_array_size(ev, res1->info, ev->res1->num)) {
>>>>
>>>
>>> I'm sorry, I forgot to mention the affected source code, the check seems to be too late. GDB says it is already happening in net/bluetooth/hci_event.c:4519:
>>>
>>> (gdb) list *hci_inquiry_result_with_rssi_evt+0x9b
>>> 0xffffffff83470d8b is in hci_inquiry_result_with_rssi_evt (net/bluetooth/hci_event.c:4519).
>>> 4514 struct inquiry_data data;
>>> 4515 int i;
>>> 4516
>>> 4517 bt_dev_dbg(hdev, "num_rsp %d", ev->res1->num);
>>> 4518
>>> 4519 if (!ev->res1->num) # <- page fault here
>>> 4520 return;
>>>
>>> I just reproduced it on the HEAD of bluetooth-next (for-net-next-2021-12-29).
>>
>> That would mean there is less data than the hci_ev.min_len, but that
>> is checked in hci_event_func prior to calling the hci_ev.func:
>>
>> if (skb->len < ev->min_len) {
>> bt_dev_err(hdev, "unexpected event 0x%2.2x length: %u < %u",
>> event, skb->len, ev->min_len);
>> return;
>> }
>>
>>>
>>>> These requires the data to be multiple of sizeof(struct
>>>> inquiry_info_rssi_pscan) = 15 bytes or sizeof(struct
>>>> inquiry_info_rssi) = 14 bytes respectively where the data left is just
>>>> 8 bytes long, besides with the number of entries being 0x24 this shall
>>>> be well beyond skb->len which shall have cause the else clause:
>>>>
>>>> } else {
>>>> bt_dev_err(hdev, "Malformed HCI Event: 0x%2.2x",
>>>> HCI_EV_INQUIRY_RESULT_WITH_RSSI);
>>>> }
>>>>
>>>
>>> I think prior to the commit that introduced that, the check was made before casting it to the struct, so from the "raw" skb->data:
>>>
>>> - int num_rsp = *((__u8 *) skb->data);
>>> - if ((skb->len - 1) / num_rsp != sizeof(struct inquiry_info_with_rssi)) {
>>
>> That is still being checked, anyway that would cause a page fault when
>> accessing num_rsp so I don't understand why it would cause a page
>> fault now when previously it didn't even check if there were any bytes
>> to be read, perhaps there is some memory alignment at play.
>>
>>>> Anyway the bluetooth-next has been updated since last week so I first
>>>> attempt to reproduce with a fresh clone of it since we did some fixups
>>>> since then.
>>>>
>>>
>>> Btw, what is the best way to provide an easily reproducible bug report here, I did not figure that out yet.
>>>
>>> Also, when searching for bugs (to ideally provide patches), I am currently searching on the HEAD of bluetooth-next. As far as I understood it, the tags "for-net-..." should be more or less stable, as they are merged to net-next which makes its way to mainline, right?
>>
>> Yep, those are the tags we sent to net-next but in general
>> bluetooth-next shall also be stable since we run CI on every patch
>> nowadays.
>
> Ive just sent a patch trying to eliminate the use of the union since
> that perhaps cause the compiler to use a different alignment, Im also

The patch fixes it, I can't reproduce it anymore and the kernel log shows the expected "Bluetooth: hci0: Malformed HCI Event: 0x22".

> thinking on introducing some mechanism to our emulator to generate
> arbitrary events in a form a command that generates an event based on
> its parameter.
>
> https://patchwork.kernel.org/project/bluetooth/patch/[email protected]/
>


2022-01-04 22:40:20

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [BUG] Page Fault in hci_inquiry_result_with_rssi_evt

Hi Sönke,

On Tue, Jan 4, 2022 at 1:31 PM Sönke Huster <[email protected]> wrote:
>
> Hi Luiz,
>
> On 04.01.22 22:04, Luiz Augusto von Dentz wrote:
> > Hi Sönke,
> >
> > On Tue, Jan 4, 2022 at 11:31 AM Luiz Augusto von Dentz
> > <[email protected]> wrote:
> >>
> >> Hi Sönke,
> >>
> >> On Tue, Jan 4, 2022 at 3:50 AM Sönke Huster <[email protected]> wrote:
> >>>
> >>> Hi Luiz,
> >>>
> >>> On 04.01.22 01:38, Luiz Augusto von Dentz wrote:
> >>>> Hi Sönke,
> >>>>
> >>>> On Mon, Jan 3, 2022 at 3:41 PM Sönke Huster <[email protected]> wrote:
> >>>>>
> >>>>> Hello,
> >>>>>
> >>>>> While fuzzing bluetooth-next I found the following bug:
> >>>>>
> >>>>> [ 27.333034] BUG: unable to handle page fault for address: fffff61a1a1a1a1a
> >>>>> [ 27.333241] #PF: supervisor read access in kernel mode
> >>>>> [ 27.333241] #PF: error_code(0x0000) - not-present page
> >>>>> [ 27.333241] PGD 6dfd2067 P4D 6dfd2067 PUD 0
> >>>>> [ 27.333241] Oops: 0000 [#1] PREEMPT SMP KASAN NOPTI
> >>>>> [ 27.333241] CPU: 0 PID: 45 Comm: kworker/u3:2 Not tainted 5.16.0-rc1+ #81
> >>>>> [ 27.333241] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> >>>>> [ 27.333241] Workqueue: hci0 hci_rx_work
> >>>>> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
> >>>>> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
> >>>>> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
> >>>>> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
> >>>>> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
> >>>>> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
> >>>>> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
> >>>>> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
> >>>>> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
> >>>>> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >>>>> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
> >>>>> [ 27.333241] Call Trace:
> >>>>> [ 27.333241] <TASK>
> >>>>> [ 27.333241] ? wait_for_completion_io+0x270/0x270
> >>>>> [ 27.333241] ? hci_inquiry_result_evt+0x4b0/0x4b0
> >>>>> [ 27.333241] hci_event_packet+0x3b11/0x7b10
> >>>>> [ 27.333241] ? lock_chain_count+0x20/0x20
> >>>>> [ 27.333241] ? hci_cmd_status_evt.constprop.0+0x4ea0/0x4ea0
> >>>>> [ 27.333241] ? sysvec_reboot+0x50/0xc0
> >>>>> [ 27.333241] ? find_held_lock+0x2c/0x110
> >>>>> [ 27.333241] ? lock_release+0x3b2/0x6f0
> >>>>> [ 27.333241] ? skb_dequeue+0x110/0x1a0
> >>>>> [ 27.333241] ? mark_held_locks+0x9e/0xe0
> >>>>> [ 27.333241] ? lockdep_hardirqs_on_prepare+0x17b/0x400
> >>>>> [ 27.333241] hci_rx_work+0x4d3/0xb90
> >>>>> [ 27.333241] process_one_work+0x904/0x1590
> >>>>> [ 27.333241] ? lock_release+0x6f0/0x6f0
> >>>>> [ 27.333241] ? pwq_dec_nr_in_flight+0x230/0x230
> >>>>> [ 27.333241] ? rwlock_bug.part.0+0x90/0x90
> >>>>> [ 27.333241] ? _raw_spin_lock_irq+0x41/0x50
> >>>>> [ 27.333241] worker_thread+0x578/0x1310
> >>>>> [ 27.333241] ? process_one_work+0x1590/0x1590
> >>>>> [ 27.333241] kthread+0x3b2/0x490
> >>>>> [ 27.333241] ? _raw_spin_unlock_irq+0x1f/0x40
> >>>>> [ 27.333241] ? set_kthread_struct+0x100/0x100
> >>>>> [ 27.333241] ret_from_fork+0x22/0x30
> >>>>> [ 27.333241] </TASK>
> >>>>> [ 27.333241] Modules linked in:
> >>>>> [ 27.333241] CR2: fffff61a1a1a1a1a
> >>>>> [ 27.333241] ---[ end trace 6a6825484c8fefa6 ]---
> >>>>> [ 27.333241] RIP: 0010:hci_inquiry_result_with_rssi_evt+0xbc/0x950
> >>>>> [ 27.333241] Code: 8b 04 24 48 c1 e8 03 42 80 3c 28 00 0f 85 20 07 00 00 48 8b 04 24 4c 8b 28 48 b8 00 00 00 00 00 fc ff df 4c 89 0
> >>>>> [ 27.333241] RSP: 0018:ffffc900004ff9c8 EFLAGS: 00010212
> >>>>> [ 27.333241] RAX: dffffc0000000000 RBX: 0000000000000022 RCX: ffffffff834663d1
> >>>>> [ 27.333241] RDX: 1ffffa1a1a1a1a1a RSI: 0000000000000012 RDI: ffff88800affb074
> >>>>> [ 27.333241] RBP: ffff88800aae0000 R08: ffffffff844ef360 R09: ffffffff83487b35
> >>>>> [ 27.333241] R10: 000000000000002c R11: 0000000000000022 R12: ffff88800affb000
> >>>>> [ 27.333241] R13: ffffd0d0d0d0d0d0 R14: 0000000000000000 R15: ffff88800aae0000
> >>>>> [ 27.333241] FS: 0000000000000000(0000) GS:ffff88806ce00000(0000) knlGS:0000000000000000
> >>>>> [ 27.333241] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >>>>> [ 27.333241] CR2: fffff61a1a1a1a1a CR3: 0000000004a26000 CR4: 00000000000006f0
> >>>>> [ 27.379996] kworker/u3:2 (45) used greatest stack depth: 27736 bytes left
> >>>>>
> >>>>> It occurs when sending the following frame to the kernel:
> >>>>>
> >>>>> $ xxd crashes/hci_inquiry_result_with_rssi_evt
> >>>>> 00000000: 0422 24d0 d0d0 d0d0 d0ff ff ."$........
> >>>>>
> >>>>> The bug was introduced with the commit "Bluetooth: HCI: Use skb_pull_data to parse Inquiry Result with RSSI event" (https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/commit/?id=8d08d324fdcb7).
> >>>>
> >>>> That is pretty weird, the data seems to be the following:
> >>>>
> >>>> 04 -> HCI_EVENT_PKT
> >>>> 22 -> HCI_EV_INQUIRY_RESULT_WITH_RSSI
> >>>> 24 -> hci_ev_inquiry_result_rssi.num
> >>>> d0 d0d0 d0d0 d0ff ff
> >>>>
> >>>> But this should never evaluate to true for:
> >>>>
> >>>> if (skb->len == flex_array_size(ev, res2->info, ev->res2->num)) {
> >>>> ...
> >>>> } else if (skb->len == flex_array_size(ev, res1->info, ev->res1->num)) {
> >>>>
> >>>
> >>> I'm sorry, I forgot to mention the affected source code, the check seems to be too late. GDB says it is already happening in net/bluetooth/hci_event.c:4519:
> >>>
> >>> (gdb) list *hci_inquiry_result_with_rssi_evt+0x9b
> >>> 0xffffffff83470d8b is in hci_inquiry_result_with_rssi_evt (net/bluetooth/hci_event.c:4519).
> >>> 4514 struct inquiry_data data;
> >>> 4515 int i;
> >>> 4516
> >>> 4517 bt_dev_dbg(hdev, "num_rsp %d", ev->res1->num);
> >>> 4518
> >>> 4519 if (!ev->res1->num) # <- page fault here
> >>> 4520 return;
> >>>
> >>> I just reproduced it on the HEAD of bluetooth-next (for-net-next-2021-12-29).
> >>
> >> That would mean there is less data than the hci_ev.min_len, but that
> >> is checked in hci_event_func prior to calling the hci_ev.func:
> >>
> >> if (skb->len < ev->min_len) {
> >> bt_dev_err(hdev, "unexpected event 0x%2.2x length: %u < %u",
> >> event, skb->len, ev->min_len);
> >> return;
> >> }
> >>
> >>>
> >>>> These requires the data to be multiple of sizeof(struct
> >>>> inquiry_info_rssi_pscan) = 15 bytes or sizeof(struct
> >>>> inquiry_info_rssi) = 14 bytes respectively where the data left is just
> >>>> 8 bytes long, besides with the number of entries being 0x24 this shall
> >>>> be well beyond skb->len which shall have cause the else clause:
> >>>>
> >>>> } else {
> >>>> bt_dev_err(hdev, "Malformed HCI Event: 0x%2.2x",
> >>>> HCI_EV_INQUIRY_RESULT_WITH_RSSI);
> >>>> }
> >>>>
> >>>
> >>> I think prior to the commit that introduced that, the check was made before casting it to the struct, so from the "raw" skb->data:
> >>>
> >>> - int num_rsp = *((__u8 *) skb->data);
> >>> - if ((skb->len - 1) / num_rsp != sizeof(struct inquiry_info_with_rssi)) {
> >>
> >> That is still being checked, anyway that would cause a page fault when
> >> accessing num_rsp so I don't understand why it would cause a page
> >> fault now when previously it didn't even check if there were any bytes
> >> to be read, perhaps there is some memory alignment at play.
> >>
> >>>> Anyway the bluetooth-next has been updated since last week so I first
> >>>> attempt to reproduce with a fresh clone of it since we did some fixups
> >>>> since then.
> >>>>
> >>>
> >>> Btw, what is the best way to provide an easily reproducible bug report here, I did not figure that out yet.
> >>>
> >>> Also, when searching for bugs (to ideally provide patches), I am currently searching on the HEAD of bluetooth-next. As far as I understood it, the tags "for-net-..." should be more or less stable, as they are merged to net-next which makes its way to mainline, right?
> >>
> >> Yep, those are the tags we sent to net-next but in general
> >> bluetooth-next shall also be stable since we run CI on every patch
> >> nowadays.
> >
> > Ive just sent a patch trying to eliminate the use of the union since
> > that perhaps cause the compiler to use a different alignment, Im also
>
> The patch fixes it, I can't reproduce it anymore and the kernel log shows the expected "Bluetooth: hci0: Malformed HCI Event: 0x22".

Thanks, would you please respond to the patch with Tested-by:

> > thinking on introducing some mechanism to our emulator to generate
> > arbitrary events in a form a command that generates an event based on
> > its parameter.
> >
> > https://patchwork.kernel.org/project/bluetooth/patch/[email protected]/
> >
>


--
Luiz Augusto von Dentz