Hi Sherry, On Mon, May 16, 2022 at 3:56 AM Sherry Sun <sherry.sun@xxxxxxx> wrote: > > Hi Luiz, > > > > > Hi Sherry, > > > > On Tue, May 10, 2022 at 2:47 AM Sherry Sun <sherry.sun@xxxxxxx> wrote: > > > > > > Hi, Bluetooth community: > > > > > > When I try to connect the BLE device to i.MX8mm platform on L5.17.0-rc8 > > kernel, sometimes BLE connection may fail, at which point I can observe an > > kernel panic (Unable to handle kernel paging request at virtual address > > 00078024e000003b), then I enabled the KASAN, found there is a use-after- > > free issue in hci_le_conn_failed(), check the following error logs for details. > > > There is no such issue with the L5.15 kernel. Has anyone observed the > > similar issue on L5.17.0-rc8 kernel? Or have any idea regarding this issue? > > Many thanks. > > > > Interesting, this might be a problem with the controller generating a different > > event than expected: > > > > /* BLUETOOTH CORE SPECIFICATION Version 5.3 | Vol 4, Part E page 2261: > > * > > * If this event is unmasked and the HCI_LE_Connection_Complete event > > * is unmasked, only the HCI_LE_Enhanced_Connection_Complete event is > > * sent when a new connection has been created. > > */ > > err = __hci_cmd_sync_status_sk(hdev, HCI_OP_LE_CREATE_CONN, > > sizeof(cp), &cp, > > use_enhanced_conn_complete(hdev) ? > > HCI_EV_LE_ENHANCED_CONN_COMPLETE : > > HCI_EV_LE_CONN_COMPLETE, > > conn->conn_timeout, NULL); > > > > So if the event is different than expected the event would be processed > > _before_ create_le_conn_complete which would likely timeout, so perhaps > > we need a special handling to match multiple events instead of just one, > > though it worth checking if this is allowed by the spec given that: > > > > /* BLUETOOTH CORE SPECIFICATION Version 5.3 | Vol 4, Part E page 1789: > > * > > * C24: Mandatory if the LE Controller supports Connection State and either > > * LE Feature (LL Privacy) or LE Feature (Extended Advertising) is supported > > */ #define use_enhanced_conn_complete(dev) (ll_privacy_capable(dev) || \ > > ext_adv_capable(dev)) > > > > Perhaps this is not enough since it appears we are getting the enhanced > > version even if this evaluates to false so perhaps we should test something > > else, that said we also do: > > > > /* If the controller supports LL Privacy feature or LE Extended Adv, > > * enable the corresponding event. > > */ > > if (use_enhanced_conn_complete(hdev)) > > events[1] |= 0x02; /* LE Enhanced Connection Complete */ > > > > So it looks like the controller is generating LE Enhanced Connection Complete > > even when the host has not unmasked it. > > I have checked that use_enhanced_conn_complete(hdev) is true for my host, so the controller generate LE Enhanced Connection Complete is the expected behavior. > BTW, I have cherry-picked your patch 9b3628d79b46(Bluetooth: hci_sync: Cleanup hci_conn if it cannot be aborted) to L5.17, found this can avoid the kernel panic(Unable to handle kernel paging request at virtual address dead000000000122), maybe because you removed the hci_conn_del() from hci_le_conn_failed(), but KASAN still reported the same use-after-free issue(BUG: KASAN: use-after-free in hci_le_conn_failed+0x3c8/0x480). > > I checked the btmon log, seems there is an LE Create Connection Cancel HCI command which cause the LE Enhanced Connection Complete fail, I have no idea how this command is triggered, but with your patch, as there is no kernel panic, the hci_connect_le() is still trying to create the LE connection, and 2 seconds later, the connection has been auto created successfully, and LE Enhanced Connection Complete also show the success status. > So the use-after-free issue reported by KASAN maybe caused by the LE Create Connection Cancel command before LE Enhanced Connection Complete return, which cause hci_le_enh_conn_complete_evt() return error status and free the hci_conn struct. Could you try with the following change as well: https://patchwork.kernel.org/project/bluetooth/list/?series=641604 > btmon logs: > < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2 #1241 2021-11-19 17:24:36.276592 > Scanning: Disabled (0x00) > Filter duplicates: Disabled (0x00) > > HCI Event: Command Complete (0x0e) plen 4 #1242 2021-11-19 17:24:36.277450 > LE Set Scan Enable (0x08|0x000c) ncmd 1 > Status: Success (0x00) > < HCI Command: LE Create Connection (0x08|0x000d) plen 25 #1243 2021-11-19 17:24:36.285151 > Scan interval: 60.000 msec (0x0060) > Scan window: 60.000 msec (0x0060) > Filter policy: White list is not used (0x00) > Peer address type: Random (0x01) > Peer address: E3:BD:5B:22:90:68 (Static) > Own address type: Public (0x00) > Min connection interval: 400.00 msec (0x0140) > Max connection interval: 480.00 msec (0x0180) > Connection latency: 2 (0x0002) > Supervision timeout: 6000 msec (0x0258) > Min connection length: 0.000 msec (0x0000) > Max connection length: 0.000 msec (0x0000) > > HCI Event: Command Status (0x0f) plen 4 #1244 2021-11-19 17:24:36.286326 > LE Create Connection (0x08|0x000d) ncmd 1 > Status: Success (0x00) > < HCI Command: LE Create Connection Cancel (0x08|0x000e) plen 0 #1245 2021-11-19 17:24:40.413907 > > HCI Event: Command Complete (0x0e) plen 4 #1246 2021-11-19 17:24:40.414858 > LE Create Connection Cancel (0x08|0x000e) ncmd 1 > Status: Success (0x00) > > HCI Event: LE Meta Event (0x3e) plen 31 #1247 2021-11-19 17:24:40.415118 > LE Enhanced Connection Complete (0x0a) > Status: Unknown Connection Identifier (0x02) > Handle: 0 > Role: Master (0x00) > Peer address type: Random (0x01) > Peer address: E3:BD:5B:22:90:68 (Static) > Local resolvable private address: 00:00:00:00:00:00 (Non-Resolvable) > Peer resolvable private address: 00:00:00:00:00:00 (Non-Resolvable) > Connection interval: 480.00 msec (0x0180) > Connection latency: 2 (0x0002) > Supervision timeout: 6000 msec (0x0258) > Master clock accuracy: 0x00 > @ MGMT Event: Connect Failed (0x000d) plen 8 {0x0001} 2021-11-19 17:24:40.415190 > LE Address: E3:BD:5B:22:90:68 (Static) > Status: Not Connected (0x02) > @ MGMT Event: Connect Failed (0x000d) plen 8 {0x0001} 2021-11-19 17:24:41.006451 > LE Address: E3:BD:5B:22:90:68 (Static) > Status: Failed (0x03) > > ...(two seconds later) > > < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2 #1366 2021-11-19 17:24:43.998501 > Scanning: Disabled (0x00) > Filter duplicates: Disabled (0x00) > > HCI Event: Command Complete (0x0e) plen 4 #1367 2021-11-19 17:24:43.999293 > LE Set Scan Enable (0x08|0x000c) ncmd 1 > Status: Success (0x00) > < HCI Command: LE Create Connection (0x08|0x000d) plen 25 #1368 2021-11-19 17:24:44.007019 > Scan interval: 60.000 msec (0x0060) > Scan window: 60.000 msec (0x0060) > Filter policy: White list is not used (0x00) > Peer address type: Random (0x01) > Peer address: E3:BD:5B:22:90:68 (Static) > Own address type: Public (0x00) > Min connection interval: 400.00 msec (0x0140) > Max connection interval: 480.00 msec (0x0180) > Connection latency: 2 (0x0002) > Supervision timeout: 6000 msec (0x0258) > Min connection length: 0.000 msec (0x0000) > Max connection length: 0.000 msec (0x0000) > > HCI Event: Command Status (0x0f) plen 4 #1369 2021-11-19 17:24:44.008290 > LE Create Connection (0x08|0x000d) ncmd 1 > Status: Success (0x00) > > HCI Event: LE Meta Event (0x3e) plen 31 #1370 2021-11-19 17:24:47.843529 > LE Enhanced Connection Complete (0x0a) > Status: Success (0x00) > Handle: 128 > Role: Master (0x00) > Peer address type: Random (0x01) > Peer address: E3:BD:5B:22:90:68 (Static) > Local resolvable private address: 00:00:00:00:00:00 (Non-Resolvable) > Peer resolvable private address: 00:00:00:00:00:00 (Non-Resolvable) > Connection interval: 480.00 msec (0x0180) > Connection latency: 2 (0x0002) > Supervision timeout: 6000 msec (0x0258) > Master clock accuracy: 0x01 > @ MGMT Event: Device Connected (0x000b) plen 41 {0x0001} 2021-11-19 17:24:47.843647 > LE Address: E3:BD:5B:22:90:68 (Static) > Flags: 0x00000008 > Connection Locally Initiated > Data length: 28 > Name (complete): nut > Flags: 0x06 > LE General Discoverable Mode > BR/EDR Not Supported > 16-bit Service UUIDs (complete): 1 entry > Link Loss (0x1803) > Company: Nordic Semiconductor ASA (89) > Data: 0010 > Service Data (UUID 0x180a): e3bd5b229068 > > Best regards > Sherry > > > > > > Error logs: > > > [bluetooth]# connect E3:BD:5B:22:90:68 Attempting to connect to > > > E3:BD:5B:22:90:68 [bluetooth]# [ 552.446716] Bluetooth: hci0: Opcode > > > 0x200d failed: -110 Failed to connect: org.bluez.Error.Failed [ > > > 552.467725] Bluetooth: hci0: request failed to create LE connection: > > > err -110 [ 552.481726] > > > > > ================================================================ > > == > > > [ 552.488966] BUG: KASAN: use-after-free in > > > hci_le_conn_failed+0x4b0/0x5a0 [ 552.495695] Read of size 8 at addr > > > ffff0000126da570 by task kworker/u9:0/73 [ 552.502667] > > > [ 552.504169] CPU: 2 PID: 73 Comm: kworker/u9:0 Tainted: G O > > 5.17.0-rc8-next-20220315-00001-g7c4f5ebecd82-dirty #245 > > > [ 552.515834] Hardware name: FSL i.MX8MM EVK board (DT) [ > > > 552.520894] Workqueue: hci0 hci_cmd_sync_work [ 552.525275] Call > > > trace: > > > [ 552.527727] dump_backtrace.part.0+0x210/0x220 [ 552.532190] > > > show_stack+0x18/0x6c [ 552.535518] dump_stack_lvl+0x68/0x84 [ > > > 552.539199] print_report+0x160/0x5bc [ 552.542878] > > > kasan_report+0xa4/0xf0 [ 552.546378] > > > __asan_report_load8_noabort+0x3c/0x50 > > > [ 552.551185] hci_le_conn_failed+0x4b0/0x5a0 [ 552.555378] > > > create_le_conn_complete+0x60/0xb0 [ 552.559836] > > > hci_cmd_sync_work+0x128/0x210 [ 552.563945] > > > process_one_work+0x60c/0xf04 [ 552.567971] > > worker_thread+0x3bc/0xe1c > > > [ 552.571731] kthread+0x278/0x2e0 [ 552.574976] > > > ret_from_fork+0x10/0x20 [ 552.578568] [ 552.580065] Allocated by > > > task 518: > > > [ 552.583474] kasan_save_stack+0x2c/0x54 [ 552.587323] > > > __kasan_kmalloc+0x90/0xbc [ 552.591086] hci_conn_add+0x70/0xe50 [ > > > 552.594670] hci_connect_le_scan+0x23c/0x71c [ 552.598952] > > > l2cap_chan_connect+0xbe8/0x11ec [ 552.603238] > > > l2cap_sock_connect+0x298/0x57c [ 552.607434] > > > __sys_connect+0x1e4/0x240 [ 552.611198] > > > __arm64_sys_connect+0x6c/0xa0 [ 552.615306] > > > invoke_syscall+0x6c/0x260 [ 552.619073] > > > el0_svc_common.constprop.0+0x17c/0x280 > > > [ 552.623962] do_el0_svc+0xa0/0xd0 > > > [ 552.627292] el0_svc+0x4c/0x8c > > > [ 552.630360] el0t_64_sync_handler+0xa4/0x130 [ 552.634649] > > > el0t_64_sync+0x18c/0x190 [ 552.638325] [ 552.639821] Freed by task > > > 476: > > > [ 552.642882] kasan_save_stack+0x2c/0x54 [ 552.646731] > > > kasan_set_track+0x2c/0x40 [ 552.650494] > > > kasan_set_free_info+0x28/0x50 [ 552.654603] > > > __kasan_slab_free+0xec/0x13c [ 552.658625] kfree+0xd4/0x280 [ > > > 552.661605] bt_link_release+0x2c/0x3c [ 552.665366] > > > device_release+0xe4/0x1f0 [ 552.669131] kobject_put+0x130/0x244 [ > > > 552.672722] put_device+0x18/0x30 [ 552.676049] > > > hci_conn_cleanup+0x230/0x4d4 [ 552.680068] hci_conn_del+0x46c/0x4a4 > > > [ 552.683740] hci_le_conn_failed+0x318/0x5a0 [ 552.687935] > > > le_conn_complete_evt.part.0+0x778/0x15a0 > > > [ 552.693008] hci_le_enh_conn_complete_evt+0x224/0x330 > > > [ 552.698075] hci_le_meta_evt+0x1cc/0x40c [ 552.702011] > > > hci_event_packet+0x3e0/0x165c [ 552.706123] hci_rx_work+0x2e0/0x580 > > > [ 552.709715] process_one_work+0x60c/0xf04 [ 552.713735] > > > worker_thread+0x3bc/0xe1c [ 552.717495] kthread+0x278/0x2e0 [ > > > 552.720739] ret_from_fork+0x10/0x20 [ 552.724330] [ 552.725824] > > > Last potentially related work creation: > > > [ 552.730708] kasan_save_stack+0x2c/0x54 [ 552.734557] > > > __kasan_record_aux_stack+0xa0/0xd0 > > > [ 552.739100] kasan_record_aux_stack_noalloc+0x14/0x20 > > > [ 552.744168] __queue_work+0x428/0xd14 [ 552.747846] > > > __queue_delayed_work+0x144/0x220 [ 552.752216] > > > queue_delayed_work_on+0xa0/0xe0 [ 552.756498] > > > l2cap_chan_del+0x4b8/0xb50 [ 552.760343] l2cap_conn_del+0x254/0x694 > > > [ 552.764187] l2cap_connect_cfm+0x698/0xb10 [ 552.768299] > > > hci_le_conn_failed+0x2c4/0x5a0 [ 552.772494] > > > le_conn_complete_evt.part.0+0x778/0x15a0 > > > [ 552.777565] hci_le_enh_conn_complete_evt+0x224/0x330 > > > [ 552.782630] hci_le_meta_evt+0x1cc/0x40c [ 552.786567] > > > hci_event_packet+0x3e0/0x165c [ 552.790680] hci_rx_work+0x2e0/0x580 > > > [ 552.794273] process_one_work+0x60c/0xf04 [ 552.798292] > > > worker_thread+0x3bc/0xe1c [ 552.802056] kthread+0x278/0x2e0 [ > > > 552.805295] ret_from_fork+0x10/0x20 [ 552.808883] [ 552.810380] > > > Second to last potentially related work creation: > > > [ 552.816133] kasan_save_stack+0x2c/0x54 [ 552.819984] > > > __kasan_record_aux_stack+0xa0/0xd0 > > > [ 552.824526] kasan_record_aux_stack_noalloc+0x14/0x20 > > > [ 552.829592] __queue_work+0x428/0xd14 [ 552.833264] > > > delayed_work_timer_fn+0x68/0xa0 [ 552.837546] > > > call_timer_fn.constprop.0+0x54/0x15c > > > [ 552.842269] __run_timers.part.0+0x3f4/0x604 [ 552.846553] > > > run_timer_softirq+0x78/0x110 [ 552.850580] _stext+0x29c/0x7d8 [ > > > 552.853734] [ 552.855229] The buggy address belongs to the object at > > > ffff0000126da000 [ 552.855229] which belongs to the cache kmalloc-2k > > > of size 2048 [ 552.867759] The buggy address is located 1392 bytes > > > inside of [ 552.867759] 2048-byte region [ffff0000126da000, > > > ffff0000126da800) [ 552.879683] [ 552.881180] The buggy address > > > belongs to the physical page: > > > [ 552.886761] page:00000000bc19f159 refcount:1 mapcount:0 > > > mapping:0000000000000000 index:0x0 pfn:0x526d8 [ 552.896083] > > > head:00000000bc19f159 order:3 compound_mapcount:0 > > compound_pincount:0 > > > [ 552.903576] flags: > > > 0x3fffc0000010200(slab|head|node=0|zone=0|lastcpupid=0xffff) > > > [ 552.910910] raw: 03fffc0000010200 dead000000000100 > > dead000000000122 > > > ffff000008002900 [ 552.918663] raw: 0000000000000000 > > 0000000080080008 > > > 00000001ffffffff 0000000000000000 [ 552.926413] page dumped because: > > > kasan: bad access detected [ 552.931989] [ 552.933486] Memory state > > > around the buggy address: > > > [ 552.938285] ffff0000126da400: fb fb fb fb fb fb fb fb fb fb fb fb > > > fb fb fb fb [ 552.945518] ffff0000126da480: fb fb fb fb fb fb fb fb > > > fb fb fb fb fb fb fb fb [ 552.952752] >ffff0000126da500: fb fb fb fb fb fb fb > > fb fb fb fb fb fb fb fb fb > > > [ 552.959980] ^ > > > [ 552.966862] ffff0000126da580: fb fb fb fb fb fb fb fb fb fb fb fb > > > fb fb fb fb [ 552.974093] ffff0000126da600: fb fb fb fb fb fb fb fb > > > fb fb fb fb fb fb fb fb [ 552.981323] > > > > > ================================================================ > > == > > > [ 552.988700] Disabling lock debugging due to kernel taint [ > > > 552.994223] hci0 hcon 00000000c12ea080 handle 65535 [ 552.994267] > > > Unable to handle kernel paging request at virtual address > > > 00078024e000003b [ 553.007176] Mem abort info: > > > [ 553.009986] ESR = 0x96000004 > > > [ 553.013078] EC = 0x25: DABT (current EL), IL = 32 bits > > > [ 553.018460] SET = 0, FnV = 0 > > > [ 553.021615] EA = 0, S1PTW = 0 > > > [ 553.024845] FSC = 0x04: level 0 translation fault > > > [ 553.029772] Data abort info: > > > [ 553.032726] ISV = 0, ISS = 0x00000004 > > > [ 553.036617] CM = 0, WnR = 0 > > > [ 553.039651] [00078024e000003b] address between user and kernel > > > address ranges [ 553.046850] Internal error: Oops: 96000004 [#1] > > > PREEMPT SMP [ 553.052450] Modules linked in: moal(O) mlan(O) > > > [ 553.056948] CPU: 3 PID: 73 Comm: kworker/u9:0 Tainted: G B O > > 5.17.0-rc8-next-20220315-00001-g7c4f5ebecd82-dirty #245 > > > [ 553.056965] Hardware name: FSL i.MX8MM EVK board (DT) [ > > > 553.056974] Workqueue: hci0 hci_cmd_sync_work [ 553.073677] pstate: > > > 40000005 (nZcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--) [ 553.085004] > > > pc : hci_conn_cleanup+0x128/0x4d4 [ 553.085019] lr : > > > hci_conn_cleanup+0x42c/0x4d4 [ 553.093734] sp : ffff80000d797ae0 [ > > > 553.093740] x29: ffff80000d797ae0 x28: ffff00000e85f938 x27: > > > 0000000000000002 [ 553.104206] x26: 1fffe00001d0bf27 x25: > > > ffff000010a78000 x24: ffff000010a78000 [ 553.104227] x23: > > > dfff800000000000 x22: ffff0000126da0e8 x21: ffff00000f98d000 [ > > > 553.104249] x20: ffff0000126da000 x19: a0400127000001dc x18: > > > 0000000000000000 [ 553.118534] x17: ffff80000ac1f008 x16: > > > ffff80000ac1ed74 x15: 0000000000000007 [ 553.132821] x14: > > > 0000000000000000 x13: 0000000000000007 x12: ffff6000024db41d [ > > > 553.139981] x11: 1fffe000024db41c x10: ffff6000024db41c x9 : > > > dfff800000000000 [ 553.140000] x8 : ffff0000126da0e4 x7 : > > > 0000000000000001 x6 : 0000000000000004 [ 553.154287] x5 : > > ffff0000126da0e4 x4 : 0000000000000000 x3 : ffff80000ab714cc [ 553.154318] > > x2 : 0000000000000001 x1 : 14080024e000003b x0 : dfff800000000000 > > [ 553.168614] Call trace: > > > [ 553.168625] hci_conn_cleanup+0x128/0x4d4 [ 553.175094] > > > hci_conn_del+0x46c/0x4a4 [ 553.178775] > > > hci_le_conn_failed+0x318/0x5a0 [ 553.182970] > > > create_le_conn_complete+0x60/0xb0 [ 553.187425] > > > hci_cmd_sync_work+0x128/0x210 > > > > > > Message from syslogd@ at Fri Nov 19 17:28:03 2021 ... > > > : Internal error: Oops: 96000004 [#1] PREEMPT SMP [ 553.201344] > > > process_one_work+0x60c/0xf04 [ 553.205379] > > worker_thread+0x3bc/0xe1c > > > [ 553.209137] kthread+0x278/0x2e0 [ 553.212378] > > > ret_from_fork+0x10/0x20 [ 553.215973] Code: d343fe61 d2d00000 > > > f2fbffe0 f90006b3 (38e06820) [ 553.222079] ---[ end trace > > > 0000000000000000 ]--- > > > > > > Message from syslogd@ at Fri Nov 19 17:28:03 2021 ... > > > : Code: d343fe61 d2d00000 f2fbffe0 f90006b3 (38e06820) > > > > > > Best regards > > > Sherry > > > > > > > > > -- > > Luiz Augusto von Dentz -- Luiz Augusto von Dentz
