Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

dwc_otg: Probable use-after-free in handle_hc_intr resulting in Oops or SLUB errors #217

Closed
P33M opened this issue Feb 10, 2013 · 21 comments

Comments

@P33M
Copy link
Contributor

P33M commented Feb 10, 2013

My Model A Pi oopses in a reproducible way after a while under the following conditions:

  1. Core SOF interrupts are disabled (due to a single device plugged in with no periodic endpoints)
  2. Occasional USB access - with either control or bulk messages.

This is with latest default kernel.

The problem is most reproducible with my RT5370 wifi dongle whose rt2800_usb driver will periodically do radio link maintenance as dictated by its link quality management (setting gain/speed etc). The problem also occurs at infrequent intervals during a wifi data transfer.

If the device is plugged in via a hub (including the smsc one on a Pi model B) the system no longer Oopses.

First OOPS:

<1>[23717.211305] Unable to handle kernel NULL pointer dereference at virtual address 00000000
<1>[23717.224500] pgd = c0004000
<1>[23717.229450] [00000000] *pgd=00000000
<0>[23717.236017] Internal error: Oops: 17 [#1] PREEMPT ARM
kdb> btc
btc: cpu status: Currently on cpu 0
Available cpus: 0
Stack traceback for pid 2376
0xca996200     2376        2  1    0   R  0xca9964e0 *kworker/u:2
[<c0013a7c>] (unwind_backtrace+0x0/0xf0) from [<c0010f64>] (show_stack+0x10/0x14)
[<c0010f64>] (show_stack+0x10/0x14) from [<c0076700>] (kdb_show_stack+0x3c/0x58)
[<c0076700>] (kdb_show_stack+0x3c/0x58) from [<c00767a4>] (kdb_bt1.isra.0+0x88/0xd0)
[<c00767a4>] (kdb_bt1.isra.0+0x88/0xd0) from [<c0076960>] (kdb_bt+0x174/0x360)
[<c0076960>] (kdb_bt+0x174/0x360) from [<c0074334>] (kdb_parse+0x2b4/0x630)
[<c0074334>] (kdb_parse+0x2b4/0x630) from [<c00769dc>] (kdb_bt+0x1f0/0x360)
[<c00769dc>] (kdb_bt+0x1f0/0x360) from [<c0074334>] (kdb_parse+0x2b4/0x630)
[<c0074334>] (kdb_parse+0x2b4/0x630) from [<c0074f4c>] (kdb_main_loop+0x4d8/0x6fc)
[<c0074f4c>] (kdb_main_loop+0x4d8/0x6fc) from [<c0077500>] (kdb_stub+0x154/0x380)
[<c0077500>] (kdb_stub+0x154/0x380) from [<c006e634>] (kgdb_handle_exception+0x1f8/0x668)
[<c006e634>] (kgdb_handle_exception+0x1f8/0x668) from [<c00131fc>] (kgdb_notify+0x24/0x40)
[<c00131fc>] (kgdb_notify+0x24/0x40) from [<c039b4d4>] (notifier_call_chain+0x44/0x84)
[<c039b4d4>] (notifier_call_chain+0x44/0x84) from [<c039b54c>] (__atomic_notifier_call_chain+0x38/0x4c)
[<c039b54c>] (__atomic_notifier_call_chain+0x38/0x4c) from [<c039b578>] (atomic_notifier_call_chain+0x18/0x20)
[<c039b578>] (atomic_notifier_call_chain+0x18/0x20) from [<c039b5b8>] (notify_die+0x38/0x44)
[<c039b5b8>] (notify_die+0x38/0x44) from [<c001102c>] (die+0xc4/0x39c)
[<c001102c>] (die+0xc4/0x39c) from [<c039430c>] (__do_kernel_fault.part.9+0x54/0x74)
[<c039430c>] (__do_kernel_fault.part.9+0x54/0x74) from [<c039b1e4>] (do_page_fault+0x1e8/0x3ec)
[<c039b1e4>] (do_page_fault+0x1e8/0x3ec) from [<c000832c>] (do_DataAbort+0x34/0x98)
[<c000832c>] (do_DataAbort+0x34/0x98) from [<c03999d8>] (__dabt_svc+0x38/0x60)
Exception stack(0xca99bc88 to 0xca99bcd0)
bc80:                   f3000806 a0000013 00000000 00000000 ca964980 00000000
bca0: ca982850 caa565a0 ca964a80 ca982838 00000000 ca9837c0 00000000 ca99bcd0
bcc0: c029824c c0298260 60000013 ffffffff
[<c03999d8>] (__dabt_svc+0x38/0x60) from [<c0298260>] (dwc_otg_hcd_urb_enqueue+0x70/0x184)
[<c0298260>] (dwc_otg_hcd_urb_enqueue+0x70/0x184) from [<c0298e7c>] (dwc_otg_urb_enqueue+0x21c/0x2f0)
[<c0298e7c>] (dwc_otg_urb_enqueue+0x21c/0x2f0) from [<c0273344>] (usb_hcd_submit_urb+0xbc/0x77c)
[<c0273344>] (usb_hcd_submit_urb+0xbc/0x77c) from [<c0275828>] (usb_start_wait_urb+0x44/0xbc)
[<c0275828>] (usb_start_wait_urb+0x44/0xbc) from [<c0275a54>] (usb_control_msg+0xb4/0xe8)
[<c0275a54>] (usb_control_msg+0xb4/0xe8) from [<bf0bce48>] (rt2x00usb_vendor_request+0x98/0x128 [rt2x00usb])
[<bf0bce48>] (rt2x00usb_vendor_request+0x98/0x128 [rt2x00usb]) from [<bf0bcf6c>] (rt2x00usb_vendor_req_buff_lock+0x60/0x108 [rt2x00usb])
[<bf0bcf6c>] (rt2x00usb_vendor_req_buff_lock+0x60/0x108 [rt2x00usb]) from [<bf0bd13c>] (rt2x00usb_regbusy_read+0x78/0x104 [rt2x00usb])
[<bf0bd13c>] (rt2x00usb_regbusy_read+0x78/0x104 [rt2x00usb]) from [<bf0c4d98>] (rt2800_bbp_read+0x58/0xd4 [rt2800lib])
[<bf0c4d98>] (rt2800_bbp_read+0x58/0xd4 [rt2800lib]) from [<bf0c8234>] (rt2800_config_txpower+0x1ac/0x460 [rt2800lib])
[<bf0c8234>] (rt2800_config_txpower+0x1ac/0x460 [rt2800lib]) from [<bf0ae718>] (rt2x00link_agc+0x28/0x54 [rt2x00lib])
[<bf0ae718>] (rt2x00link_agc+0x28/0x54 [rt2x00lib]) from [<c0035024>] (process_one_work+0x150/0x40c)
[<c0035024>] (process_one_work+0x150/0x40c) from [<c0035604>] (worker_thread+0x150/0x498)
[<c0035604>] (worker_thread+0x150/0x498) from [<c003a7c8>] (kthread+0x88/0x94)
[<c003a7c8>] (kthread+0x88/0x94) from [<c000e9fc>] (kernel_thread_exit+0x0/0x8)
kdb>

I recompiled the kernel with debug info, reproduced the OOPS and traced the exception to line 507 in dwc_otg_hcd.c -

if ((qtd->qh->ep_type == UE_BULK)

For some reason qh (or qtd) ends up null.

This line is only called if SOF interrupts are disabled and the qtd allocation was successful, i.e. if there are no periodic endpoints enabled.

As usual I have reconfigured the kernel to do SLUB debugging with poison/redzone/user checking enabled along with more general debug options. SLUB is reporting a possible use-after-free (which reliably happens on boot):

[  335.227016] =============================================================================
[  335.227053] BUG kmalloc-64 (Not tainted): Poison overwritten
[  335.227063] -----------------------------------------------------------------------------
[  335.227063]
[  335.227082] INFO: 0xc96d8610-0xc96d8610. First byte 0x0 instead of 0x6b
[  335.227131] INFO: Allocated in dwc_otg_hcd_qtd_create+0x1c/0x50 age=184 cpu=0 pid=2480
[  335.227160]  __slab_alloc.isra.46.constprop.48+0x454/0x4b4
[  335.227188]  __kmalloc+0x64/0x100
[  335.227206]  dwc_otg_hcd_qtd_create+0x1c/0x50
[  335.227220]  dwc_otg_hcd_urb_enqueue+0x58/0x18c
[  335.227233]  dwc_otg_urb_enqueue+0x24c/0x2e8
[  335.227264]  usb_hcd_submit_urb+0x69c/0x7d8
[  335.227302]  rt2x00usb_kick_rx_entry+0xa0/0xf4 [rt2x00usb]
[  335.227378]  rt2x00queue_init_queues+0x4c/0x80 [rt2x00lib]
[  335.227413]  rt2x00lib_enable_radio+0x1c/0xc0 [rt2x00lib]
[  335.227442]  rt2x00lib_start+0x98/0xc0 [rt2x00lib]
[  335.227698]  ieee80211_do_open+0x118/0x7d0 [mac80211]
[  335.227718]  __dev_open+0x9c/0x104
[  335.227732]  __dev_change_flags+0xa4/0x130
[  335.227745]  dev_change_flags+0x10/0x44
[  335.227760]  devinet_ioctl+0x304/0x75c
[  335.227784]  sock_ioctl+0x22c/0x284
[  335.227809] INFO: Freed in release_channel+0x124/0x1ec age=59 cpu=0 pid=0
[  335.227828]  __slab_free+0x2c/0x33c
[  335.227843]  release_channel+0x124/0x1ec
[  335.227858]  handle_hc_xfercomp_intr+0x2e0/0x3b4
[  335.227872]  dwc_otg_hcd_handle_hc_n_intr+0x1c4/0x620
[  335.227886]  dwc_otg_hcd_handle_hc_intr+0x54/0x78
[  335.227900]  dwc_otg_hcd_handle_intr+0x100/0x1f4
[  335.227912]  dwc_otg_hcd_irq+0xc/0x18
[  335.227932]  usb_hcd_irq+0x30/0x40
[  335.227958]  handle_irq_event_percpu+0x34/0x190
[  335.227973]  handle_irq_event+0x60/0x80
[  335.227992]  handle_level_irq+0xd4/0x13c
[  335.228006]  generic_handle_irq+0x30/0x48
[  335.228028]  handle_IRQ+0x60/0x80
[  335.228051]  __irq_svc+0x34/0xc8
[  335.228067]  default_idle+0x24/0x2c
[  335.228080]  cpu_idle+0x68/0xb4
[  335.228094] INFO: Slab 0xc0712b00 objects=16 used=16 fp=0x  (null) flags=0x0080
[  335.228106] INFO: Object 0xc96d8600 @offset=1536 fp=0xc96d8400
[  335.228106]
[  335.228127] Bytes b4 c96d85f0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a  ZZZZZZZZZZZZZZZZ
[  335.228142] Object c96d8600: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  kkkkkkkkkkkkkkkk
[  335.228154] Object c96d8610: 00 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  .kkkkkkkkkkkkkkk
[  335.228167] Object c96d8620: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  kkkkkkkkkkkkkkkk
[  335.228180] Object c96d8630: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5  kkkkkkkkkkkkkkk.
[  335.228192] Redzone c96d8640: bb bb bb bb                                      ....
[  335.228205] Padding c96d86e8: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a  ZZZZZZZZZZZZZZZZ
[  335.228217] Padding c96d86f8: 5a 5a 5a 5a 5a 5a 5a 5a                          ZZZZZZZZ
[  335.228262] [<c00138c0>] (unwind_backtrace+0x0/0xf0) from [<c00bbba4>] (check_bytes_and_report+0xb4/0xdc)
[  335.228292] [<c00bbba4>] (check_bytes_and_report+0xb4/0xdc) from [<c00bbc98>] (check_object+0xcc/0x214)
[  335.228321] [<c00bbc98>] (check_object+0xcc/0x214) from [<c0393048>] (alloc_debug_processing+0x88/0x134)
[  335.228351] [<c0393048>] (alloc_debug_processing+0x88/0x134) from [<c0393b4c>] (__slab_alloc.isra.46.constprop.48+0x454/0x4b4)
[  335.228381] [<c0393b4c>] (__slab_alloc.isra.46.constprop.48+0x454/0x4b4) from [<c00bd5b0>] (__kmalloc+0x64/0x100)
[  335.228415] [<c00bd5b0>] (__kmalloc+0x64/0x100) from [<c029b798>] (dwc_otg_hcd_qtd_create+0x30/0x50)
[  335.228443] [<c029b798>] (dwc_otg_hcd_qtd_create+0x30/0x50) from [<c02973cc>] (dwc_otg_hcd_urb_enqueue+0x58/0x18c)
[  335.228468] [<c02973cc>] (dwc_otg_hcd_urb_enqueue+0x58/0x18c) from [<c0298014>] (dwc_otg_urb_enqueue+0x24c/0x2e8)
[  335.228501] [<c0298014>] (dwc_otg_urb_enqueue+0x24c/0x2e8) from [<c0271c84>] (usb_hcd_submit_urb+0x69c/0x7d8)
[  335.228534] [<c0271c84>] (usb_hcd_submit_urb+0x69c/0x7d8) from [<c0273b7c>] (usb_start_wait_urb+0x44/0xb4)
[  335.228557] [<c0273b7c>] (usb_start_wait_urb+0x44/0xb4) from [<c0273db0>] (usb_control_msg+0xc8/0xf4)
[  335.228599] [<c0273db0>] (usb_control_msg+0xc8/0xf4) from [<bf145e58>] (rt2x00usb_vendor_request+0x8c/0x11c [rt2x00usb])
[  335.228647] [<bf145e58>] (rt2x00usb_vendor_request+0x8c/0x11c [rt2x00usb]) from [<bf145fec>] (rt2x00usb_vendor_req_buff_lock+0xcc/0x100 [rt2x00usb])
[  335.228690] [<bf145fec>] (rt2x00usb_vendor_req_buff_lock+0xcc/0x100 [rt2x00usb]) from [<bf146180>] (rt2x00usb_vendor_request_buff+0x64/0xa8 [rt2x00usb])
[  335.228738] [<bf146180>] (rt2x00usb_vendor_request_buff+0x64/0xa8 [rt2x00usb]) from [<bf164030>] (rt2x00usb_register_read+0x30/0x40 [rt2800usb])
[  335.228812] [<bf164030>] (rt2x00usb_register_read+0x30/0x40 [rt2800usb]) from [<bf151274>] (rt2800_config_intf+0xd0/0x21c [rt2800lib])
[  335.228902] [<bf151274>] (rt2800_config_intf+0xd0/0x21c [rt2800lib]) from [<bf1354a4>] (rt2x00lib_config_intf+0x120/0x128 [rt2x00lib])
[  335.228970] [<bf1354a4>] (rt2x00lib_config_intf+0x120/0x128 [rt2x00lib]) from [<bf134a84>] (rt2x00mac_remove_interface+0x84/0x8c [rt2x00lib])
[  335.229196] [<bf134a84>] (rt2x00mac_remove_interface+0x84/0x8c [rt2x00lib]) from [<bf05cc00>] (ieee80211_do_stop+0x3ac/0x5e0 [mac80211])
[  335.229473] [<bf05cc00>] (ieee80211_do_stop+0x3ac/0x5e0 [mac80211]) from [<bf05ce44>] (ieee80211_stop+0x10/0x18 [mac80211])
[  335.229635] [<bf05ce44>] (ieee80211_stop+0x10/0x18 [mac80211]) from [<c02ef784>] (__dev_close_many+0x9c/0xcc)
[  335.229662] [<c02ef784>] (__dev_close_many+0x9c/0xcc) from [<c02ef7dc>] (__dev_close+0x28/0x3c)
[  335.229689] [<c02ef7dc>] (__dev_close+0x28/0x3c) from [<c02f231c>] (__dev_change_flags+0xa4/0x130)
[  335.229715] [<c02f231c>] (__dev_change_flags+0xa4/0x130) from [<c02f2414>] (dev_change_flags+0x10/0x44)
[  335.229741] [<c02f2414>] (dev_change_flags+0x10/0x44) from [<c0346a48>] (devinet_ioctl+0x304/0x75c)
[  335.229774] [<c0346a48>] (devinet_ioctl+0x304/0x75c) from [<c02dd12c>] (sock_ioctl+0x22c/0x284)
[  335.229807] [<c02dd12c>] (sock_ioctl+0x22c/0x284) from [<c00d31a0>] (do_vfs_ioctl+0x578/0x600)
[  335.229833] [<c00d31a0>] (do_vfs_ioctl+0x578/0x600) from [<c00d3260>] (sys_ioctl+0x38/0x5c)
[  335.229862] [<c00d3260>] (sys_ioctl+0x38/0x5c) from [<c000d8a0>] (ret_fast_syscall+0x0/0x30)
[  335.229881] FIX kmalloc-64: Restoring 0xc96d8610-0xc96d8610=0x6b
[  335.229881]
[  335.229897] FIX kmalloc-64: Marking all objects used

I'm somewhat stuck at this point as I've drudged through the transfer complete interrupt handling with no avail.

I got a similar oops when I unplugged a zd1211b device; possibly related:

[   35.172381] Unable to handle kernel paging request at virtual address 6b6b6b9f
[   35.181055] pgd = c0004000
[   35.185035] [6b6b6b9f] *pgd=00000000
[   35.189902] Internal error: Oops: 5 [#1] PREEMPT ARM

Entering kdb (current=0xc05131c8, pid 0) Oops: (null)
due to oops @ 0xc0299bc8

Pid: 0, comm:              swapper
CPU: 0    Not tainted  (3.6.11+ #3)
PC is at handle_hc_nak_intr+0x14/0x14c
LR is at dwc_otg_hcd_handle_hc_n_intr+0x4b4/0x620
pc : [<c0299bc8>]    lr : [<c029a47c>]    psr: 20000193
sp : c0509e48  ip : 00000000  fp : f29805ec
r10: 00000012  r9 : c8946300  r8 : f29805e0
r7 : cabc0380  r6 : cabc0380  r5 : 00000001  r4 : c8946300
r3 : 6b6b6b6b  r2 : f29805e0  r1 : cabdfc60  r0 : cabc0380
Flags: nzCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment kernel
Control: 00c5387d  Table: 0970c008  DAC: 00000017
[<c00138c0>] (unwind_backtrace+0x0/0xf0) from [<c007223c>] (kdb_dumpregs+0x28/0x50)
[<c007223c>] (kdb_dumpregs+0x28/0x50) from [<c0074424>] (kdb_main_loop+0x250/0x750)
[<c0074424>] (kdb_main_loop+0x250/0x750) from [<c0076d60>] (kdb_stub+0x278/0x3d8)
[<c0076d60>] (kdb_stub+0x278/0x3d8) from [<c006e120>] (kgdb_handle_exception+0x41c/0x644)
[<c006e120>] (kgdb_handle_exception+0x41c/0x644) from [<c0013028>] (kgdb_notify+0x28/0x44)
[<c0013028>] (kgdb_notify+0x28/0x44) from [<c03999ec>] (notifier_call_chain+0x44/0x84)
[<c03999ec>] (notifier_call_chain+0x44/0x84) from [<c0399a64>] (__atomic_notifier_call_chain+0x38/0x4c)
[<c0399a64>] (__atomic_notifier_call_chain+0x38/0x4c) from [<c0399a90>] (atomic_notifier_call_chain+0x18/0x20)
[<c0399a90>] (atomic_notifier_call_chain+0x18/0x20) from [<c0399ad0>] (notify_die+0x38/0x44)
[<c0399ad0>] (notify_die+0x38/0x44) from [<c0010e88>] (die+0xe0/0x3ac)
[<c0010e88>] (die+0xe0/0x3ac) from [<c0016d04>] (__do_kernel_fault+0x64/0x84)
[<c0016d04>] (__do_kernel_fault+0x64/0x84) from [<c03998d4>] (do_page_fault+0x37c/0x3ac)
[<c03998d4>] (do_page_fault+0x37c/0x3ac) from [<c0008310>] (do_DataAbort+0x34/0x98)
[<c0008310>] (do_DataAbort+0x34/0x98) from [<c0397ef8>] (__dabt_svc+0x38/0x60)
Exception stack(0xc0509e00 to 0xc0509e48)
9e00: cabc0380 cabdfc60 f29805e0 6b6b6b6b c8946300 00000001 cabc0380 cabc0380
9e20: f29805e0 c8946300 00000012 f29805ec 00000000 c0509e48 c029a47c c0299bc8
9e40: 20000193 ffffffff
[<c0397ef8>] (__dabt_svc+0x38/0x60) from [<c0299bc8>] (handle_hc_nak_intr+0x14/0x14c)
[<c0299bc8>] (handle_hc_nak_intr+0x14/0x14c) from [<c029a47c>] (dwc_otg_hcd_handle_hc_n_intr+0x4b4/0x620)
[<c029a47c>] (dwc_otg_hcd_handle_hc_n_intr+0x4b4/0x620) from [<c029a63c>] (dwc_otg_hcd_handle_hc_intr+0x54/0x78)
[<c029a63c>] (dwc_otg_hcd_handle_hc_intr+0x54/0x78) from [<c029a760>] (dwc_otg_hcd_handle_intr+0x100/0x1f4)
[<c029a760>] (dwc_otg_hcd_handle_intr+0x100/0x1f4) from [<c02980c4>] (dwc_otg_hcd_irq+0xc/0x18)
[<c02980c4>] (dwc_otg_hcd_irq+0xc/0x18) from [<c026fd6c>] (usb_hcd_irq+0x30/0x40)
[<c026fd6c>] (usb_hcd_irq+0x30/0x40) from [<c0077c60>] (handle_irq_event_percpu+0x34/0x190)
[<c0077c60>] (handle_irq_event_percpu+0x34/0x190) from [<c0077e1c>] (handle_irq_event+0x60/0x80)
[<c0077e1c>] (handle_irq_event+0x60/0x80) from [<c0079ee0>] (handle_level_irq+0xd4/0x13c)
[<c0079ee0>] (handle_level_irq+0xd4/0x13c) from [<c0077594>] (generic_handle_irq+0x30/0x48)
[<c0077594>] (generic_handle_irq+0x30/0x48) from [<c000e78c>] (handle_IRQ+0x60/0x80)
[<c000e78c>] (handle_IRQ+0x60/0x80) from [<c0397f54>] (__irq_svc+0x34/0xc8)
[<c0397f54>] (__irq_svc+0x34/0xc8) from [<c000e898>] (default_idle+0x24/0x2c)
[<c000e898>] (default_idle+0x24/0x2c) from [<c000ea24>] (cpu_idle+0x68/0xb4)
[<c000ea24>] (cpu_idle+0x68/0xb4) from [<c04e6730>] (start_kernel+0x290/0x2d8)
more>
kdb>
@P33M
Copy link
Contributor Author

P33M commented Feb 10, 2013

The OOPS is almost certainly a continuation of #190 - this case being brought out into the open on the model A because of the lack of SOF interrupts. The QTD is being freed immediately after interrupts are re-enabled in dwc_otg_qtd_add() which results in either null pointer dereference without SLUB debugging turned on, or a dereference of 0x6b6b6b6b with SLUB debugging enabled.

There is still a use-after-free going on as evidenced by SLUB detecting corruption. Either the qtd or qh structs are being tampered with after freeing - offset 0x10 in each case is:
qh->channel (uint8_t)
qtd->error_count (uint8_t)

I also note the offset 0x3F also has an overwritten byte to A5 - no idea what this is.

Edit: I patched the offending function into a more sane check carried out prior to firing the QTD off into the driver. I will leave the Pi online overnight and see if it falls over.

gist: https://gist.github.com/P33M/b85973e60405bdb1db0d

@popcornmix
Copy link
Collaborator

Interesting. I hope you find a fix.

@P33M
Copy link
Contributor Author

P33M commented Feb 12, 2013

This is what I've gotten so far:

  • Fix incorrect error handling in dwc_otg_hcd_alloc_urb leading to OOPS
  • Fix unsafe access of qtd in dwc_otg_hcd_urb_enqueue leading to potential OOPS
  • Hack: clobber pointers after freeing QTDs and QHs to hide obscure memory corruption bug

This completely solves the first OOPS experienced. It doesn't remove the SLUB poison overwritten though. The hack is just there to narrow the causes down (i.e. eliminate double free)

One clue is that kill_urbs_in_qh will predictably OOPS due to dereferencing freed memory in the non_periodic_sched_active qh list. This is replicated by pulling the USB stick out of the port at just the right time.

gist: https://gist.github.com/P33M/1629b113edcf101aa3f6

@P33M
Copy link
Contributor Author

P33M commented Feb 14, 2013

I've found the cause of the memory corruption (I think).

In dwc_otg_hcd_handle_hc_n_intr, the various halt conditions of a host channel are processed. If a NYET occurs on an non-periodic OUT, the channel is halted with xfercomp and nyet bits set - the driver commentary says:

 * Handles a host channel NYET interrupt. This interrupt should only occur on
 * Bulk and Control OUT endpoints and for complete split transactions. If a
 * NYET occurs at the same time as a Transfer Complete interrupt, it is
 * handled in the xfercomp interrupt handler, not here. This handler may be
 * called in either DMA mode or Slave mode.
 */

but the NYET interrupt isn't cleared by xfercomp. I think this results in the IRQ being re-entrant but with xfercomp cleared and nyet active - which leads to accessing a qtd that doesn't exist because xfercomp removed it. I need to check to see that this is actually happening.

This correlates with the stacktrace associated with the corruption - in most cases it's a control URB that results in the use-after-free.

@popcornmix
Copy link
Collaborator

@P33M
Sounds promising.

@P33M
Copy link
Contributor Author

P33M commented Feb 21, 2013

Found the incorrect QTD access.

In handle_hc_n_intr the execution flow hands off to each interrupt type handler in turn with xfercomp at the top of the queue. The incorrect access happens around line 1589 in dwc_otg_hcd_intr.c (exact lines incorrect as I have added debug statements).

This is presumably because the ACK interrupt fires after Xfercomp as Xfercomp can take up to 500us to complete. This behaviour I have only seen on CONTROL type endpoints where the device spends time processing data - e.g. in my case it is when my RTL5370 chipset finishes loading firmware. In this case I doubt the use-after-free will result in memory corruption as we are in and IRQ and there are no further allocations before handle_ack_intr, however if the ACK interrupt fires after the handler completes...

Issue #205 may be related. If the xfercomp completes and the ACK interrupt then fires with the hc not expecting it, you will get this result. In this case it is certain that kernel memory is corrupt because the QTD circleq will be empty and no check is made before accessing the QTD.

@P33M
Copy link
Contributor Author

P33M commented Feb 21, 2013

Note that #217 (comment) is hogwash - NYET is handled correctly as far as I can tell.

As for a bugfix - there seems to be a few of these arbitrary qtd->error_count = 0 statements scattered throughout the code. In general the entire file is an exercise in how not to write an interrupt handler due to the extremely scattered and convoluted call graph, overall SLOC, calls to freeing memory etc, etc. Therefore just bludgeoning in for a fix for laggy hardware would be fraught with danger.

I will be back from my current field job at the weekend and will have more time to think on a solution.

Suggestions, anyone?

@ghollingworth
Copy link

ghollingworth commented Feb 21, 2013

I've found another terrible bit of code that also means that it's possible to end up with a null qtr pointer when you go to schedule a transaction… Turns out the driver does the following:

add_qtd(qh, qtd)
{
if(schedule_periodic(qh))
{
// Interrupt occurs here and tries to access qh->qtr before we've set it!
qh->qtd = qtd;
}
}

Unfortunately schedule periodic also enables the start of frame interrupt which then means the SOF interrupt occurs and tries to actually access the qh->qtd structure before we've filled it in!

I think the changes I've got so far for my FIQ implementation means that now I'm just doing it all a lot quicker which in turn means I'm more likely to hit the problem!

More hacking ensues….

Gordon

Gordon Hollingworth, Director of Engineering

On 21 Feb 2013, at 11:39, P33M notifications@github.com wrote:

Note that #217 is hogwash - NYET is handled correctly as far as I can tell.

As for a bugfix - there seems to be a few of these arbitrary qtd->error_count = 0 statements scattered throughout the code. In general the entire file is an exercise in how not to write an interrupt handler due to the extremely scattered and convoluted call graph, overall SLOC, calls to freeing memory etc, etc. Therefore just bludgeoning in for a fix for laggy hardware would be fraught with danger.

I will be back from my current field job at the weekend and will have more time to think on a solution.

Suggestions, anyone?


Reply to this email directly or view it on GitHub.

@P33M
Copy link
Contributor Author

P33M commented Feb 21, 2013

OK... I'm getting these with IN endpoints (both BULK and CONTROL) on my RTL5370 - why on earth does the hardware generate an interrupt on an IN endpoint after it's already interrupted that the transaction is complete?

@P33M
Copy link
Contributor Author

P33M commented Feb 23, 2013

Eurgh. I've uncovered yet more bugs while attempting to pin down this one.

Those issues aside, I've determined the following:

  • dwc_otg: Probable use-after-free in handle_hc_intr resulting in Oops or SLUB errors #217 (comment) is bollocks
  • the incorrect QTD access happens if and only if the ack and chhltd interrupts fire at the same time
  • chhltd is cleared by default in the driver unless it is the only interrupt to have fired. Presumably something to do with DMA mode.
  • in several of the cases I have seen, the qtd list is not empty when the incorrect access occurs. Just the first qtd in the circleq references freed memory.
  • The IRQ is not being re-entrant as the xfercomp handler takes the time to clear and disable all other pending interrupts.
  • The ack is not spurious - I added register writes to clear all pending interrupts, masked or not, on allocation of a hc to a channel (i.e. re-use a channel) and got the same result.

What I am unable to determine is the phase in the transaction upon which this odd bug occurs. It's most definitely not after the transfer is completed and the hc is disabled.

@P33M
Copy link
Contributor Author

P33M commented Feb 23, 2013

It would be possible to elastoplast this one like so:

diff --git a/drivers/usb/host/dwc_otg/dwc_otg_hcd_intr.c b/drivers/usb/host/dwc_otg_hcd_intr.c
index e8c91e7..b911995 100644
--- a/drivers/usb/host/dwc_otg/dwc_otg_hcd_intr.c
+++ b/drivers/usb/host/dwc_otg/dwc_otg_hcd_intr.c
@@ -1571,7 +1571,8 @@ static int32_t handle_hc_ack_intr(dwc_otg_hcd_t * hcd,
                        halt_channel(hcd, hc, qtd, DWC_OTG_HC_XFER_ACK);
                }
        } else {
-               qtd->error_count = 0;
+               if(!hc->ep_is_in || !dwc_qh_is_non_per(hc->qh))
+                       qtd->error_count = 0;

                if (hc->qh->ping_state) {
                        hc->qh->ping_state = 0;

This at least solves the specific case of memory corruption picked up by SLUB in my case.

@P33M
Copy link
Contributor Author

P33M commented Feb 25, 2013

Apologies for the steadily decreasing signal to noise ratio of this thread but yet more info:

This is hardware wierdness. After tracing the actual interrupt servicing it appears that the ACK interrupt is being raised after a transfer complete interrupt despite the hc's interrupts being cleared and masked!

This only occurs on (non-split) transfers which have previously halted in an error state, in my case I get a reproducible xacterr interrupt with my RTL5370 on cold boot for 2 IN transactions. If a transaction has previously bombed out, when requeued the ACK interrupt is unmasked and in theory used to reset the error count. If the xfercomp is subsequently triggered on the last packet in a transaction the QTD ends up being freed by xfercomp and the resulting re-entry into the IRQ will result in a freed byte being overwritten to 0x00. If the interrupts were happening around the time where something else was allocating memory this could result in corruption.

Basically, by the time we actually get to the ACK interrupt handler both the interrupt and mask reg do in fact read 0x0000000, but during the top-level re-entry it looks like the register write hasn't taken hold:

[   29.385696] xacterr on hcnum:2 ep_type:Bulk direction:IN
[   29.385732] hc_init: Nonzero QTD error count:1 EP type:Bulk Direction:IN assigned hcnum:4
[   29.385746] hc_init: ACK enabled due to error state on hcnum:4
[   29.385756] hc_init: DATATGLERR enabled due to error state on IN hcnum:4
[   29.385764] hc_init: NAK enabled due to error state on non-intr hcnum:4
[   29.466279] hc_n_intr: ack! hcnum:4 hcint:0x00000022 hcintmsk:0x00000426
[   29.466416] handle_ack: ACK! freed qtd detected num:4 ep_type:Bulk direction:IN
[   29.466435] handle_ack: ACK! hcint:0x00000000 hcintmsk:0x00000000

The state of the mask at the hc_n_intr level is as expected for a error-prone bulk IN endpoint prior to the channel being disabled, but a scant few function calls later the hcint register is mysteriously 0x00000000, as it should be after an xfercomp has completed and disabled the hc.

@ghollingworth
Copy link

ghollingworth commented Feb 25, 2013

This is interesting, I've seen something similar in the FIQ processing I'm doing now, where I actually run through the FIQ twice for each interrupt even though at the end I write a mask to clear the interrupt and read it back to check the value.

Added memory barriers to no avail… I could do with provoking the problem in a small test application (i.e. an RTOS app like uboot) so that I can get the Broadcom guys to run a sim of the chip to see what's happening.

My assumption is that this is likely to do with some asynchronous clocking which means that although the mask is removed the interrupt is still pending in some later clocked logic…

Gordon

Gordon Hollingworth, Director of Engineering

On 25 Feb 2013, at 19:48, P33M notifications@github.com wrote:

Apologies for the steadily decreasing signal to noise ratio of this thread but yet more info:

This is hardware wierdness. After tracing the actual interrupt servicing it appears that the ACK interrupt is being raised after a transfer complete interrupt despite the hc's interrupts being cleared and masked!

This only occurs on (non-split) transfers which have previously halted in an error state, in my case I get a reproducible xacterr interrupt with my RTL5370 on cold boot for 2 IN transactions. If a transaction has previously bombed out, when requeued the ACK interrupt is unmasked and in theory used to reset the error count. If the xfercomp is subsequently triggered on the last packet in a transaction the QTD ends up being freed by xfercomp and the resulting re-entry into the IRQ will result in a freed byte being overwritten to 0x00. If the interrupts were happening around the time where something else was allocating memory this could result in corruption.

Basically, by the time we actually get to the ACK interrupt handler both the interrupt and mask reg do in fact read 0x0000000, but during the top-level re-entry it looks like the register write hasn't taken hold:

[ 29.385696] xacterr on hcnum:2 ep_type:Bulk direction:IN
[ 29.385732] hc_init: Nonzero QTD error count:1 EP type:Bulk Direction:IN assigned hcnum:4
[ 29.385746] hc_init: ACK enabled due to error state on hcnum:4
[ 29.385756] hc_init: DATATGLERR enabled due to error state on IN hcnum:4
[ 29.385764] hc_init: NAK enabled due to error state on non-intr hcnum:4
[ 29.466279] hc_n_intr: ack! hcnum:4 hcint:0x00000022 hcintmsk:0x00000426
[ 29.466416] handle_ack: ACK! freed qtd detected num:4 ep_type:Bulk direction:IN
[ 29.466435] handle_ack: ACK! hcint:0x00000000 hcintmsk:0x00000000
The state of the mask at the hc_n_intr level is as expected for a error-prone bulk IN endpoint prior to the channel being disabled, but a scant few function calls later the hcint register is mysteriously 0x00000000, as it should be after an xfercomp has completed and disabled the hc.


Reply to this email directly or view it on GitHub.

@P33M
Copy link
Contributor Author

P33M commented Feb 25, 2013

There definitely is something screwy happening - if I busy-wait on reading the mask (or hcint) register after the write in hc_cleanup until the result is 0, the loop is never executed (and still spurious ACKs). Similarly if I induce a ridiculously big delay (133us) before the hc_cleanup function returns, I still get spurious ACKs.

@P33M
Copy link
Contributor Author

P33M commented Feb 28, 2013

Welp here's my fix:

This fix relies on the fact that we only hit this incorrect function call because of an unmasked ACK bit being set - conditions in which it is enabled described above. If the channel is already halted then don't do anything, otherwise proceed as normal and reset the error count. ACKs during split transfers result in a call to handle_ack_intr elsewhere in the processing chain. I tried to do this in a way that's the least intrusive to the overall execution flow - messing with this mass of spaghetti will probably only make things worse.

I have tested it on a variety of USB devices 1.1+2.0 both directly connected to a Model A and behind a hub.

As an aside, the processing time for USB transfer completion is something I wish I hadn't looked at - using GPIO profiling to toggle GPIOs when in various interrupt handlers, xfercomp takes anywhere between 20 and 50uS to complete - that means the CPU is spinning inside an interrupt for up to 40% of the remaining microframe!

@P33M
Copy link
Contributor Author

P33M commented Mar 6, 2013

No noise on the forum since this patch pushed - closing issue.

@P33M P33M closed this as completed Mar 6, 2013
popcornmix pushed a commit that referenced this issue Oct 8, 2014
We allocate the cpufreq table after calling rcu_read_lock(),
which disables preemption. This causes scheduling while atomic
warnings. Use GFP_ATOMIC instead of GFP_KERNEL and update for
kcalloc while we're here.

BUG: sleeping function called from invalid context at mm/slub.c:1246
in_atomic(): 0, irqs_disabled(): 0, pid: 80, name: modprobe
5 locks held by modprobe/80:
 #0:  (&dev->mutex){......}, at: [<c050d484>] __driver_attach+0x48/0x98
 #1:  (&dev->mutex){......}, at: [<c050d494>] __driver_attach+0x58/0x98
 #2:  (subsys mutex#5){+.+.+.}, at: [<c050c114>] subsys_interface_register+0x38/0xc8
 #3:  (cpufreq_rwsem){.+.+.+}, at: [<c05a9c8c>] __cpufreq_add_dev.isra.22+0x84/0x92c
 #4:  (rcu_read_lock){......}, at: [<c05ab24c>] dev_pm_opp_init_cpufreq_table+0x18/0x10c
Preemption disabled at:[<  (null)>]   (null)

CPU: 2 PID: 80 Comm: modprobe Not tainted 3.16.0-rc3-next-20140701-00035-g286857f216aa-dirty #217
[<c0214da8>] (unwind_backtrace) from [<c02123f8>] (show_stack+0x10/0x14)
[<c02123f8>] (show_stack) from [<c070141c>] (dump_stack+0x70/0xbc)
[<c070141c>] (dump_stack) from [<c02f4cb0>] (__kmalloc+0x124/0x250)
[<c02f4cb0>] (__kmalloc) from [<c05ab270>] (dev_pm_opp_init_cpufreq_table+0x3c/0x10c)
[<c05ab270>] (dev_pm_opp_init_cpufreq_table) from [<bf000508>] (cpufreq_init+0x48/0x378 [cpufreq_generic])
[<bf000508>] (cpufreq_init [cpufreq_generic]) from [<c05a9e08>] (__cpufreq_add_dev.isra.22+0x200/0x92c)
[<c05a9e08>] (__cpufreq_add_dev.isra.22) from [<c050c160>] (subsys_interface_register+0x84/0xc8)
[<c050c160>] (subsys_interface_register) from [<c05a9494>] (cpufreq_register_driver+0x108/0x2d8)
[<c05a9494>] (cpufreq_register_driver) from [<bf000888>] (generic_cpufreq_probe+0x50/0x74 [cpufreq_generic])
[<bf000888>] (generic_cpufreq_probe [cpufreq_generic]) from [<c050e994>] (platform_drv_probe+0x18/0x48)
[<c050e994>] (platform_drv_probe) from [<c050d1f4>] (driver_probe_device+0x128/0x370)
[<c050d1f4>] (driver_probe_device) from [<c050d4d0>] (__driver_attach+0x94/0x98)
[<c050d4d0>] (__driver_attach) from [<c050b778>] (bus_for_each_dev+0x54/0x88)
[<c050b778>] (bus_for_each_dev) from [<c050c894>] (bus_add_driver+0xe8/0x204)
[<c050c894>] (bus_add_driver) from [<c050dd48>] (driver_register+0x78/0xf4)
[<c050dd48>] (driver_register) from [<c0208870>] (do_one_initcall+0xac/0x1d8)
[<c0208870>] (do_one_initcall) from [<c028b6b4>] (load_module+0x190c/0x21e8)
[<c028b6b4>] (load_module) from [<c028c034>] (SyS_init_module+0xa4/0x110)
[<c028c034>] (SyS_init_module) from [<c020f0c0>] (ret_fast_syscall+0x0/0x48)

Fixes: a0dd7b7 (PM / OPP: Move cpufreq specific OPP functions out of generic OPP library)
Signed-off-by: Stephen Boyd <sboyd@codeaurora.org>
Acked-by: Viresh Kumar <viresh.kumar@linaro.org>
Cc: 3.16+ <stable@vger.kernel.org> # 3.16+
Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
popcornmix pushed a commit that referenced this issue Oct 12, 2014
commit 3c5445c upstream.

We allocate the cpufreq table after calling rcu_read_lock(),
which disables preemption. This causes scheduling while atomic
warnings. Use GFP_ATOMIC instead of GFP_KERNEL and update for
kcalloc while we're here.

BUG: sleeping function called from invalid context at mm/slub.c:1246
in_atomic(): 0, irqs_disabled(): 0, pid: 80, name: modprobe
5 locks held by modprobe/80:
 #0:  (&dev->mutex){......}, at: [<c050d484>] __driver_attach+0x48/0x98
 #1:  (&dev->mutex){......}, at: [<c050d494>] __driver_attach+0x58/0x98
 #2:  (subsys mutex#5){+.+.+.}, at: [<c050c114>] subsys_interface_register+0x38/0xc8
 #3:  (cpufreq_rwsem){.+.+.+}, at: [<c05a9c8c>] __cpufreq_add_dev.isra.22+0x84/0x92c
 #4:  (rcu_read_lock){......}, at: [<c05ab24c>] dev_pm_opp_init_cpufreq_table+0x18/0x10c
Preemption disabled at:[<  (null)>]   (null)

CPU: 2 PID: 80 Comm: modprobe Not tainted 3.16.0-rc3-next-20140701-00035-g286857f216aa-dirty #217
[<c0214da8>] (unwind_backtrace) from [<c02123f8>] (show_stack+0x10/0x14)
[<c02123f8>] (show_stack) from [<c070141c>] (dump_stack+0x70/0xbc)
[<c070141c>] (dump_stack) from [<c02f4cb0>] (__kmalloc+0x124/0x250)
[<c02f4cb0>] (__kmalloc) from [<c05ab270>] (dev_pm_opp_init_cpufreq_table+0x3c/0x10c)
[<c05ab270>] (dev_pm_opp_init_cpufreq_table) from [<bf000508>] (cpufreq_init+0x48/0x378 [cpufreq_generic])
[<bf000508>] (cpufreq_init [cpufreq_generic]) from [<c05a9e08>] (__cpufreq_add_dev.isra.22+0x200/0x92c)
[<c05a9e08>] (__cpufreq_add_dev.isra.22) from [<c050c160>] (subsys_interface_register+0x84/0xc8)
[<c050c160>] (subsys_interface_register) from [<c05a9494>] (cpufreq_register_driver+0x108/0x2d8)
[<c05a9494>] (cpufreq_register_driver) from [<bf000888>] (generic_cpufreq_probe+0x50/0x74 [cpufreq_generic])
[<bf000888>] (generic_cpufreq_probe [cpufreq_generic]) from [<c050e994>] (platform_drv_probe+0x18/0x48)
[<c050e994>] (platform_drv_probe) from [<c050d1f4>] (driver_probe_device+0x128/0x370)
[<c050d1f4>] (driver_probe_device) from [<c050d4d0>] (__driver_attach+0x94/0x98)
[<c050d4d0>] (__driver_attach) from [<c050b778>] (bus_for_each_dev+0x54/0x88)
[<c050b778>] (bus_for_each_dev) from [<c050c894>] (bus_add_driver+0xe8/0x204)
[<c050c894>] (bus_add_driver) from [<c050dd48>] (driver_register+0x78/0xf4)
[<c050dd48>] (driver_register) from [<c0208870>] (do_one_initcall+0xac/0x1d8)
[<c0208870>] (do_one_initcall) from [<c028b6b4>] (load_module+0x190c/0x21e8)
[<c028b6b4>] (load_module) from [<c028c034>] (SyS_init_module+0xa4/0x110)
[<c028c034>] (SyS_init_module) from [<c020f0c0>] (ret_fast_syscall+0x0/0x48)

Fixes: a0dd7b7 (PM / OPP: Move cpufreq specific OPP functions out of generic OPP library)
Signed-off-by: Stephen Boyd <sboyd@codeaurora.org>
Acked-by: Viresh Kumar <viresh.kumar@linaro.org>
Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
anholt pushed a commit to anholt/linux that referenced this issue Jun 18, 2015
 =================================
 [ INFO: inconsistent lock state ]
 4.1.0-rc7+ raspberrypi#217 Tainted: G           O
 ---------------------------------
 inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
 swapper/6/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
  (ext_devt_lock){+.?...}, at: [<ffffffff8143a60c>] blk_free_devt+0x3c/0x70
 {SOFTIRQ-ON-W} state was registered at:
   [<ffffffff810bf6b1>] __lock_acquire+0x461/0x1e70
   [<ffffffff810c1947>] lock_acquire+0xb7/0x290
   [<ffffffff818ac3a8>] _raw_spin_lock+0x38/0x50
   [<ffffffff8143a07d>] blk_alloc_devt+0x6d/0xd0  <-- take the lock in process context
[..]
  [<ffffffff810bf64e>] __lock_acquire+0x3fe/0x1e70
  [<ffffffff810c00ad>] ? __lock_acquire+0xe5d/0x1e70
  [<ffffffff810c1947>] lock_acquire+0xb7/0x290
  [<ffffffff8143a60c>] ? blk_free_devt+0x3c/0x70
  [<ffffffff818ac3a8>] _raw_spin_lock+0x38/0x50
  [<ffffffff8143a60c>] ? blk_free_devt+0x3c/0x70
  [<ffffffff8143a60c>] blk_free_devt+0x3c/0x70    <-- take the lock in softirq
  [<ffffffff8143bfec>] part_release+0x1c/0x50
  [<ffffffff8158edf6>] device_release+0x36/0xb0
  [<ffffffff8145ac2b>] kobject_cleanup+0x7b/0x1a0
  [<ffffffff8145aad0>] kobject_put+0x30/0x70
  [<ffffffff8158f147>] put_device+0x17/0x20
  [<ffffffff8143c29c>] delete_partition_rcu_cb+0x16c/0x180
  [<ffffffff8143c130>] ? read_dev_sector+0xa0/0xa0
  [<ffffffff810e0e0f>] rcu_process_callbacks+0x2ff/0xa90
  [<ffffffff810e0dcf>] ? rcu_process_callbacks+0x2bf/0xa90
  [<ffffffff81067e2e>] __do_softirq+0xde/0x600

Neil sees this in his tests and it also triggers on pmem driver unbind
for the libnvdimm tests.  This fix is on top of an initial fix by Keith
for incorrect usage of mutex_lock() in this path: 2da7809 "block:
Fix dev_t minor allocation lifetime".  Both this and 2da7809 are
candidates for -stable.

Fixes: 2da7809 ("block: Fix dev_t minor allocation lifetime")
Cc: <stable@vger.kernel.org>
Cc: Keith Busch <keith.busch@intel.com>
Reported-by: NeilBrown <neilb@suse.de>
Signed-off-by: Dan Williams <dan.j.williams@intel.com>
Signed-off-by: Jens Axboe <axboe@fb.com>
davet321 pushed a commit to davet321/rpi-linux that referenced this issue Jun 23, 2015
commit 4d66e5e upstream.

 =================================
 [ INFO: inconsistent lock state ]
 4.1.0-rc7+ raspberrypi#217 Tainted: G           O
 ---------------------------------
 inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
 swapper/6/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
  (ext_devt_lock){+.?...}, at: [<ffffffff8143a60c>] blk_free_devt+0x3c/0x70
 {SOFTIRQ-ON-W} state was registered at:
   [<ffffffff810bf6b1>] __lock_acquire+0x461/0x1e70
   [<ffffffff810c1947>] lock_acquire+0xb7/0x290
   [<ffffffff818ac3a8>] _raw_spin_lock+0x38/0x50
   [<ffffffff8143a07d>] blk_alloc_devt+0x6d/0xd0  <-- take the lock in process context
[..]
  [<ffffffff810bf64e>] __lock_acquire+0x3fe/0x1e70
  [<ffffffff810c00ad>] ? __lock_acquire+0xe5d/0x1e70
  [<ffffffff810c1947>] lock_acquire+0xb7/0x290
  [<ffffffff8143a60c>] ? blk_free_devt+0x3c/0x70
  [<ffffffff818ac3a8>] _raw_spin_lock+0x38/0x50
  [<ffffffff8143a60c>] ? blk_free_devt+0x3c/0x70
  [<ffffffff8143a60c>] blk_free_devt+0x3c/0x70    <-- take the lock in softirq
  [<ffffffff8143bfec>] part_release+0x1c/0x50
  [<ffffffff8158edf6>] device_release+0x36/0xb0
  [<ffffffff8145ac2b>] kobject_cleanup+0x7b/0x1a0
  [<ffffffff8145aad0>] kobject_put+0x30/0x70
  [<ffffffff8158f147>] put_device+0x17/0x20
  [<ffffffff8143c29c>] delete_partition_rcu_cb+0x16c/0x180
  [<ffffffff8143c130>] ? read_dev_sector+0xa0/0xa0
  [<ffffffff810e0e0f>] rcu_process_callbacks+0x2ff/0xa90
  [<ffffffff810e0dcf>] ? rcu_process_callbacks+0x2bf/0xa90
  [<ffffffff81067e2e>] __do_softirq+0xde/0x600

Neil sees this in his tests and it also triggers on pmem driver unbind
for the libnvdimm tests.  This fix is on top of an initial fix by Keith
for incorrect usage of mutex_lock() in this path: 2da7809 "block:
Fix dev_t minor allocation lifetime".  Both this and 2da7809 are
candidates for -stable.

Fixes: 2da7809 ("block: Fix dev_t minor allocation lifetime")
Cc: Keith Busch <keith.busch@intel.com>
Reported-by: NeilBrown <neilb@suse.de>
Signed-off-by: Dan Williams <dan.j.williams@intel.com>
Signed-off-by: Jens Axboe <axboe@fb.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
@darbyShaw
Copy link
Contributor

Hi,
I see the following trace for dwc_otg version dwc_otg: version 2.94a 27-OCT-2011 on kernel 3.2.26.
I see that the changes mentioned in above patches already applied:

[ 197.670449] =============================================================================
[ 197.678680] BUG kmalloc-64: Poison overwritten
[ 197.683148] -----------------------------------------------------------------------------
[ 197.683155]
[ 197.692867] INFO: 0xcefb571c-0xcefb571f. First byte 0x0 instead of 0x6b
[ 197.699553] INFO: Allocated in __DWC_ALLOC+0x20/0x24 age=19 cpu=0 pid=11
[ 197.706300] alloc_debug_processing+0x118/0x180
[ 197.710859] __slab_alloc.constprop.58+0x3d8/0x424
[ 197.715694] __kmalloc+0xa8/0x1ac
[ 197.719032] __DWC_ALLOC+0x20/0x24
[ 197.722455] dwc_otg_hcd_qtd_create+0x38/0x54
[ 197.726837] dwc_otg_hcd_urb_enqueue+0x68/0x188
[ 197.731393] urb_enqueue+0x1d0/0x240
[ 197.734992] usb_hcd_submit_urb+0x608/0x6e4
[ 197.739199] usb_submit_urb+0x360/0x39c
[ 197.743093] submit_tx_urb+0x3c/0x88 [btusb]
[ 197.747396] submit_or_queue_tx_urb+0x6c/0x94 [btusb]
[ 197.752481] btusb_send_frame+0x84/0xdc [btusb]
[ 197.757197] hci_send_frame+0x84/0xac [bluetooth]
[ 197.761977] hci_tx_work+0x4ac/0x530 [bluetooth]
[ 197.766641] process_one_work+0x21c/0x3bc
[ 197.770676] worker_thread+0x1bc/0x304
[ 197.774460] INFO: Freed in __DWC_FREE+0x1c/0x20 age=27 cpu=0 pid=11
[ 197.780765] free_debug_processing+0x1b8/0x258
[ 197.785235] __slab_free+0x44/0x284
[ 197.788754] kfree+0x150/0x1a0
[ 197.791829] __DWC_FREE+0x1c/0x20
[ 197.795165] release_channel+0x10c/0x1ac
[ 197.799111] complete_non_periodic_xfer+0x80/0x84
[ 197.803842] handle_hc_xfercomp_intr+0x2d8/0x434
[ 197.808486] dwc_otg_hcd_handle_hc_n_intr+0x1a0/0x544
[ 197.813566] dwc_otg_hcd_handle_hc_intr+0x64/0x78
[ 197.818296] dwc_otg_hcd_handle_intr+0xdc/0x118
[ 197.822851] dwc_otg_hcd_irq+0x1c/0x28
[ 197.826639] usb_hcd_irq+0x48/0x80
[ 197.830067] handle_irq_event_percpu+0x4c/0x200
[ 197.834624] handle_irq_event+0x50/0x70
[ 197.838488] handle_fasteoi_irq+0xdc/0x134
[ 197.842607] generic_handle_irq+0x30/0x40
[ 197.846640] INFO: Slab 0xc11046a0 objects=16 used=16 fp=0x (null) flags=0x0080
[ 197.853987] INFO: Object 0xcefb5700 @offset=1792 fp=0x (null)
[ 197.853993]
[ 197.861350] Bytes b4 cefb56f0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
[ 197.870181] Object cefb5700: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ 197.878839] Object cefb5710: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 00 51 cd cb kkkkkkkkkkkk.Q..
[ 197.887496] Object cefb5720: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ 197.896152] Object cefb5730: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.
[ 197.904809] Redzone cefb5740: bb bb bb bb ....
[ 197.912506] Padding cefb57e8: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
[ 197.921249] Padding cefb57f8: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
[ 197.929293] Backtrace:
[ 197.931813] [] (dump_backtrace+0x0/0x10c) from [] (dump_stack+0x20/0x24)
[ 197.940294] r6:c11046a0 r5:cefb5700 r4:cf802c60 r3:00000018
[ 197.946052] [] (dump_stack+0x0/0x24) from [] (print_trailer+0x130/0x158)
[ 197.954545] [] (print_trailer+0x0/0x158) from [] (check_bytes_and_report+0x94/0xd8)
[ 197.963985] r7:cf802c60 r6:0000006b r5:cefb571c r4:cefb5720
[ 197.969733] [] (check_bytes_and_report+0x0/0xd8) from [] (check_object+0x138/0x240)
[ 197.979184] [] (check_object+0x0/0x240) from [] (alloc_debug_processing+0xf0/0x180)
[ 197.988623] r8:cf8012a0 r7:c0130130 r6:cefb5700 r5:cf802c60 r4:c11046a0
[ 197.995429] [] (alloc_debug_processing+0x0/0x180) from [] (__slab_alloc.constprop.58+0x3d8/0x424)
[ 198.006091] r7:c11046a0 r6:cf802c60 r5:cefb5700 r4:c112c558
[ 198.011841] [] (__slab_alloc.constprop.58+0x0/0x424) from [] (kmem_cache_alloc_trace+0x6c/0x170)
[ 198.022435] [] (kmem_cache_alloc_trace+0x0/0x170) from [] (alloc_nfs_open_context+0x3c/0xe0)
[ 198.032669] [] (alloc_nfs_open_context+0x0/0xe0) from [] (nfs_open+0x3c/0x74)
[ 198.041586] r8:ce9e1280 r7:00000000 r6:cbc88b40 r5:cdc120f0 r4:c0af2240
[ 198.048198] r3:c0ea8390
[ 198.050861] [] (nfs_open+0x0/0x74) from [] (nfs_file_open+0x9c/0xac)
[ 198.058992] r6:00000000 r5:cdc120f0 r4:cbc88b40 r3:00000000
[ 198.064742] [] (nfs_file_open+0x0/0xac) from [] (__dentry_open.isra.14+0x1ec/0x34c)
[ 198.074181] r5:cdc120f0 r4:cbc88b40
[ 198.077810] [] (__dentry_open.isra.14+0x0/0x34c) from [] (nameidata_to_filp+0x48/0x54)
[ 198.087525] [] (nameidata_to_filp+0x0/0x54) from [] (do_last.isra.36+0x590/0x6e0)
[ 198.096791] r6:00000000 r5:00000000 r4:cbd4ded8 r3:00000082
[ 198.102538] [] (do_last.isra.36+0x0/0x6e0) from [] (path_openat+0xcc/0x380)
[ 198.111288] [] (path_openat+0x0/0x380) from [] (do_filp_open+0x3c/0x88)
[ 198.119689] [] (do_filp_open+0x0/0x88) from [] (do_sys_open+0xec/0x184)
[ 198.128081] r7:ffffff9c r6:cf988000 r5:00000001 r4:00000000
[ 198.133826] [] (do_sys_open+0x0/0x184) from [] (sys_open+0x30/0x34)
[ 198.141870] r9:cbd4c000 r8:c000e004 r7:00000005 r6:00000008 r5:0000e955
[ 198.148483] r4:002f5120
[ 198.151152] [] (sys_open+0x0/0x34) from [] (ret_fast_syscall+0x0/0x30)
[ 198.159462] FIX kmalloc-64: Restoring 0xcefb571c-0xcefb571f=0x6b
[ 198.159471]
[ 198.166999] FIX kmalloc-64: Marking all objects used

@P33M
Copy link
Contributor Author

P33M commented May 24, 2017

Why are you using kernel 3.2.26?

@darbyShaw
Copy link
Contributor

One of our devices had 3.2.26. We updated it to 4.1.8 and we still see the same issue.
Here's the backtrace for 4.1.8 kernel.

=============================================================================

BUG kmalloc-64 (Not tainted): Poison overwritten

Disabling lock debugging due to kernel taint
INFO: 0xcd2b6c1c-0xcd2b6c1f. First byte 0x0 instead of 0x6b
INFO: Allocated in __DWC_ALLOC+0x20/0x24 age=30 cpu=0 pid=930
__kmalloc+0xa8/0x1a4
__DWC_ALLOC+0x20/0x24
dwc_otg_hcd_qtd_create+0x34/0x50
dwc_otg_hcd_urb_enqueue+0x68/0x18c
urb_enqueue+0x1a0/0x200
usb_hcd_submit_urb+0x1d0/0x294
usb_submit_urb.part.3+0x3fc/0x42c
usb_submit_urb+0x64/0x84
submit_tx_urb+0x38/0x84 [btusb]
submit_or_queue_tx_urb+0x64/0x9c [btusb]
btusb_send_frame+0xb8/0x118 [btusb]
hci_send_frame+0xcc/0xfc
hci_tx_work+0x6b4/0x77c
process_one_work+0x230/0x3a8
worker_thread+0x2f4/0x448
kthread+0xe8/0xfc
INFO: Freed in __DWC_FREE+0x1c/0x20 age=35 cpu=0 pid=930
kfree+0x170/0x17c
__DWC_FREE+0x1c/0x20
release_channel+0x108/0x1a8
complete_non_periodic_xfer+0x7c/0x80
handle_hc_xfercomp_intr+0x2d0/0x420
dwc_otg_hcd_handle_hc_n_intr+0x1a8/0x554
dwc_otg_hcd_handle_hc_intr+0x64/0x78
dwc_otg_hcd_handle_intr+0xe4/0x120
dwc_otg_hcd_irq+0x1c/0x28
usb_hcd_irq+0x34/0x48
handle_irq_event_percpu+0x80/0x1cc
handle_irq_event+0x54/0x74
handle_fasteoi_irq+0xb0/0x138
generic_handle_irq+0x30/0x40
__handle_domain_irq+0x9c/0xc4
gic_handle_irq+0xf0/0x110
INFO: Slab 0xcdf8f6c0 objects=16 used=16 fp=0x (null) flags=0x0080
INFO: Object 0xcd2b6c00 @offset=3072 fp=0xcd2b6200

Bytes b4 cd2b6bf0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
Object cd2b6c00: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object cd2b6c10: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 00 10 ea cb kkkkkkkkkkkk....
Object cd2b6c20: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object cd2b6c30: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.
Redzone cd2b6c40: bb bb bb bb ....
Padding cd2b6ce8: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ
Padding cd2b6cf8: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
FIX kmalloc-64: Restoring 0xcd2b6c1c-0xcd2b6c1f=0x6b

FIX kmalloc-64: Marking all objects used

@P33M
Copy link
Contributor Author

P33M commented Jun 7, 2017

4.1.8 is not the latest version available in either our Raspbian repositories or via rpi-update. Do you still see this issue with the latest shipped kernel (for information, 4.9.30 via rpi-update, 4.4.24 via Raspbian deb)?

@darbyShaw
Copy link
Contributor

Sorry for the delay. We cannot possibly use kernel-4.9.30 directly since we don't have many of our drivers ported to 4.9.30. We ported them to 4.1.8. Can I accommodate the newest dwc_otg driver to 4.1.8? Also I am looking for ways that help debug this issue.

ED6E0F17 pushed a commit to ED6E0F17/linux that referenced this issue Mar 15, 2018
With 4.11-rc4, the following command triggers a WARN_ON,
when a sink is not enabled.

 perf record -e cs_etm/@20010000.etf/

 [88286.547741] ------------[ cut here ]------------
 [88286.552332] WARNING: CPU: 3 PID: 2156 at kernel/workqueue.c:1442 __queue_work+0x29c/0x3b8
 [88286.560427] Modules linked in:
 [88286.563451]
 [88286.564928] CPU: 3 PID: 2156 Comm: perf_v4.11 Not tainted 4.11.0-rc4 raspberrypi#217
 [88286.573453] Hardware name: ARM LTD ARM Juno Development Platform/ARM Juno Development Platform, BIOS EDK II Aug 15
  2016
 [88286.584128] task: ffff80097597c200 task.stack: ffff8009768b0000
 [88286.589990] PC is at __queue_work+0x29c/0x3b8
 [88286.594303] LR is at __queue_work+0x104/0x3b8
 [88286.598614] pc : [<ffff0000080d8c7c>] lr : [<ffff0000080d8ae4>] pstate: a00001c5
 [88286.605934] sp : ffff8009768b3aa0
 [88286.609212] x29: ffff8009768b3aa0 x28: ffff80097ff3da00
 [88286.614477] x27: ffff80097ff89c00 x26: ffff8009751b0e00
 [88286.619741] x25: ffff000008c9f000 x24: 0000000000000003
 [88286.625004] x23: 0000000000000040 x22: ffff000008d3dab8
 [88286.630268] x21: ffff800977804400 x20: 0000000000000007
 [88286.635532] x19: ffff000008c54000 x18: 0000fffff9185160
 [88286.640795] x17: 0000ffffb33d9a38 x16: ffff000008088270
 [88286.646059] x15: 0000ffffb345b590 x14: 0000000000000000
 [88286.651322] x13: 0000000000000004 x12: 0000000000000040
 [88286.656586] x11: 0000000000000068 x10: 0000000000000000
 [88286.661849] x9 : ffff800977400028 x8 : 0000000000000000
 [88286.667113] x7 : 0000000000000000 x6 : ffff0000080d8ae4
 [88286.672376] x5 : 0000000000000000 x4 : 0000000000000080
 [88286.677639] x3 : 0000000000000000 x2 : 0000000000000000
 [88286.682903] x1 : 0000000000000000 x0 : ffff8009751b0e08
 [88286.688166]
 [88286.689638] ---[ end trace 31633f18fd33d4cb ]---
 [88286.694206] Call trace:
 [88286.696627] Exception stack(0xffff8009768b38d0 to 0xffff8009768b3a00)
 [88286.703004] 38c0:                                   ffff000008c54000 0001000000000000
 [88286.710757] 38e0: ffff8009768b3aa0 ffff0000080d8c7c ffff8009768b3b50 ffff80097ff8a5b0
 [88286.718511] 3900: 0000800977325000 0000000000000000 0000000000000040 ffff80097ffc6180
 [88286.726264] 3920: ffff8009768b3940 ffff0000088a8694 ffff80097ffc5800 0000000000000000
 [88286.734017] 3940: ffff8009768b3960 ffff0000081919c0 ffff80097ffc5280 0000000000000001
 [88286.741771] 3960: ffff8009768b3a50 ffff00000819206c ffff8009751b0e08 0000000000000000
 [88286.749523] 3980: 0000000000000000 0000000000000000 0000000000000080 0000000000000000
 [88286.757277] 39a0: ffff0000080d8ae4 0000000000000000 0000000000000000 ffff800977400028
 [88286.765029] 39c0: 0000000000000000 0000000000000068 0000000000000040 0000000000000004
 [88286.772783] 39e0: 0000000000000000 0000ffffb345b590 ffff000008088270 0000ffffb33d9a38
 [88286.780537] [<ffff0000080d8c7c>] __queue_work+0x29c/0x3b8
 [88286.785883] [<ffff0000080d8df8>] queue_work_on+0x60/0x78
 [88286.791146] [<ffff000008764c68>] etm_setup_aux+0x178/0x238
 [88286.796578] [<ffff000008183600>] rb_alloc_aux+0x228/0x310
 [88286.801925] [<ffff00000817e564>] perf_mmap+0x404/0x5a8
 [88286.807015] [<ffff0000081c60cc>] mmap_region+0x394/0x5c0
 [88286.812276] [<ffff0000081c654c>] do_mmap+0x254/0x388
 [88286.817191] [<ffff0000081a989c>] vm_mmap_pgoff+0xbc/0xe0
 [88286.822452] [<ffff0000081c3ffc>] SyS_mmap_pgoff+0xac/0x228
 [88286.827884] [<ffff000008088288>] sys_mmap+0x18/0x28
 [88286.832714] [<ffff000008082f30>] el0_svc_naked+0x24/0x28

The patch makes sure that the event_data->work is initialised
properly before we could possibly use it.

Cc: Mathieu Poirier <mathieu.poirier@linaro.org>
Signed-off-by: Suzuki K Poulose <suzuki.poulose@arm.com>
Tested-by: Mike Leach <mike.leach@linaro.org>
Signed-off-by: Mathieu Poirier <mathieu.poirier@linaro.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
(cherry picked from commit d755209)

Change-Id: I7a12c9fcf58e5ec2eb5998d0d6cc2cfbef289fcd
nathanchance pushed a commit to nathanchance/pi-kernel that referenced this issue Apr 19, 2018
commit 082f230 upstream.

Local random address needs to be updated before creating connection if
RPA from LE Direct Advertising Report was resolved in host. Otherwise
remote device might ignore connection request due to address mismatch.

This was affecting following qualification test cases:
GAP/CONN/SCEP/BV-03-C, GAP/CONN/GCEP/BV-05-C, GAP/CONN/DCEP/BV-05-C

Before patch:
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6          #11350 [hci0] 84680.231216
        Address: 56:BC:E8:24:11:68 (Resolvable)
          Identity type: Random (0x01)
          Identity: F2:F1:06:3D:9C:42 (Static)
> HCI Event: Command Complete (0x0e) plen 4                        #11351 [hci0] 84680.246022
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7         #11352 [hci0] 84680.246417
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement, inc. directed unresolved RPA (0x02)
> HCI Event: Command Complete (0x0e) plen 4                        #11353 [hci0] 84680.248854
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2             #11354 [hci0] 84680.249466
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                        #11355 [hci0] 84680.253222
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 18                          #11356 [hci0] 84680.458387
      LE Direct Advertising Report (0x0b)
        Num reports: 1
        Event type: Connectable directed - ADV_DIRECT_IND (0x01)
        Address type: Random (0x01)
        Address: 53:38:DA:46:8C:45 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Direct address type: Random (0x01)
        Direct address: 7C:D6:76:8C:DF:82 (Resolvable)
          Identity type: Random (0x01)
          Identity: F2:F1:06:3D:9C:42 (Static)
        RSSI: -74 dBm (0xb6)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2             #11357 [hci0] 84680.458737
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                        #11358 [hci0] 84680.469982
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25          #11359 [hci0] 84680.470444
        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: 53:38:DA:46:8C:45 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Own address type: Random (0x01)
        Min connection interval: 30.00 msec (0x0018)
        Max connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                          #11360 [hci0] 84680.474971
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection Cancel (0x08|0x000e) plen 0    #11361 [hci0] 84682.545385
> HCI Event: Command Complete (0x0e) plen 4                        #11362 [hci0] 84682.551014
      LE Create Connection Cancel (0x08|0x000e) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                          #11363 [hci0] 84682.551074
      LE Connection Complete (0x01)
        Status: Unknown Connection Identifier (0x02)
        Handle: 0
        Role: Master (0x00)
        Peer address type: Public (0x00)
        Peer address: 00:00:00:00:00:00 (OUI 00-00-00)
        Connection interval: 0.00 msec (0x0000)
        Connection latency: 0 (0x0000)
        Supervision timeout: 0 msec (0x0000)
        Master clock accuracy: 0x00

After patch:
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7    raspberrypi#210 [hci0] 667.152459
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement, inc. directed unresolved RPA (0x02)
> HCI Event: Command Complete (0x0e) plen 4                   raspberrypi#211 [hci0] 667.153613
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2        raspberrypi#212 [hci0] 667.153704
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                   raspberrypi#213 [hci0] 667.154584
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 18                     raspberrypi#214 [hci0] 667.182619
      LE Direct Advertising Report (0x0b)
        Num reports: 1
        Event type: Connectable directed - ADV_DIRECT_IND (0x01)
        Address type: Random (0x01)
        Address: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Direct address type: Random (0x01)
        Direct address: 7C:C1:57:A5:B7:A8 (Resolvable)
          Identity type: Random (0x01)
          Identity: F4:28:73:5D:38:B0 (Static)
        RSSI: -70 dBm (0xba)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2       raspberrypi#215 [hci0] 667.182704
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                  raspberrypi#216 [hci0] 667.183599
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6    raspberrypi#217 [hci0] 667.183645
        Address: 7C:C1:57:A5:B7:A8 (Resolvable)
          Identity type: Random (0x01)
          Identity: F4:28:73:5D:38:B0 (Static)
> HCI Event: Command Complete (0x0e) plen 4                  raspberrypi#218 [hci0] 667.184590
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25    raspberrypi#219 [hci0] 667.184613
        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: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Own address type: Random (0x01)
        Min connection interval: 30.00 msec (0x0018)
        Max connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                    raspberrypi#220 [hci0] 667.186558
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                    raspberrypi#221 [hci0] 667.485824
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 0
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Master clock accuracy: 0x07
@ MGMT Event: Device Connected (0x000b) plen 13          {0x0002} [hci0] 667.485996
        LE Address: 11:22:33:44:55:66 (OUI 11-22-33)
        Flags: 0x00000000
        Data length: 0

Signed-off-by: Szymon Janc <szymon.janc@codecoup.pl>
Signed-off-by: Marcel Holtmann <marcel@holtmann.org>
Cc: stable@vger.kernel.org
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Apr 26, 2018
commit 082f230 upstream.

Local random address needs to be updated before creating connection if
RPA from LE Direct Advertising Report was resolved in host. Otherwise
remote device might ignore connection request due to address mismatch.

This was affecting following qualification test cases:
GAP/CONN/SCEP/BV-03-C, GAP/CONN/GCEP/BV-05-C, GAP/CONN/DCEP/BV-05-C

Before patch:
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6          #11350 [hci0] 84680.231216
        Address: 56:BC:E8:24:11:68 (Resolvable)
          Identity type: Random (0x01)
          Identity: F2:F1:06:3D:9C:42 (Static)
> HCI Event: Command Complete (0x0e) plen 4                        #11351 [hci0] 84680.246022
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7         #11352 [hci0] 84680.246417
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement, inc. directed unresolved RPA (0x02)
> HCI Event: Command Complete (0x0e) plen 4                        #11353 [hci0] 84680.248854
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2             #11354 [hci0] 84680.249466
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                        #11355 [hci0] 84680.253222
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 18                          #11356 [hci0] 84680.458387
      LE Direct Advertising Report (0x0b)
        Num reports: 1
        Event type: Connectable directed - ADV_DIRECT_IND (0x01)
        Address type: Random (0x01)
        Address: 53:38:DA:46:8C:45 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Direct address type: Random (0x01)
        Direct address: 7C:D6:76:8C:DF:82 (Resolvable)
          Identity type: Random (0x01)
          Identity: F2:F1:06:3D:9C:42 (Static)
        RSSI: -74 dBm (0xb6)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2             #11357 [hci0] 84680.458737
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                        #11358 [hci0] 84680.469982
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25          #11359 [hci0] 84680.470444
        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: 53:38:DA:46:8C:45 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Own address type: Random (0x01)
        Min connection interval: 30.00 msec (0x0018)
        Max connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                          #11360 [hci0] 84680.474971
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection Cancel (0x08|0x000e) plen 0    #11361 [hci0] 84682.545385
> HCI Event: Command Complete (0x0e) plen 4                        #11362 [hci0] 84682.551014
      LE Create Connection Cancel (0x08|0x000e) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                          #11363 [hci0] 84682.551074
      LE Connection Complete (0x01)
        Status: Unknown Connection Identifier (0x02)
        Handle: 0
        Role: Master (0x00)
        Peer address type: Public (0x00)
        Peer address: 00:00:00:00:00:00 (OUI 00-00-00)
        Connection interval: 0.00 msec (0x0000)
        Connection latency: 0 (0x0000)
        Supervision timeout: 0 msec (0x0000)
        Master clock accuracy: 0x00

After patch:
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7    #210 [hci0] 667.152459
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement, inc. directed unresolved RPA (0x02)
> HCI Event: Command Complete (0x0e) plen 4                   #211 [hci0] 667.153613
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2        #212 [hci0] 667.153704
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                   #213 [hci0] 667.154584
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 18                     #214 [hci0] 667.182619
      LE Direct Advertising Report (0x0b)
        Num reports: 1
        Event type: Connectable directed - ADV_DIRECT_IND (0x01)
        Address type: Random (0x01)
        Address: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Direct address type: Random (0x01)
        Direct address: 7C:C1:57:A5:B7:A8 (Resolvable)
          Identity type: Random (0x01)
          Identity: F4:28:73:5D:38:B0 (Static)
        RSSI: -70 dBm (0xba)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2       #215 [hci0] 667.182704
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                  #216 [hci0] 667.183599
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6    #217 [hci0] 667.183645
        Address: 7C:C1:57:A5:B7:A8 (Resolvable)
          Identity type: Random (0x01)
          Identity: F4:28:73:5D:38:B0 (Static)
> HCI Event: Command Complete (0x0e) plen 4                  #218 [hci0] 667.184590
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25    #219 [hci0] 667.184613
        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: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Own address type: Random (0x01)
        Min connection interval: 30.00 msec (0x0018)
        Max connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                    #220 [hci0] 667.186558
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                    #221 [hci0] 667.485824
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 0
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Master clock accuracy: 0x07
@ MGMT Event: Device Connected (0x000b) plen 13          {0x0002} [hci0] 667.485996
        LE Address: 11:22:33:44:55:66 (OUI 11-22-33)
        Flags: 0x00000000
        Data length: 0

Signed-off-by: Szymon Janc <szymon.janc@codecoup.pl>
Signed-off-by: Marcel Holtmann <marcel@holtmann.org>
Cc: stable@vger.kernel.org
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue May 5, 2018
commit 082f230 upstream.

Local random address needs to be updated before creating connection if
RPA from LE Direct Advertising Report was resolved in host. Otherwise
remote device might ignore connection request due to address mismatch.

This was affecting following qualification test cases:
GAP/CONN/SCEP/BV-03-C, GAP/CONN/GCEP/BV-05-C, GAP/CONN/DCEP/BV-05-C

Before patch:
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6          #11350 [hci0] 84680.231216
        Address: 56:BC:E8:24:11:68 (Resolvable)
          Identity type: Random (0x01)
          Identity: F2:F1:06:3D:9C:42 (Static)
> HCI Event: Command Complete (0x0e) plen 4                        #11351 [hci0] 84680.246022
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7         #11352 [hci0] 84680.246417
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement, inc. directed unresolved RPA (0x02)
> HCI Event: Command Complete (0x0e) plen 4                        #11353 [hci0] 84680.248854
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2             #11354 [hci0] 84680.249466
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                        #11355 [hci0] 84680.253222
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 18                          #11356 [hci0] 84680.458387
      LE Direct Advertising Report (0x0b)
        Num reports: 1
        Event type: Connectable directed - ADV_DIRECT_IND (0x01)
        Address type: Random (0x01)
        Address: 53:38:DA:46:8C:45 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Direct address type: Random (0x01)
        Direct address: 7C:D6:76:8C:DF:82 (Resolvable)
          Identity type: Random (0x01)
          Identity: F2:F1:06:3D:9C:42 (Static)
        RSSI: -74 dBm (0xb6)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2             #11357 [hci0] 84680.458737
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                        #11358 [hci0] 84680.469982
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25          #11359 [hci0] 84680.470444
        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: 53:38:DA:46:8C:45 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Own address type: Random (0x01)
        Min connection interval: 30.00 msec (0x0018)
        Max connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                          #11360 [hci0] 84680.474971
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection Cancel (0x08|0x000e) plen 0    #11361 [hci0] 84682.545385
> HCI Event: Command Complete (0x0e) plen 4                        #11362 [hci0] 84682.551014
      LE Create Connection Cancel (0x08|0x000e) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                          #11363 [hci0] 84682.551074
      LE Connection Complete (0x01)
        Status: Unknown Connection Identifier (0x02)
        Handle: 0
        Role: Master (0x00)
        Peer address type: Public (0x00)
        Peer address: 00:00:00:00:00:00 (OUI 00-00-00)
        Connection interval: 0.00 msec (0x0000)
        Connection latency: 0 (0x0000)
        Supervision timeout: 0 msec (0x0000)
        Master clock accuracy: 0x00

After patch:
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7    #210 [hci0] 667.152459
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Random (0x01)
        Filter policy: Accept all advertisement, inc. directed unresolved RPA (0x02)
> HCI Event: Command Complete (0x0e) plen 4                   #211 [hci0] 667.153613
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2        #212 [hci0] 667.153704
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                   #213 [hci0] 667.154584
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 18                     #214 [hci0] 667.182619
      LE Direct Advertising Report (0x0b)
        Num reports: 1
        Event type: Connectable directed - ADV_DIRECT_IND (0x01)
        Address type: Random (0x01)
        Address: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Direct address type: Random (0x01)
        Direct address: 7C:C1:57:A5:B7:A8 (Resolvable)
          Identity type: Random (0x01)
          Identity: F4:28:73:5D:38:B0 (Static)
        RSSI: -70 dBm (0xba)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2       #215 [hci0] 667.182704
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                  #216 [hci0] 667.183599
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6    #217 [hci0] 667.183645
        Address: 7C:C1:57:A5:B7:A8 (Resolvable)
          Identity type: Random (0x01)
          Identity: F4:28:73:5D:38:B0 (Static)
> HCI Event: Command Complete (0x0e) plen 4                  #218 [hci0] 667.184590
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25    #219 [hci0] 667.184613
        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: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Own address type: Random (0x01)
        Min connection interval: 30.00 msec (0x0018)
        Max connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                    #220 [hci0] 667.186558
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                    #221 [hci0] 667.485824
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 0
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: 50:52:D9:A6:48:A0 (Resolvable)
          Identity type: Public (0x00)
          Identity: 11:22:33:44:55:66 (OUI 11-22-33)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Master clock accuracy: 0x07
@ MGMT Event: Device Connected (0x000b) plen 13          {0x0002} [hci0] 667.485996
        LE Address: 11:22:33:44:55:66 (OUI 11-22-33)
        Flags: 0x00000000
        Data length: 0

Signed-off-by: Szymon Janc <szymon.janc@codecoup.pl>
Signed-off-by: Marcel Holtmann <marcel@holtmann.org>
Cc: stable@vger.kernel.org
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Jan 25, 2021
While testing the error paths of relocation I hit the following lockdep
splat:

  ======================================================
  WARNING: possible circular locking dependency detected
  5.10.0-rc6+ #217 Not tainted
  ------------------------------------------------------
  mount/779 is trying to acquire lock:
  ffffa0e676945418 (&fs_info->balance_mutex){+.+.}-{3:3}, at: btrfs_recover_balance+0x2f0/0x340

  but task is already holding lock:
  ffffa0e60ee31da8 (btrfs-root-00){++++}-{3:3}, at: __btrfs_tree_read_lock+0x27/0x100

  which lock already depends on the new lock.

  the existing dependency chain (in reverse order) is:

  -> #2 (btrfs-root-00){++++}-{3:3}:
	 down_read_nested+0x43/0x130
	 __btrfs_tree_read_lock+0x27/0x100
	 btrfs_read_lock_root_node+0x31/0x40
	 btrfs_search_slot+0x462/0x8f0
	 btrfs_update_root+0x55/0x2b0
	 btrfs_drop_snapshot+0x398/0x750
	 clean_dirty_subvols+0xdf/0x120
	 btrfs_recover_relocation+0x534/0x5a0
	 btrfs_start_pre_rw_mount+0xcb/0x170
	 open_ctree+0x151f/0x1726
	 btrfs_mount_root.cold+0x12/0xea
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 vfs_kern_mount.part.0+0x71/0xb0
	 btrfs_mount+0x10d/0x380
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 path_mount+0x433/0xc10
	 __x64_sys_mount+0xe3/0x120
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  -> #1 (sb_internal#2){.+.+}-{0:0}:
	 start_transaction+0x444/0x700
	 insert_balance_item.isra.0+0x37/0x320
	 btrfs_balance+0x354/0xf40
	 btrfs_ioctl_balance+0x2cf/0x380
	 __x64_sys_ioctl+0x83/0xb0
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  -> #0 (&fs_info->balance_mutex){+.+.}-{3:3}:
	 __lock_acquire+0x1120/0x1e10
	 lock_acquire+0x116/0x370
	 __mutex_lock+0x7e/0x7b0
	 btrfs_recover_balance+0x2f0/0x340
	 open_ctree+0x1095/0x1726
	 btrfs_mount_root.cold+0x12/0xea
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 vfs_kern_mount.part.0+0x71/0xb0
	 btrfs_mount+0x10d/0x380
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 path_mount+0x433/0xc10
	 __x64_sys_mount+0xe3/0x120
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  other info that might help us debug this:

  Chain exists of:
    &fs_info->balance_mutex --> sb_internal#2 --> btrfs-root-00

   Possible unsafe locking scenario:

	 CPU0                    CPU1
	 ----                    ----
    lock(btrfs-root-00);
				 lock(sb_internal#2);
				 lock(btrfs-root-00);
    lock(&fs_info->balance_mutex);

   *** DEADLOCK ***

  2 locks held by mount/779:
   #0: ffffa0e60dc040e0 (&type->s_umount_key#47/1){+.+.}-{3:3}, at: alloc_super+0xb5/0x380
   #1: ffffa0e60ee31da8 (btrfs-root-00){++++}-{3:3}, at: __btrfs_tree_read_lock+0x27/0x100

  stack backtrace:
  CPU: 0 PID: 779 Comm: mount Not tainted 5.10.0-rc6+ #217
  Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
  Call Trace:
   dump_stack+0x8b/0xb0
   check_noncircular+0xcf/0xf0
   ? trace_call_bpf+0x139/0x260
   __lock_acquire+0x1120/0x1e10
   lock_acquire+0x116/0x370
   ? btrfs_recover_balance+0x2f0/0x340
   __mutex_lock+0x7e/0x7b0
   ? btrfs_recover_balance+0x2f0/0x340
   ? btrfs_recover_balance+0x2f0/0x340
   ? rcu_read_lock_sched_held+0x3f/0x80
   ? kmem_cache_alloc_trace+0x2c4/0x2f0
   ? btrfs_get_64+0x5e/0x100
   btrfs_recover_balance+0x2f0/0x340
   open_ctree+0x1095/0x1726
   btrfs_mount_root.cold+0x12/0xea
   ? rcu_read_lock_sched_held+0x3f/0x80
   legacy_get_tree+0x30/0x50
   vfs_get_tree+0x28/0xc0
   vfs_kern_mount.part.0+0x71/0xb0
   btrfs_mount+0x10d/0x380
   ? __kmalloc_track_caller+0x2f2/0x320
   legacy_get_tree+0x30/0x50
   vfs_get_tree+0x28/0xc0
   ? capable+0x3a/0x60
   path_mount+0x433/0xc10
   __x64_sys_mount+0xe3/0x120
   do_syscall_64+0x33/0x40
   entry_SYSCALL_64_after_hwframe+0x44/0xa9

This is straightforward to fix, simply release the path before we setup
the balance_ctl.

CC: stable@vger.kernel.org # 4.4+
Reviewed-by: Qu Wenruo <wqu@suse.com>
Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
Signed-off-by: Josef Bacik <josef@toxicpanda.com>
Reviewed-by: David Sterba <dsterba@suse.com>
Signed-off-by: David Sterba <dsterba@suse.com>
popcornmix pushed a commit that referenced this issue Jan 27, 2021
commit fb28610 upstream.

While testing the error paths of relocation I hit the following lockdep
splat:

  ======================================================
  WARNING: possible circular locking dependency detected
  5.10.0-rc6+ #217 Not tainted
  ------------------------------------------------------
  mount/779 is trying to acquire lock:
  ffffa0e676945418 (&fs_info->balance_mutex){+.+.}-{3:3}, at: btrfs_recover_balance+0x2f0/0x340

  but task is already holding lock:
  ffffa0e60ee31da8 (btrfs-root-00){++++}-{3:3}, at: __btrfs_tree_read_lock+0x27/0x100

  which lock already depends on the new lock.

  the existing dependency chain (in reverse order) is:

  -> #2 (btrfs-root-00){++++}-{3:3}:
	 down_read_nested+0x43/0x130
	 __btrfs_tree_read_lock+0x27/0x100
	 btrfs_read_lock_root_node+0x31/0x40
	 btrfs_search_slot+0x462/0x8f0
	 btrfs_update_root+0x55/0x2b0
	 btrfs_drop_snapshot+0x398/0x750
	 clean_dirty_subvols+0xdf/0x120
	 btrfs_recover_relocation+0x534/0x5a0
	 btrfs_start_pre_rw_mount+0xcb/0x170
	 open_ctree+0x151f/0x1726
	 btrfs_mount_root.cold+0x12/0xea
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 vfs_kern_mount.part.0+0x71/0xb0
	 btrfs_mount+0x10d/0x380
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 path_mount+0x433/0xc10
	 __x64_sys_mount+0xe3/0x120
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  -> #1 (sb_internal#2){.+.+}-{0:0}:
	 start_transaction+0x444/0x700
	 insert_balance_item.isra.0+0x37/0x320
	 btrfs_balance+0x354/0xf40
	 btrfs_ioctl_balance+0x2cf/0x380
	 __x64_sys_ioctl+0x83/0xb0
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  -> #0 (&fs_info->balance_mutex){+.+.}-{3:3}:
	 __lock_acquire+0x1120/0x1e10
	 lock_acquire+0x116/0x370
	 __mutex_lock+0x7e/0x7b0
	 btrfs_recover_balance+0x2f0/0x340
	 open_ctree+0x1095/0x1726
	 btrfs_mount_root.cold+0x12/0xea
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 vfs_kern_mount.part.0+0x71/0xb0
	 btrfs_mount+0x10d/0x380
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 path_mount+0x433/0xc10
	 __x64_sys_mount+0xe3/0x120
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  other info that might help us debug this:

  Chain exists of:
    &fs_info->balance_mutex --> sb_internal#2 --> btrfs-root-00

   Possible unsafe locking scenario:

	 CPU0                    CPU1
	 ----                    ----
    lock(btrfs-root-00);
				 lock(sb_internal#2);
				 lock(btrfs-root-00);
    lock(&fs_info->balance_mutex);

   *** DEADLOCK ***

  2 locks held by mount/779:
   #0: ffffa0e60dc040e0 (&type->s_umount_key#47/1){+.+.}-{3:3}, at: alloc_super+0xb5/0x380
   #1: ffffa0e60ee31da8 (btrfs-root-00){++++}-{3:3}, at: __btrfs_tree_read_lock+0x27/0x100

  stack backtrace:
  CPU: 0 PID: 779 Comm: mount Not tainted 5.10.0-rc6+ #217
  Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
  Call Trace:
   dump_stack+0x8b/0xb0
   check_noncircular+0xcf/0xf0
   ? trace_call_bpf+0x139/0x260
   __lock_acquire+0x1120/0x1e10
   lock_acquire+0x116/0x370
   ? btrfs_recover_balance+0x2f0/0x340
   __mutex_lock+0x7e/0x7b0
   ? btrfs_recover_balance+0x2f0/0x340
   ? btrfs_recover_balance+0x2f0/0x340
   ? rcu_read_lock_sched_held+0x3f/0x80
   ? kmem_cache_alloc_trace+0x2c4/0x2f0
   ? btrfs_get_64+0x5e/0x100
   btrfs_recover_balance+0x2f0/0x340
   open_ctree+0x1095/0x1726
   btrfs_mount_root.cold+0x12/0xea
   ? rcu_read_lock_sched_held+0x3f/0x80
   legacy_get_tree+0x30/0x50
   vfs_get_tree+0x28/0xc0
   vfs_kern_mount.part.0+0x71/0xb0
   btrfs_mount+0x10d/0x380
   ? __kmalloc_track_caller+0x2f2/0x320
   legacy_get_tree+0x30/0x50
   vfs_get_tree+0x28/0xc0
   ? capable+0x3a/0x60
   path_mount+0x433/0xc10
   __x64_sys_mount+0xe3/0x120
   do_syscall_64+0x33/0x40
   entry_SYSCALL_64_after_hwframe+0x44/0xa9

This is straightforward to fix, simply release the path before we setup
the balance_ctl.

CC: stable@vger.kernel.org # 4.4+
Reviewed-by: Qu Wenruo <wqu@suse.com>
Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
Signed-off-by: Josef Bacik <josef@toxicpanda.com>
Reviewed-by: David Sterba <dsterba@suse.com>
Signed-off-by: David Sterba <dsterba@suse.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
spockfish pushed a commit to RoPieee/linux that referenced this issue Feb 1, 2021
commit fb28610 upstream.

While testing the error paths of relocation I hit the following lockdep
splat:

  ======================================================
  WARNING: possible circular locking dependency detected
  5.10.0-rc6+ raspberrypi#217 Not tainted
  ------------------------------------------------------
  mount/779 is trying to acquire lock:
  ffffa0e676945418 (&fs_info->balance_mutex){+.+.}-{3:3}, at: btrfs_recover_balance+0x2f0/0x340

  but task is already holding lock:
  ffffa0e60ee31da8 (btrfs-root-00){++++}-{3:3}, at: __btrfs_tree_read_lock+0x27/0x100

  which lock already depends on the new lock.

  the existing dependency chain (in reverse order) is:

  -> #2 (btrfs-root-00){++++}-{3:3}:
	 down_read_nested+0x43/0x130
	 __btrfs_tree_read_lock+0x27/0x100
	 btrfs_read_lock_root_node+0x31/0x40
	 btrfs_search_slot+0x462/0x8f0
	 btrfs_update_root+0x55/0x2b0
	 btrfs_drop_snapshot+0x398/0x750
	 clean_dirty_subvols+0xdf/0x120
	 btrfs_recover_relocation+0x534/0x5a0
	 btrfs_start_pre_rw_mount+0xcb/0x170
	 open_ctree+0x151f/0x1726
	 btrfs_mount_root.cold+0x12/0xea
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 vfs_kern_mount.part.0+0x71/0xb0
	 btrfs_mount+0x10d/0x380
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 path_mount+0x433/0xc10
	 __x64_sys_mount+0xe3/0x120
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  -> #1 (sb_internal#2){.+.+}-{0:0}:
	 start_transaction+0x444/0x700
	 insert_balance_item.isra.0+0x37/0x320
	 btrfs_balance+0x354/0xf40
	 btrfs_ioctl_balance+0x2cf/0x380
	 __x64_sys_ioctl+0x83/0xb0
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  -> #0 (&fs_info->balance_mutex){+.+.}-{3:3}:
	 __lock_acquire+0x1120/0x1e10
	 lock_acquire+0x116/0x370
	 __mutex_lock+0x7e/0x7b0
	 btrfs_recover_balance+0x2f0/0x340
	 open_ctree+0x1095/0x1726
	 btrfs_mount_root.cold+0x12/0xea
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 vfs_kern_mount.part.0+0x71/0xb0
	 btrfs_mount+0x10d/0x380
	 legacy_get_tree+0x30/0x50
	 vfs_get_tree+0x28/0xc0
	 path_mount+0x433/0xc10
	 __x64_sys_mount+0xe3/0x120
	 do_syscall_64+0x33/0x40
	 entry_SYSCALL_64_after_hwframe+0x44/0xa9

  other info that might help us debug this:

  Chain exists of:
    &fs_info->balance_mutex --> sb_internal#2 --> btrfs-root-00

   Possible unsafe locking scenario:

	 CPU0                    CPU1
	 ----                    ----
    lock(btrfs-root-00);
				 lock(sb_internal#2);
				 lock(btrfs-root-00);
    lock(&fs_info->balance_mutex);

   *** DEADLOCK ***

  2 locks held by mount/779:
   #0: ffffa0e60dc040e0 (&type->s_umount_key#47/1){+.+.}-{3:3}, at: alloc_super+0xb5/0x380
   #1: ffffa0e60ee31da8 (btrfs-root-00){++++}-{3:3}, at: __btrfs_tree_read_lock+0x27/0x100

  stack backtrace:
  CPU: 0 PID: 779 Comm: mount Not tainted 5.10.0-rc6+ raspberrypi#217
  Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
  Call Trace:
   dump_stack+0x8b/0xb0
   check_noncircular+0xcf/0xf0
   ? trace_call_bpf+0x139/0x260
   __lock_acquire+0x1120/0x1e10
   lock_acquire+0x116/0x370
   ? btrfs_recover_balance+0x2f0/0x340
   __mutex_lock+0x7e/0x7b0
   ? btrfs_recover_balance+0x2f0/0x340
   ? btrfs_recover_balance+0x2f0/0x340
   ? rcu_read_lock_sched_held+0x3f/0x80
   ? kmem_cache_alloc_trace+0x2c4/0x2f0
   ? btrfs_get_64+0x5e/0x100
   btrfs_recover_balance+0x2f0/0x340
   open_ctree+0x1095/0x1726
   btrfs_mount_root.cold+0x12/0xea
   ? rcu_read_lock_sched_held+0x3f/0x80
   legacy_get_tree+0x30/0x50
   vfs_get_tree+0x28/0xc0
   vfs_kern_mount.part.0+0x71/0xb0
   btrfs_mount+0x10d/0x380
   ? __kmalloc_track_caller+0x2f2/0x320
   legacy_get_tree+0x30/0x50
   vfs_get_tree+0x28/0xc0
   ? capable+0x3a/0x60
   path_mount+0x433/0xc10
   __x64_sys_mount+0xe3/0x120
   do_syscall_64+0x33/0x40
   entry_SYSCALL_64_after_hwframe+0x44/0xa9

This is straightforward to fix, simply release the path before we setup
the balance_ctl.

CC: stable@vger.kernel.org # 4.4+
Reviewed-by: Qu Wenruo <wqu@suse.com>
Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
Signed-off-by: Josef Bacik <josef@toxicpanda.com>
Reviewed-by: David Sterba <dsterba@suse.com>
Signed-off-by: David Sterba <dsterba@suse.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Nov 21, 2022
…kprobe_event_gen_test_exit()

When trace_get_event_file() failed, gen_kretprobe_test will be assigned
as the error code. If module kprobe_event_gen_test is removed now, the
null pointer dereference will happen in kprobe_event_gen_test_exit().
Check if gen_kprobe_test or gen_kretprobe_test is error code or NULL
before dereference them.

BUG: kernel NULL pointer dereference, address: 0000000000000012
PGD 0 P4D 0
Oops: 0000 [#1] SMP PTI
CPU: 3 PID: 2210 Comm: modprobe Not tainted
6.1.0-rc1-00171-g2159299a3b74-dirty #217
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
RIP: 0010:kprobe_event_gen_test_exit+0x1c/0xb5 [kprobe_event_gen_test]
Code: Unable to access opcode bytes at 0xffffffff9ffffff2.
RSP: 0018:ffffc900015bfeb8 EFLAGS: 00010246
RAX: ffffffffffffffea RBX: ffffffffa0002080 RCX: 0000000000000000
RDX: ffffffffa0001054 RSI: ffffffffa0001064 RDI: ffffffffdfc6349c
RBP: ffffffffa0000000 R08: 0000000000000004 R09: 00000000001e95c0
R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000800
R13: ffffffffa0002420 R14: 0000000000000000 R15: 0000000000000000
FS:  00007f56b75be540(0000) GS:ffff88813bc00000(0000)
knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffff9ffffff2 CR3: 000000010874a006 CR4: 0000000000330ee0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <TASK>
 __x64_sys_delete_module+0x206/0x380
 ? lockdep_hardirqs_on_prepare+0xd8/0x190
 ? syscall_enter_from_user_mode+0x1c/0x50
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x63/0xcd

Link: https://lore.kernel.org/all/20221108015130.28326-2-shangxiaojing@huawei.com/

Fixes: 6483624 ("tracing: Add kprobe event command generation test module")
Signed-off-by: Shang XiaoJing <shangxiaojing@huawei.com>
Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Cc: stable@vger.kernel.org
Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
herrnst pushed a commit to herrnst/linux-raspberrypi that referenced this issue Nov 26, 2022
…kprobe_event_gen_test_exit()

commit e0d7526 upstream.

When trace_get_event_file() failed, gen_kretprobe_test will be assigned
as the error code. If module kprobe_event_gen_test is removed now, the
null pointer dereference will happen in kprobe_event_gen_test_exit().
Check if gen_kprobe_test or gen_kretprobe_test is error code or NULL
before dereference them.

BUG: kernel NULL pointer dereference, address: 0000000000000012
PGD 0 P4D 0
Oops: 0000 [raspberrypi#1] SMP PTI
CPU: 3 PID: 2210 Comm: modprobe Not tainted
6.1.0-rc1-00171-g2159299a3b74-dirty raspberrypi#217
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
RIP: 0010:kprobe_event_gen_test_exit+0x1c/0xb5 [kprobe_event_gen_test]
Code: Unable to access opcode bytes at 0xffffffff9ffffff2.
RSP: 0018:ffffc900015bfeb8 EFLAGS: 00010246
RAX: ffffffffffffffea RBX: ffffffffa0002080 RCX: 0000000000000000
RDX: ffffffffa0001054 RSI: ffffffffa0001064 RDI: ffffffffdfc6349c
RBP: ffffffffa0000000 R08: 0000000000000004 R09: 00000000001e95c0
R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000800
R13: ffffffffa0002420 R14: 0000000000000000 R15: 0000000000000000
FS:  00007f56b75be540(0000) GS:ffff88813bc00000(0000)
knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffff9ffffff2 CR3: 000000010874a006 CR4: 0000000000330ee0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <TASK>
 __x64_sys_delete_module+0x206/0x380
 ? lockdep_hardirqs_on_prepare+0xd8/0x190
 ? syscall_enter_from_user_mode+0x1c/0x50
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x63/0xcd

Link: https://lore.kernel.org/all/20221108015130.28326-2-shangxiaojing@huawei.com/

Fixes: 6483624 ("tracing: Add kprobe event command generation test module")
Signed-off-by: Shang XiaoJing <shangxiaojing@huawei.com>
Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Cc: stable@vger.kernel.org
Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Nov 29, 2022
If a kernel thread is created by a user thread, it may carry FPU/SIMD
thread info flags (TIF_USEDFPU, TIF_USEDSIMD, etc.). Then it will be
considered as a fpu owner and kernel try to save its FPU/SIMD context
and cause such errors:

[   41.518931] do_fpu invoked from kernel context![#1]:
[   41.523933] CPU: 1 PID: 395 Comm: iou-wrk-394 Not tainted 6.1.0-rc5+ #217
[   41.530757] Hardware name: Loongson Loongson-3A5000-7A1000-1w-CRB/Loongson-LS3A5000-7A1000-1w-CRB, BIOS vUDK2018-LoongArch-V2.0.pre-beta8 08/18/2022
[   41.544064] $ 0   : 0000000000000000 90000000011e9468 9000000106c7c000 9000000106c7fcf0
[   41.552101] $ 4   : 9000000106305d40 9000000106689800 9000000106c7fd08 0000000003995818
[   41.560138] $ 8   : 0000000000000001 90000000009a72e4 0000000000000020 fffffffffffffffc
[   41.568174] $12   : 0000000000000000 0000000000000000 0000000000000020 00000009aab7e130
[   41.576211] $16   : 00000000000001ff 0000000000000407 0000000000000001 0000000000000000
[   41.584247] $20   : 0000000000000000 0000000000000001 9000000106c7fd70 90000001002f0400
[   41.592284] $24   : 0000000000000000 900000000178f740 90000000011e9834 90000001063057c0
[   41.600320] $28   : 0000000000000000 0000000000000001 9000000006826b40 9000000106305140
[   41.608356] era   : 9000000000228848 _save_fp+0x0/0xd8
[   41.613542] ra    : 90000000011e9468 __schedule+0x568/0x8d0
[   41.619160] CSR crmd: 000000b0
[   41.619163] CSR prmd: 00000000
[   41.622359] CSR euen: 00000000
[   41.625558] CSR ecfg: 00071c1c
[   41.628756] CSR estat: 000f0000
[   41.635239] ExcCode : f (SubCode 0)
[   41.638783] PrId  : 0014c010 (Loongson-64bit)
[   41.643191] Modules linked in: acpi_ipmi vfat fat ipmi_si ipmi_devintf cfg80211 ipmi_msghandler rfkill fuse efivarfs
[   41.653734] Process iou-wrk-394 (pid: 395, threadinfo=0000000004ebe913, task=00000000636fa1be)
[   41.662375] Stack : 00000000ffff0875 9000000006800ec0 9000000006800ec0 90000000002d57e0
[   41.670412]         0000000000000001 0000000000000000 9000000106535880 0000000000000001
[   41.678450]         9000000105291800 0000000000000000 9000000105291838 900000000178e000
[   41.686487]         9000000106c7fd90 9000000106305140 0000000000000001 90000000011e9834
[   41.694523]         00000000ffff0875 90000000011f034c 9000000105291838 9000000105291830
[   41.702561]         0000000000000000 9000000006801440 00000000ffff0875 90000000002d48c0
[   41.710597]         9000000128800001 9000000106305140 9000000105291838 9000000105291838
[   41.718634]         9000000105291830 9000000107811740 9000000105291848 90000000009bf1e0
[   41.726672]         9000000105291830 9000000107811748 2d6b72772d756f69 0000000000343933
[   41.734708]         0000000000000000 0000000000000000 0000000000000000 0000000000000000
[   41.742745]         ...
[   41.745252] Call Trace:
[   42.197868] [<9000000000228848>] _save_fp+0x0/0xd8
[   42.205214] [<90000000011ed468>] __schedule+0x568/0x8d0
[   42.210485] [<90000000011ed834>] schedule+0x64/0xd4
[   42.215411] [<90000000011f434c>] schedule_timeout+0x88/0x188
[   42.221115] [<90000000009c36d0>] io_wqe_worker+0x184/0x350
[   42.226645] [<9000000000221cf0>] ret_from_kernel_thread+0xc/0x9c

This can be easily triggered by ltp testcase syscalls/io_uring02 and it
can also be easily fixed by clearing the FPU/SIMD thread info flags for
kernel threads in copy_thread().

Cc: stable@vger.kernel.org
Reported-by: Qi Hu <huqi@loongson.cn>
Signed-off-by: Huacai Chen <chenhuacai@loongson.cn>
popcornmix pushed a commit that referenced this issue Nov 29, 2022
…kprobe_event_gen_test_exit()

commit e0d7526 upstream.

When trace_get_event_file() failed, gen_kretprobe_test will be assigned
as the error code. If module kprobe_event_gen_test is removed now, the
null pointer dereference will happen in kprobe_event_gen_test_exit().
Check if gen_kprobe_test or gen_kretprobe_test is error code or NULL
before dereference them.

BUG: kernel NULL pointer dereference, address: 0000000000000012
PGD 0 P4D 0
Oops: 0000 [#1] SMP PTI
CPU: 3 PID: 2210 Comm: modprobe Not tainted
6.1.0-rc1-00171-g2159299a3b74-dirty #217
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
RIP: 0010:kprobe_event_gen_test_exit+0x1c/0xb5 [kprobe_event_gen_test]
Code: Unable to access opcode bytes at 0xffffffff9ffffff2.
RSP: 0018:ffffc900015bfeb8 EFLAGS: 00010246
RAX: ffffffffffffffea RBX: ffffffffa0002080 RCX: 0000000000000000
RDX: ffffffffa0001054 RSI: ffffffffa0001064 RDI: ffffffffdfc6349c
RBP: ffffffffa0000000 R08: 0000000000000004 R09: 00000000001e95c0
R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000800
R13: ffffffffa0002420 R14: 0000000000000000 R15: 0000000000000000
FS:  00007f56b75be540(0000) GS:ffff88813bc00000(0000)
knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffff9ffffff2 CR3: 000000010874a006 CR4: 0000000000330ee0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <TASK>
 __x64_sys_delete_module+0x206/0x380
 ? lockdep_hardirqs_on_prepare+0xd8/0x190
 ? syscall_enter_from_user_mode+0x1c/0x50
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x63/0xcd

Link: https://lore.kernel.org/all/20221108015130.28326-2-shangxiaojing@huawei.com/

Fixes: 6483624 ("tracing: Add kprobe event command generation test module")
Signed-off-by: Shang XiaoJing <shangxiaojing@huawei.com>
Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Cc: stable@vger.kernel.org
Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
herrnst pushed a commit to herrnst/linux-raspberrypi that referenced this issue Dec 3, 2022
commit e428e96 upstream.

If a kernel thread is created by a user thread, it may carry FPU/SIMD
thread info flags (TIF_USEDFPU, TIF_USEDSIMD, etc.). Then it will be
considered as a fpu owner and kernel try to save its FPU/SIMD context
and cause such errors:

[   41.518931] do_fpu invoked from kernel context![raspberrypi#1]:
[   41.523933] CPU: 1 PID: 395 Comm: iou-wrk-394 Not tainted 6.1.0-rc5+ raspberrypi#217
[   41.530757] Hardware name: Loongson Loongson-3A5000-7A1000-1w-CRB/Loongson-LS3A5000-7A1000-1w-CRB, BIOS vUDK2018-LoongArch-V2.0.pre-beta8 08/18/2022
[   41.544064] $ 0   : 0000000000000000 90000000011e9468 9000000106c7c000 9000000106c7fcf0
[   41.552101] $ 4   : 9000000106305d40 9000000106689800 9000000106c7fd08 0000000003995818
[   41.560138] $ 8   : 0000000000000001 90000000009a72e4 0000000000000020 fffffffffffffffc
[   41.568174] $12   : 0000000000000000 0000000000000000 0000000000000020 00000009aab7e130
[   41.576211] $16   : 00000000000001ff 0000000000000407 0000000000000001 0000000000000000
[   41.584247] $20   : 0000000000000000 0000000000000001 9000000106c7fd70 90000001002f0400
[   41.592284] $24   : 0000000000000000 900000000178f740 90000000011e9834 90000001063057c0
[   41.600320] $28   : 0000000000000000 0000000000000001 9000000006826b40 9000000106305140
[   41.608356] era   : 9000000000228848 _save_fp+0x0/0xd8
[   41.613542] ra    : 90000000011e9468 __schedule+0x568/0x8d0
[   41.619160] CSR crmd: 000000b0
[   41.619163] CSR prmd: 00000000
[   41.622359] CSR euen: 00000000
[   41.625558] CSR ecfg: 00071c1c
[   41.628756] CSR estat: 000f0000
[   41.635239] ExcCode : f (SubCode 0)
[   41.638783] PrId  : 0014c010 (Loongson-64bit)
[   41.643191] Modules linked in: acpi_ipmi vfat fat ipmi_si ipmi_devintf cfg80211 ipmi_msghandler rfkill fuse efivarfs
[   41.653734] Process iou-wrk-394 (pid: 395, threadinfo=0000000004ebe913, task=00000000636fa1be)
[   41.662375] Stack : 00000000ffff0875 9000000006800ec0 9000000006800ec0 90000000002d57e0
[   41.670412]         0000000000000001 0000000000000000 9000000106535880 0000000000000001
[   41.678450]         9000000105291800 0000000000000000 9000000105291838 900000000178e000
[   41.686487]         9000000106c7fd90 9000000106305140 0000000000000001 90000000011e9834
[   41.694523]         00000000ffff0875 90000000011f034c 9000000105291838 9000000105291830
[   41.702561]         0000000000000000 9000000006801440 00000000ffff0875 90000000002d48c0
[   41.710597]         9000000128800001 9000000106305140 9000000105291838 9000000105291838
[   41.718634]         9000000105291830 9000000107811740 9000000105291848 90000000009bf1e0
[   41.726672]         9000000105291830 9000000107811748 2d6b72772d756f69 0000000000343933
[   41.734708]         0000000000000000 0000000000000000 0000000000000000 0000000000000000
[   41.742745]         ...
[   41.745252] Call Trace:
[   42.197868] [<9000000000228848>] _save_fp+0x0/0xd8
[   42.205214] [<90000000011ed468>] __schedule+0x568/0x8d0
[   42.210485] [<90000000011ed834>] schedule+0x64/0xd4
[   42.215411] [<90000000011f434c>] schedule_timeout+0x88/0x188
[   42.221115] [<90000000009c36d0>] io_wqe_worker+0x184/0x350
[   42.226645] [<9000000000221cf0>] ret_from_kernel_thread+0xc/0x9c

This can be easily triggered by ltp testcase syscalls/io_uring02 and it
can also be easily fixed by clearing the FPU/SIMD thread info flags for
kernel threads in copy_thread().

Cc: stable@vger.kernel.org
Reported-by: Qi Hu <huqi@loongson.cn>
Signed-off-by: Huacai Chen <chenhuacai@loongson.cn>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants