Bug 2271175 - bluetoothd busy loop in find_service_with_state()
Summary: bluetoothd busy loop in find_service_with_state()
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: bluez
Version: 40
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Gopal krishna tiwari
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2024-03-23 10:38 UTC by Zbigniew Jędrzejewski-Szmek
Modified: 2024-04-19 21:36 UTC (History)
5 users (show)

Fixed In Version: bluez-5.75-1.fc40
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2024-04-19 21:36:10 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github bluez bluez issues 785 0 None closed As of 5.73: `rfkill block bluetooth` puts `bluetoothd` in loop at 100% CPU. 2024-04-15 21:17:05 UTC

Description Zbigniew Jędrzejewski-Szmek 2024-03-23 10:38:49 UTC
Description of problem:
My laptop had one CPU spinning at 100%.

I killed the process with SIGABRT and this is the backtrace:

(gdb) bt full
#0  0x0000561a14675f73 in find_service_with_state (list=0x561a15b68010 = {...}, state=BTD_SERVICE_STATE_CONNECTED) at src/device.c:346
        service = 0x561a15b5c9e0
        l = 0x561a15b654d0 = {0x561a15b5c9e0, 0x561a15b5ca20, 0x561a15b80900}
#1  btd_device_is_connected (dev=<optimized out>) at src/device.c:3279
No locals.
#2  btd_device_is_connected (dev=0x561a15b69390) at src/device.c:3274
No locals.
#3  adapter_remove_connection (adapter=0x561a15b55c20, device=0x561a15b69390, bdaddr_type=0 '\000') at src/adapter.c:7489
        remove_device = <optimized out>
        __btd_debug_desc = {file = 0x561a146da072 "src/adapter.c", flags = 0}
        __func__ = "adapter_remove_connection"
        __btd_debug_desc = {file = 0x561a146da072 "src/adapter.c", flags = 0}
#4  0x0000561a146632ad in adapter_stop (adapter=0x561a15b55c20) at src/adapter.c:7525
        device = 0x561a15b69390
        addr_type = 1 '\001'
        __func__ = <optimized out>
        __btd_debug_desc = <optimized out>
#5  settings_changed (adapter=0x561a15b55c20, settings=<optimized out>) at src/adapter.c:622
        changed_mask = 1
        changed_mask = <optimized out>
        __func__ = <optimized out>
        __btd_debug_desc = <optimized out>
        __btd_debug_desc = <optimized out>
#6  new_settings_callback (index=<optimized out>, length=<optimized out>, param=<optimized out>, user_data=0x561a15b55c20) at src/adapter.c:705
        adapter = 0x561a15b55c20
        settings = <optimized out>
        __btd_debug_desc = {file = 0x561a146da072 "src/adapter.c", flags = 0}
        __func__ = "new_settings_callback"
#7  0x0000561a146a35a9 in queue_foreach (queue=0x561a15b4f680, function=0x561a1469bcd0 <notify_handler>, user_data=0x7ffd4092c850)
    at src/shared/queue.c:207
        next = 0x561a15b62f60
        entry = <optimized out>
#8  queue_foreach (queue=0x561a15b4f680, function=0x561a1469bcd0 <notify_handler>, user_data=0x7ffd4092c850) at src/shared/queue.c:190
        entry = <optimized out>
        next = <optimized out>
#9  process_notify (mgmt=0x561a15b4f330, event=<optimized out>, index=<optimized out>, length=<optimized out>, param=<optimized out>)
    at src/shared/mgmt.c:349
        match = {event = 6, index = 0, length = 4, param = 0x561a15b4f3b6}
        match = <optimized out>
#10 can_read_data (io=<optimized out>, user_data=0x561a15b4f330) at src/shared/mgmt.c:409
        mgmt = 0x561a15b4f330
        hdr = <optimized out>
        cc = <optimized out>
        cs = <optimized out>
        bytes_read = <optimized out>
        opcode = <optimized out>
        event = <optimized out>
        index = <optimized out>
        length = <optimized out>
        __func__ = "can_read_data"
#11 0x0000561a146c56d9 in watch_callback (channel=<optimized out>, cond=<optimized out>, user_data=<optimized out>) at src/shared/io-glib.c:157
        watch = <optimized out>
        result = <optimized out>
        destroy = <optimized out>
#12 0x00007f3bdb01a26c in g_main_dispatch (context=0x561a15b49df0) at ../glib/gmain.c:3344
        dispatch = 0x7f3bdb077be0 <g_io_unix_dispatch>
        prev_source = 0x0
        begin_time_nsec = 649780860485399
        was_in_call = 0
        user_data = 0x561a15b4f6b0
        callback = 0x561a146c56b0 <watch_callback>
        cb_funcs = 0x7f3bdb109280 <g_source_callback_funcs>
        cb_data = 0x561a15b4f760
        need_destroy = <optimized out>
        source = 0x561a15b4f6e0
        current = 0x561a15b55950
        i = <optimized out>
        __func__ = <optimized out>
#13 g_main_context_dispatch_unlocked (context=0x561a15b49df0) at ../glib/gmain.c:4152
No locals.
#14 0x00007f3bdb07b2a8 in g_main_context_iterate_unlocked.isra.0 (context=0x561a15b49df0, block=block@entry=1, dispatch=dispatch@entry=1, 
    self=<optimized out>) at ../glib/gmain.c:4217
        max_priority = 200
        timeout = 0
        some_ready = 1
        nfds = 32
        allocated_nfds = <optimized out>
        fds = 0x561a15b7dc20
        begin_time_nsec = 649780860418833
#15 0x00007f3bdb020227 in g_main_loop_run (loop=0x561a15b49fe0) at ../glib/gmain.c:4419
        self = <optimized out>
        __func__ = "g_main_loop_run"
#16 0x0000561a145faddd in mainloop_run () at src/shared/mainloop-glib.c:66
No locals.
#17 mainloop_run_with_signal (func=0x561a1464e3e0 <signal_callback>, user_data=0x0) at src/shared/mainloop-notify.c:188
        data = 0x561a15b55820
        io = 0x561a15b55840
        ret = <optimized out>
        data = <optimized out>
        io = <optimized out>
        ret = <optimized out>
        __n = <optimized out>
        __s = <optimized out>
        __p = <optimized out>
#18 main (argc=<optimized out>, argv=<optimized out>) at src/main.c:1452
        context = <optimized out>
        err = 0x0
        sdp_mtu = 0
        sdp_flags = <optimized out>
        gdbus_flags = <optimized out>
        __func__ = "main"
        __btd_debug_desc = {file = 0x561a146dcbd4 "src/main.c", flags = 0}

Version-Release number of selected component (if applicable):
bluez-5.73-2.fc40.x86_64

How reproducible:
So far only happened once.

Logs:
Mar 22 12:33:36 x1c systemd[1]: Starting bluetooth.service...
Mar 22 12:33:36 x1c bluetoothd[1491894]: Bluetooth daemon 5.73
Mar 22 12:33:36 x1c bluetoothd[1491894]: Starting SDP server
Mar 22 12:33:36 x1c systemd[1]: Started bluetooth.service.
Mar 22 12:33:36 x1c bluetoothd[1491894]: src/plugin.c:init_plugin() System does not support bap plugin
Mar 22 12:33:36 x1c bluetoothd[1491894]: src/plugin.c:init_plugin() System does not support bass plugin
Mar 22 12:33:36 x1c bluetoothd[1491894]: src/plugin.c:init_plugin() System does not support mcp plugin
Mar 22 12:33:36 x1c bluetoothd[1491894]: src/plugin.c:init_plugin() System does not support vcp plugin
Mar 22 12:33:36 x1c bluetoothd[1491894]: profiles/audio/micp.c:micp_init() D-Bus experimental not enabled
Mar 22 12:33:36 x1c bluetoothd[1491894]: src/plugin.c:init_plugin() System does not support micp plugin
Mar 22 12:33:36 x1c bluetoothd[1491894]: src/plugin.c:init_plugin() System does not support ccp plugin
Mar 22 12:33:36 x1c bluetoothd[1491894]: src/plugin.c:init_plugin() System does not support csip plugin
Mar 22 12:33:36 x1c bluetoothd[1491894]: Bluetooth management interface 1.22 initialized
Mar 22 12:33:36 x1c bluetoothd[1491894]: src/adapter.c:reset_adv_monitors_complete() Failed to reset Adv Monitors: Failed (0x03)
Mar 22 12:33:36 x1c bluetoothd[1491894]: Battery Provider Manager created
Mar 22 12:33:36 x1c bluetoothd[1491894]: Failed to clear UUIDs: Failed (0x03)
Mar 22 12:33:36 x1c bluetoothd[1491894]: Failed to add UUID: Failed (0x03)
Mar 22 12:33:36 x1c bluetoothd[1491894]: Failed to add UUID: Failed (0x03)
Mar 22 12:33:36 x1c bluetoothd[1491894]: Failed to add UUID: Failed (0x03)
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/ldac
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSink/aptx_hd
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/aptx_hd
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSink/aptx
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/aptx
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSink/aac
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/aac
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSink/sbc
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/sbc
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSink/sbc_xq
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/sbc_xq
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/aptx_ll_1
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/aptx_ll_0
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/aptx_ll_duplex_1
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/aptx_ll_duplex_0
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/faststream
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/faststream_duplex
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSink/opus_05
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/opus_05
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSink/opus_05_duplex
Mar 22 12:33:36 x1c bluetoothd[1491894]: Endpoint registered: sender=:1.54 path=/MediaEndpoint/A2DPSource/opus_05_duplex
Mar 22 12:33:36 x1c bluetoothd[1491894]: Failed to load link keys for hci0: Invalid Parameters (0x0d)
Mar 22 16:00:20 x1c bluetoothd[1491894]: /org/bluez/hci0/dev_CC_98_8B_56_73_70/sep1/fd0: fd(43) ready
Mar 23 11:30:12 x1c systemd[1]: bluetooth.service: Main process exited, code=dumped, status=6/ABRT
Mar 23 11:30:12 x1c systemd[1]: bluetooth.service: Failed with result 'core-dump'.

Comment 1 Adam Williamson 2024-04-15 21:17:06 UTC
I *think* this looks like https://github.com/bluez/bluez/issues/785 , right? If so, 5.75 should fix it. I'm gonna mark the 5.75 update as fixing this, please comment if you think that's wrong.

Comment 2 Fedora Update System 2024-04-15 21:19:46 UTC
FEDORA-2024-dcfe1b5905 (bluez-5.75-1.fc40) has been submitted as an update to Fedora 40.
https://bodhi.fedoraproject.org/updates/FEDORA-2024-dcfe1b5905

Comment 3 Fedora Update System 2024-04-16 01:45:36 UTC
FEDORA-2024-dcfe1b5905 has been pushed to the Fedora 40 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2024-dcfe1b5905`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2024-dcfe1b5905

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 4 Zbigniew Jędrzejewski-Szmek 2024-04-16 19:59:46 UTC
It does look similar, though in my case it was caused (I think) by trying to stop the service, not an rfkill block.
I've had it happen a few times since filing the bug, so I'll just keep an
eye out after the update. Thanks!

Comment 5 Fedora Update System 2024-04-19 21:36:10 UTC
FEDORA-2024-dcfe1b5905 (bluez-5.75-1.fc40) has been pushed to the Fedora 40 stable repository.
If problem still persists, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.