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

replace some/most pr_debug with trace events #131

Closed
pabeni opened this issue Dec 23, 2020 · 3 comments
Closed

replace some/most pr_debug with trace events #131

pabeni opened this issue Dec 23, 2020 · 3 comments
Assignees

Comments

@pabeni
Copy link

pabeni commented Dec 23, 2020

the debug messages are useful in debug sessions, but have several downside:

  • they requires debug build
  • turning the debug messages on slow down the system a lot, likely impacting the to-be-debugged races/scenarios
  • it's difficult to handle the amount of data produced by not-so-short runs
    We can improve the situation replacing some debug messages with trace events.

Why trace event at all? we could use perf-probe instead.

  • probes can't be attached in any place
  • not all the local variables are available for perf probes.

Note: the to-be-defined trace event should be considered carefully - it's better is that interface is as stable as possible.

@geliangtang geliangtang self-assigned this Dec 29, 2020
@geliangtang
Copy link
Member

@pabeni Hi Paolo, I'll add the trace events for MPTCP recently.

@geliangtang
Copy link
Member

geliangtang commented Feb 2, 2021

As Paolo suggested, we should add the tracepoints at "the packet scheduler and the mapping status" first.

In get_mapping_status, the tracepoint should be enough to get the full mapping info, in case of no error
and the complete error reason elsewhere.

In mptcp_subflow_get_send, the tracepoint should be enough to understand the packet scheduler decision.

@matttbe
Copy link
Member

matttbe commented Apr 1, 2021

Can be closed thanks to these new commits from Geliang:

  • 00ed6f0: mptcp: export mptcp_subflow_active
  • e4421bb: mptcp: add tracepoint in mptcp_subflow_get_send
  • 12abe4c: mptcp: add tracepoint in get_mapping_status
  • 88a550c: mptcp: add tracepoint in ack_update_msk
  • 769badb: mptcp: add tracepoint in subflow_check_data_avail
  • Results: e245e13..f574fcf

(one patch is still pending but we will continue to track it on Patchwork)

@matttbe matttbe closed this as completed Apr 1, 2021
jenkins-tessares pushed a commit that referenced this issue Jan 24, 2023
…dcmds()

This patch fixes a stack-out-of-bounds read in brcmfmac that occurs
when 'buf' that is not null-terminated is passed as an argument of
strsep() in brcmf_c_preinit_dcmds(). This buffer is filled with a firmware
version string by memcpy() in brcmf_fil_iovar_data_get().
The patch ensures buf is null-terminated.

Found by a modified version of syzkaller.

[   47.569679][ T1897] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43236b for chip BCM43236/3
[   47.582839][ T1897] brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available
[   47.601565][ T1897] ==================================================================
[   47.602574][ T1897] BUG: KASAN: stack-out-of-bounds in strsep+0x1b2/0x1f0
[   47.603447][ T1897] Read of size 1 at addr ffffc90001f6f000 by task kworker/0:2/1897
[   47.604336][ T1897]
[   47.604621][ T1897] CPU: 0 PID: 1897 Comm: kworker/0:2 Tainted: G           O      5.14.0+ #131
[   47.605617][ T1897] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
[   47.606907][ T1897] Workqueue: usb_hub_wq hub_event
[   47.607453][ T1897] Call Trace:
[   47.607801][ T1897]  dump_stack_lvl+0x8e/0xd1
[   47.608295][ T1897]  print_address_description.constprop.0.cold+0xf/0x334
[   47.609009][ T1897]  ? strsep+0x1b2/0x1f0
[   47.609434][ T1897]  ? strsep+0x1b2/0x1f0
[   47.609863][ T1897]  kasan_report.cold+0x83/0xdf
[   47.610366][ T1897]  ? strsep+0x1b2/0x1f0
[   47.610882][ T1897]  strsep+0x1b2/0x1f0
[   47.611300][ T1897]  ? brcmf_fil_iovar_data_get+0x3a/0xf0
[   47.611883][ T1897]  brcmf_c_preinit_dcmds+0x995/0xc40
[   47.612434][ T1897]  ? brcmf_c_set_joinpref_default+0x100/0x100
[   47.613078][ T1897]  ? rcu_read_lock_sched_held+0xa1/0xd0
[   47.613662][ T1897]  ? rcu_read_lock_bh_held+0xb0/0xb0
[   47.614208][ T1897]  ? lock_acquire+0x19d/0x4e0
[   47.614704][ T1897]  ? find_held_lock+0x2d/0x110
[   47.615236][ T1897]  ? brcmf_usb_deq+0x1a7/0x260
[   47.615741][ T1897]  ? brcmf_usb_rx_fill_all+0x5a/0xf0
[   47.616288][ T1897]  brcmf_attach+0x246/0xd40
[   47.616758][ T1897]  ? wiphy_new_nm+0x1703/0x1dd0
[   47.617280][ T1897]  ? kmemdup+0x43/0x50
[   47.617720][ T1897]  brcmf_usb_probe+0x12de/0x1690
[   47.618244][ T1897]  ? brcmf_usbdev_qinit.constprop.0+0x470/0x470
[   47.618901][ T1897]  usb_probe_interface+0x2aa/0x760
[   47.619429][ T1897]  ? usb_probe_device+0x250/0x250
[   47.619950][ T1897]  really_probe+0x205/0xb70
[   47.620435][ T1897]  ? driver_allows_async_probing+0x130/0x130
[   47.621048][ T1897]  __driver_probe_device+0x311/0x4b0
[   47.621595][ T1897]  ? driver_allows_async_probing+0x130/0x130
[   47.622209][ T1897]  driver_probe_device+0x4e/0x150
[   47.622739][ T1897]  __device_attach_driver+0x1cc/0x2a0
[   47.623287][ T1897]  bus_for_each_drv+0x156/0x1d0
[   47.623796][ T1897]  ? bus_rescan_devices+0x30/0x30
[   47.624309][ T1897]  ? lockdep_hardirqs_on_prepare+0x273/0x3e0
[   47.624907][ T1897]  ? trace_hardirqs_on+0x46/0x160
[   47.625437][ T1897]  __device_attach+0x23f/0x3a0
[   47.625924][ T1897]  ? device_bind_driver+0xd0/0xd0
[   47.626433][ T1897]  ? kobject_uevent_env+0x287/0x14b0
[   47.627057][ T1897]  bus_probe_device+0x1da/0x290
[   47.627557][ T1897]  device_add+0xb7b/0x1eb0
[   47.628027][ T1897]  ? wait_for_completion+0x290/0x290
[   47.628593][ T1897]  ? __fw_devlink_link_to_suppliers+0x5a0/0x5a0
[   47.629249][ T1897]  usb_set_configuration+0xf59/0x16f0
[   47.629829][ T1897]  usb_generic_driver_probe+0x82/0xa0
[   47.630385][ T1897]  usb_probe_device+0xbb/0x250
[   47.630927][ T1897]  ? usb_suspend+0x590/0x590
[   47.631397][ T1897]  really_probe+0x205/0xb70
[   47.631855][ T1897]  ? driver_allows_async_probing+0x130/0x130
[   47.632469][ T1897]  __driver_probe_device+0x311/0x4b0
[   47.633002][ T1897]  ? usb_generic_driver_match+0x75/0x90
[   47.633573][ T1897]  ? driver_allows_async_probing+0x130/0x130
[   47.634170][ T1897]  driver_probe_device+0x4e/0x150
[   47.634703][ T1897]  __device_attach_driver+0x1cc/0x2a0
[   47.635248][ T1897]  bus_for_each_drv+0x156/0x1d0
[   47.635748][ T1897]  ? bus_rescan_devices+0x30/0x30
[   47.636271][ T1897]  ? lockdep_hardirqs_on_prepare+0x273/0x3e0
[   47.636881][ T1897]  ? trace_hardirqs_on+0x46/0x160
[   47.637396][ T1897]  __device_attach+0x23f/0x3a0
[   47.637904][ T1897]  ? device_bind_driver+0xd0/0xd0
[   47.638426][ T1897]  ? kobject_uevent_env+0x287/0x14b0
[   47.638985][ T1897]  bus_probe_device+0x1da/0x290
[   47.639512][ T1897]  device_add+0xb7b/0x1eb0
[   47.639977][ T1897]  ? __fw_devlink_link_to_suppliers+0x5a0/0x5a0
[   47.640612][ T1897]  ? kfree+0x14a/0x6b0
[   47.641055][ T1897]  ? __usb_get_extra_descriptor+0x116/0x160
[   47.641679][ T1897]  usb_new_device.cold+0x49c/0x1029
[   47.642245][ T1897]  ? hub_disconnect+0x450/0x450
[   47.642756][ T1897]  ? rwlock_bug.part.0+0x90/0x90
[   47.643273][ T1897]  ? _raw_spin_unlock_irq+0x24/0x30
[   47.643822][ T1897]  ? lockdep_hardirqs_on_prepare+0x273/0x3e0
[   47.644445][ T1897]  hub_event+0x1c98/0x3950
[   47.644939][ T1897]  ? hub_port_debounce+0x2e0/0x2e0
[   47.645467][ T1897]  ? check_irq_usage+0x861/0xf20
[   47.645975][ T1897]  ? drain_workqueue+0x280/0x360
[   47.646506][ T1897]  ? lock_release+0x640/0x640
[   47.646994][ T1897]  ? rcu_read_lock_sched_held+0xa1/0xd0
[   47.647572][ T1897]  ? rcu_read_lock_bh_held+0xb0/0xb0
[   47.648111][ T1897]  ? lockdep_hardirqs_on_prepare+0x273/0x3e0
[   47.648735][ T1897]  process_one_work+0x92b/0x1460
[   47.649262][ T1897]  ? pwq_dec_nr_in_flight+0x330/0x330
[   47.649816][ T1897]  ? rwlock_bug.part.0+0x90/0x90
[   47.650336][ T1897]  worker_thread+0x95/0xe00
[   47.650830][ T1897]  ? __kthread_parkme+0x115/0x1e0
[   47.651361][ T1897]  ? process_one_work+0x1460/0x1460
[   47.651904][ T1897]  kthread+0x3a1/0x480
[   47.652329][ T1897]  ? set_kthread_struct+0x120/0x120
[   47.652878][ T1897]  ret_from_fork+0x1f/0x30
[   47.653370][ T1897]
[   47.653608][ T1897]
[   47.653848][ T1897] addr ffffc90001f6f000 is located in stack of task kworker/0:2/1897 at offset 512 in frame:
[   47.654891][ T1897]  brcmf_c_preinit_dcmds+0x0/0xc40
[   47.655442][ T1897]
[   47.655690][ T1897] this frame has 4 objects:
[   47.656151][ T1897]  [48, 56) 'ptr'
[   47.656159][ T1897]  [80, 148) 'revinfo'
[   47.656534][ T1897]  [192, 210) 'eventmask'
[   47.656953][ T1897]  [256, 512) 'buf'
[   47.657410][ T1897]
[   47.658035][ T1897] Memory state around the buggy address:
[   47.658743][ T1897]  ffffc90001f6ef00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[   47.659577][ T1897]  ffffc90001f6ef80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[   47.660394][ T1897] >ffffc90001f6f000: f3 f3 f3 f3 f3 f3 f3 f3 00 00 00 00 00 00 00 00
[   47.661199][ T1897]                    ^
[   47.661625][ T1897]  ffffc90001f6f080: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[   47.662455][ T1897]  ffffc90001f6f100: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 f1 f1
[   47.663318][ T1897] ==================================================================
[   47.664147][ T1897] Disabling lock debugging due to kernel taint

Reported-by: Dokyung Song <dokyungs@yonsei.ac.kr>
Reported-by: Jisoo Jang <jisoo.jang@yonsei.ac.kr>
Reported-by: Minsuk Kang <linuxlovemin@yonsei.ac.kr>
Signed-off-by: Jisoo Jang <jisoo.jang@yonsei.ac.kr>
Signed-off-by: Kalle Valo <kvalo@kernel.org>
Link: https://lore.kernel.org/r/20221115043458.37562-1-jisoo.jang@yonsei.ac.kr
matttbe pushed a commit that referenced this issue Feb 17, 2023
This patch fixes a use-after-free in ath9k that occurs in
ath9k_hif_usb_disconnect() when ath9k_destroy_wmi() is trying to access
'drv_priv' that has already been freed by ieee80211_free_hw(), called by
ath9k_htc_hw_deinit(). The patch moves ath9k_destroy_wmi() before
ieee80211_free_hw(). Note that urbs from the driver should be killed
before freeing 'wmi' with ath9k_destroy_wmi() as their callbacks will
access 'wmi'.

Found by a modified version of syzkaller.

==================================================================
BUG: KASAN: use-after-free in ath9k_destroy_wmi+0x38/0x40
Read of size 8 at addr ffff8881069132a0 by task kworker/0:1/7

CPU: 0 PID: 7 Comm: kworker/0:1 Tainted: G O 5.14.0+ #131
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
Workqueue: usb_hub_wq hub_event
Call Trace:
 dump_stack_lvl+0x8e/0xd1
 print_address_description.constprop.0.cold+0x93/0x334
 ? ath9k_destroy_wmi+0x38/0x40
 ? ath9k_destroy_wmi+0x38/0x40
 kasan_report.cold+0x83/0xdf
 ? ath9k_destroy_wmi+0x38/0x40
 ath9k_destroy_wmi+0x38/0x40
 ath9k_hif_usb_disconnect+0x329/0x3f0
 ? ath9k_hif_usb_suspend+0x120/0x120
 ? usb_disable_interface+0xfc/0x180
 usb_unbind_interface+0x19b/0x7e0
 ? usb_autoresume_device+0x50/0x50
 device_release_driver_internal+0x44d/0x520
 bus_remove_device+0x2e5/0x5a0
 device_del+0x5b2/0xe30
 ? __device_link_del+0x370/0x370
 ? usb_remove_ep_devs+0x43/0x80
 ? remove_intf_ep_devs+0x112/0x1a0
 usb_disable_device+0x1e3/0x5a0
 usb_disconnect+0x267/0x870
 hub_event+0x168d/0x3950
 ? rcu_read_lock_sched_held+0xa1/0xd0
 ? hub_port_debounce+0x2e0/0x2e0
 ? check_irq_usage+0x860/0xf20
 ? drain_workqueue+0x281/0x360
 ? lock_release+0x640/0x640
 ? rcu_read_lock_sched_held+0xa1/0xd0
 ? rcu_read_lock_bh_held+0xb0/0xb0
 ? lockdep_hardirqs_on_prepare+0x273/0x3e0
 process_one_work+0x92b/0x1460
 ? pwq_dec_nr_in_flight+0x330/0x330
 ? rwlock_bug.part.0+0x90/0x90
 worker_thread+0x95/0xe00
 ? __kthread_parkme+0x115/0x1e0
 ? process_one_work+0x1460/0x1460
 kthread+0x3a1/0x480
 ? set_kthread_struct+0x120/0x120
 ret_from_fork+0x1f/0x30

The buggy address belongs to the page:
page:ffffea00041a44c0 refcount:0 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x106913
flags: 0x200000000000000(node=0|zone=2)
raw: 0200000000000000 0000000000000000 dead000000000122 0000000000000000
raw: 0000000000000000 0000000000000000 00000000ffffffff 0000000000000000
page dumped because: kasan: bad access detected
page_owner tracks the page as freed
page last allocated via order 3, migratetype Unmovable, gfp_mask 0x40dc0(GFP_KERNEL|__GFP_COMP|__GFP_ZERO), pid 7, ts 38347963444, free_ts 41399957635
 prep_new_page+0x1aa/0x240
 get_page_from_freelist+0x159a/0x27c0
 __alloc_pages+0x2da/0x6a0
 alloc_pages+0xec/0x1e0
 kmalloc_order+0x39/0xf0
 kmalloc_order_trace+0x19/0x120
 __kmalloc+0x308/0x390
 wiphy_new_nm+0x6f5/0x1dd0
 ieee80211_alloc_hw_nm+0x36d/0x2230
 ath9k_htc_probe_device+0x9d/0x1e10
 ath9k_htc_hw_init+0x34/0x50
 ath9k_hif_usb_firmware_cb+0x25f/0x4e0
 request_firmware_work_func+0x131/0x240
 process_one_work+0x92b/0x1460
 worker_thread+0x95/0xe00
 kthread+0x3a1/0x480
page last free stack trace:
 free_pcp_prepare+0x3d3/0x7f0
 free_unref_page+0x1e/0x3d0
 device_release+0xa4/0x240
 kobject_put+0x186/0x4c0
 put_device+0x20/0x30
 ath9k_htc_disconnect_device+0x1cf/0x2c0
 ath9k_htc_hw_deinit+0x26/0x30
 ath9k_hif_usb_disconnect+0x2d9/0x3f0
 usb_unbind_interface+0x19b/0x7e0
 device_release_driver_internal+0x44d/0x520
 bus_remove_device+0x2e5/0x5a0
 device_del+0x5b2/0xe30
 usb_disable_device+0x1e3/0x5a0
 usb_disconnect+0x267/0x870
 hub_event+0x168d/0x3950
 process_one_work+0x92b/0x1460

Memory state around the buggy address:
 ffff888106913180: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
 ffff888106913200: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
>ffff888106913280: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
                               ^
 ffff888106913300: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
 ffff888106913380: ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
==================================================================

Reported-by: Dokyung Song <dokyungs@yonsei.ac.kr>
Reported-by: Jisoo Jang <jisoo.jang@yonsei.ac.kr>
Reported-by: Minsuk Kang <linuxlovemin@yonsei.ac.kr>
Signed-off-by: Minsuk Kang <linuxlovemin@yonsei.ac.kr>
Acked-by: Toke Høiland-Jørgensen <toke@toke.dk>
Signed-off-by: Kalle Valo <quic_kvalo@quicinc.com>
Link: https://lore.kernel.org/r/20221205014308.1617597-1-linuxlovemin@yonsei.ac.kr
jenkins-tessares pushed a commit that referenced this issue Aug 14, 2023
LE Create CIS command shall not be sent before all CIS Established
events from its previous invocation have been processed. Currently it is
sent via hci_sync but that only waits for the first event, but there can
be multiple.

Make it wait for all events, and simplify the CIS creation as follows:

Add new flag HCI_CONN_CREATE_CIS, which is set if Create CIS has been
sent for the connection but it is not yet completed.

Make BT_CONNECT state to mean the connection wants Create CIS.

On events after which new Create CIS may need to be sent, send it if
possible and some connections need it. These events are:
hci_connect_cis, iso_connect_cfm, hci_cs_le_create_cis,
hci_le_cis_estabilished_evt.

The Create CIS status/completion events shall queue new Create CIS only
if at least one of the connections transitions away from BT_CONNECT, so
that we don't loop if controller is sending bogus events.

This fixes sending multiple CIS Create for the same CIS in the
"ISO AC 6(i) - Success" BlueZ test case:

< HCI Command: LE Create Co.. (0x08|0x0064) plen 9  #129 [hci0]
        Number of CIS: 2
        CIS Handle: 257
        ACL Handle: 42
        CIS Handle: 258
        ACL Handle: 42
> HCI Event: Command Status (0x0f) plen 4           #130 [hci0]
      LE Create Connected Isochronous Stream (0x08|0x0064) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 29           #131 [hci0]
      LE Connected Isochronous Stream Established (0x19)
        Status: Success (0x00)
        Connection Handle: 257
        ...
< HCI Command: LE Setup Is.. (0x08|0x006e) plen 13  #132 [hci0]
        ...
> HCI Event: Command Complete (0x0e) plen 6         #133 [hci0]
      LE Setup Isochronous Data Path (0x08|0x006e) ncmd 1
        ...
< HCI Command: LE Create Co.. (0x08|0x0064) plen 5  #134 [hci0]
        Number of CIS: 1
        CIS Handle: 258
        ACL Handle: 42
> HCI Event: Command Status (0x0f) plen 4           #135 [hci0]
      LE Create Connected Isochronous Stream (0x08|0x0064) ncmd 1
        Status: ACL Connection Already Exists (0x0b)
> HCI Event: LE Meta Event (0x3e) plen 29           #136 [hci0]
      LE Connected Isochronous Stream Established (0x19)
        Status: Success (0x00)
        Connection Handle: 258
        ...

Fixes: c09b80b ("Bluetooth: hci_conn: Fix not waiting for HCI_EVT_LE_CIS_ESTABLISHED")
Signed-off-by: Pauli Virtanen <pav@iki.fi>
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants