Bug 481870 - Bluetooth related 25 second delay after logging in
Summary: Bluetooth related 25 second delay after logging in
Status: RESOLVED FIXED
Alias: None
Product: frameworks-bluez-qt
Classification: Frameworks and Libraries
Component: general (show other bugs)
Version: unspecified
Platform: Other Linux
: HI normal
Target Milestone: ---
Assignee: David Rosca
URL:
Keywords: qt6
: 481805 482538 482675 483247 (view as bug list)
Depends on:
Blocks:
 
Reported: 2024-02-26 18:53 UTC by tagwerk19
Modified: 2024-08-01 18:55 UTC (History)
8 users (show)

See Also:
Latest Commit:
Version Fixed In: the next KDE Connect release
Sentry Crash Report:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description tagwerk19 2024-02-26 18:53:42 UTC
SUMMARY
    25 second delay after logging in before the Plasma panel appears

STEPS TO REPRODUCE
    1. Install Neon Testing, neon-testing-20240207-1524.iso, as a KVM guest…
    2. Log on and watch how long to takes before the panel appears
    3. Run journalct to check for errors
    4. Bring up to date (to 2024/02/26) and repeat

OBSERVED RESULT
    There's a noted (25 second) pause after logging on before you get shown the panel

    Journalctl shows failures, in X11:

        19:33:41 ... dbus-daemon[454]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
        19:33:41 ... pulseaudio[2660]: GetManagedObjects() failed: org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms) 
        19:33:41 ... kded6[2383]: kf.bluezqt: PendingCall Error: "Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)"
        19:33:41 ... dbus-daemon[454]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.114' (uid=1000 pid=2556 comm="/usr/lib/x86_64-linux-gnu/libexec/kdeconnectd " label="unconfined")
        19:34:06 ... dbus-daemon[454]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)

    With Wayland, the errors are:

        19:42:31 ... dbus-daemon[437]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.37' (uid=1000 pid=791 comm="/usr/bin/pulseaudio --daemonize=no --log-target=jo" label="unconfined")
        19:42:56 ... dbus-daemon[437]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
        19:42:56 ... dbus-daemon[437]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.69' (uid=1000 pid=1124 comm="/usr/lib/x86_64-linux-gnu/libexec/kdeconnectd " label="unconfined")

EXPECTED RESULT
    Logon should not hang waiting for the org.bluez service - or should check whether Bluetooth is activated or not

SOFTWARE/OS VERSIONS
    Neon Testing
    Plasma: 6.0.0
    Frameworks: 6.0.0
    Qt Version: 6.6.2
    Kernel: 6.5.0-21-generic (64-bit)

ADDITIONAL INFORMATION

   The wallpaper might appear earlier or not, it seems to if you are running X. The delay is the same whether X11 or Wayland

   Updating to the state 2024/02/26 makes no difference.
Comment 1 tagwerk19 2024-02-28 07:54:19 UTC
This doesn't seem to affect all Neon Testing systems, I have one older version where it works.

What seems different is that the failing systems have:

    $ systemctl --user status obex
    ○ obex.service - Bluetooth OBEX service
         Loaded: loaded (/usr/lib/systemd/user/obex.service; disabled; vendor preset: enabled)
         Active: inactive (dead)

and the working system has:

    $ systemctl --user status obex
    ● obex.service - Bluetooth OBEX service
         Loaded: loaded (/usr/lib/systemd/user/obex.service; disabled; vendor preset: enabled)
         Active: active (running) since Tue 2024-02-27 23:26:19 CET; 21s ago
       Main PID: 1154 (obexd)
          Tasks: 1 (limit: 9361)
         Memory: 2.0M
            CPU: 6ms
         CGroup: /user.slice/user-1000.slice/user@1000.service/app.slice/obex.service
                 └─1154 /usr/lib/bluetooth/obexd
         
    Feb 27 23:26:19 neon-testing systemd[774]: Starting Bluetooth OBEX service...
    Feb 27 23:26:19 neon-testing obexd[1154]: OBEX daemon 5.64
    Feb 27 23:26:19 neon-testing systemd[774]: Started Bluetooth OBEX service.
        
It's not evident what is forcing the service on or off. Just doing a:
    
    $ systemctl --user enable obex
    $ systemctl --user start obex

seems *not* to be enough. What seems new is that the desktop hangs until the service_start_timeout

Found this lead from https://bugs.archlinux.org/task/45816, dated 2015
Comment 2 tagwerk19 2024-02-28 23:05:13 UTC
Bug 481959 describes something similar
Comment 3 tagwerk19 2024-02-29 17:30:29 UTC
Also Bug 481805
Comment 4 tagwerk19 2024-02-29 20:55:55 UTC
See Bug 482082 which has the summary:

By default, the Breeze Splash screen is enabled. I noticed the system took a long time to log in after entering my password after upgrading to Neon / Plasma 6. I went to disable to splash screen in order to look at the text of what was being loaded and this time logging in to the desktop was almost instantaneous.
Comment 5 tagwerk19 2024-03-01 08:50:08 UTC
(In reply to tagwerk19 from comment #4)
> See Bug 482082 which has the summary:
> 
> By default, the Breeze Splash screen is enabled. I noticed the system took a
> long time to log in after entering my password after upgrading to Neon /
> Plasma 6. I went to disable to splash screen in order to look at the text of
> what was being loaded and this time logging in to the desktop was almost
> instantaneous.

A mentioned here: https://bugs.kde.org/show_bug.cgi?id=482082#c5

> There must be more than one issue in play here...
>   
> I've tried setting the splash screen to "none" (something that crashed systemsettings)
> in a test VM. Rebooting and logging on with Wayland and X11, I still get the org.bluez
> timeout and no difference to the logon delay.
Comment 6 tagwerk19 2024-03-01 18:35:47 UTC
(In reply to Arjen Hiemstra from comment https://bugs.kde.org/show_bug.cgi?id=482082#c7)
> Just to collect some extra data, can we the output of `systemd-analyze --user blame` for those that
> can reproduce this bug? While there is something going on with ksplash it'd be useful to exclude
> other things going wrong.
That was in the context of the splash screen mak a difference, seems not the case here, the result of "journalctl | grep blue":

    Mar 01 16:25:56 ... NetworkManager[383]: <info>  [1709306756.8001] Loaded device plugin: NMBluezManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.36.6/libnm-device-plugin-bluetooth.so)
    Mar 01 16:26:06 ... dbus-daemon[382]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.36' (uid=1000 pid=727 comm="/usr/bin/pulseaudio --daemonize=no --log-target=jo" label="unconfined")
    Mar 01 16:26:31 ... dbus-daemon[382]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
    Mar 01 16:26:31 ... dbus-daemon[382]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.71' (uid=1000 pid=997 comm="/usr/lib/x86_64-linux-gnu/libexec/kdeconnectd " label="unconfined")
    Mar 01 16:26:56 ... dbus-daemon[382]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
    Mar 01 16:26:56 ... kdeconnectd[997]: 2024-03-01T16:26:56 kdeconnect.core: No local bluetooth adapter found

and "systemd-analyze --user blame":

    1.526s xdg-desktop-portal.service
     961ms plasma-kcminit.service
     675ms xdg-desktop-portal-gtk.service
     319ms plasma-powerdevil.service
     188ms plasma-plasmashell.service
     184ms pulseaudio.service
     181ms plasma-xdg-desktop-portal-kde.service
     180ms plasma-polkit-agent.service
     144ms plasma-ksmserver.service
     134ms plasma-kded6.service
      75ms plasma-kactivitymanagerd.service
      49ms app-kaccess@autostart.service
      47ms app-org.kde.discover.notifier@autostart.service
      46ms app-lts_eol@autostart.service
      44ms plasma-kwin_wayland.service
      43ms app-org.kde.xwaylandvideobridge@autostart.service
      43ms plasma-restoresession.service
      38ms kde-baloo.service 
      33ms plasma-kglobalaccel.service
      27ms app-geoclue\x2ddemo\x2dagent@autostart.service
      19ms plasma-kcminit-phase1.service
      15ms session-migration.service
      11ms app-org.kde.kdeconnect.daemon@autostart.service
       9ms xdg-document-portal.service
       7ms dconf.service
       7ms xdg-desktop-portal-rewrite-launchers.service
       6ms at-spi-dbus-bus.service
       4ms app-snap\x2duserd\x2dautostart@autostart.service
       3ms xdg-permission-store.service
       3ms dbus.socket

The "blame" does not look particularly different between systems with the 25 sec bluez timeout and those without.
Comment 7 Harald Sitter 2024-03-02 12:12:51 UTC
*** Bug 481805 has been marked as a duplicate of this bug. ***
Comment 8 Harald Sitter 2024-03-02 12:13:38 UTC
*** Bug 482192 has been marked as a duplicate of this bug. ***
Comment 9 Harald Sitter 2024-03-02 12:15:19 UTC
Git commit 83708cdb20448e908641e7a546e1a301532d9f96 by Harald Sitter.
Committed on 02/03/2024 at 12:14.
Pushed by sitter into branch 'Neon/release'.

temporarily disable the bluetooth link

it unreasonably blocks plasma startup
https://invent.kde.org/network/kdeconnect-kde/-/merge_requests/600#note_884500

fail the build to revisit this in April

M  +11   -0    debian/rules

https://invent.kde.org/neon/kde/kdeconnect/-/commit/83708cdb20448e908641e7a546e1a301532d9f96
Comment 10 Nate Graham 2024-03-04 18:35:55 UTC
Re-opening as this appears to be a general issue not specific to Neon.
Comment 11 Nate Graham 2024-03-04 18:49:12 UTC
A fix is in progress with https://invent.kde.org/network/kdeconnect-kde/-/merge_requests/643.
Comment 12 Nate Graham 2024-03-06 18:06:31 UTC
*** Bug 482538 has been marked as a duplicate of this bug. ***
Comment 13 Nate Graham 2024-03-07 19:48:37 UTC
*** Bug 482675 has been marked as a duplicate of this bug. ***
Comment 14 Nate Graham 2024-03-11 19:08:11 UTC
*** Bug 483247 has been marked as a duplicate of this bug. ***
Comment 15 Nate Graham 2024-03-15 16:02:12 UTC
Fixed by Simon Redman in https://invent.kde.org/network/kdeconnect-kde/-/commit/7f3287a71b7d1acd30724d05a0719312a5b8ae94 by disabling the KDE Connect Bluetooth backend for now. More targeted fixes are also in flight.

KDE Connect hasn't had a release, so at this point we're relying on distros to cherry-pick the fix, which has been recommended in https://mail.kde.org/pipermail/distributions/2024-March/001481.html. The flow of bug reports has tapered off, so it seems like that's been broadly happening.
Comment 16 tagwerk19 2024-03-17 09:19:05 UTC
(In reply to Nate Graham from comment #15)
> ... The flow of bug reports has tapered off ...
I think the earlier workrounds hadn't necessarily worked but seems fixed now.
Comment 17 Simon Redman 2024-07-22 21:29:10 UTC
Git commit bb146a76d06a9039d55661a3e4fc42176c078643 by Simon Redman, on behalf of Rob Emery.
Committed on 22/07/2024 at 21:29.
Pushed by sredman into branch 'master'.

Bluetooth provider workaround for BlueZ/DBus timeouts

Context: https://invent.kde.org/network/kdeconnect-kde/-/merge_requests/600#note_884500

When bluetooth doesn't exist on the machine at all, QTConnectivity
tries to communicate with Bluez via dbus and introduces a 30 odd second
pause. That's not necessarily a problem in concept, however this blocks
the main thread of KDEConnect, which also then blocks the main thread
of Plasma on logon and causes tremendous delays and very broken
behaviour.

For the life of me, I cannot find a way to do "is bluetooth ok" without
QTConnect kicking off the dbus call so I think the only option is to
thread off the startup of the providers so that pauses don't block
the whole process.

I've just tested this here and my logon with bluetooth missing went
from approx 35 seconds down to about 2.

Ready for input/feedback whenever people have time; in my testing at the moment it seems to completely break the behaviour of KDEConnect (i.e. things can't connect), I'm guessing this is something to do with the effect of wrapping everything in the QThread. I'll dig into that next and see if I can figure it out.

M  +15   -4    core/daemon.cpp

https://invent.kde.org/network/kdeconnect-kde/-/commit/bb146a76d06a9039d55661a3e4fc42176c078643
Comment 18 Simon Redman 2024-07-31 21:31:03 UTC
Git commit 8eff1dcca79efc0fe7bf1f6320f40692e0d313d7 by Simon Redman.
Committed on 31/07/2024 at 21:25.
Pushed by sredman into branch 'release/24.08'.

Bluetooth provider workaround for BlueZ/DBus timeouts

Context: https://invent.kde.org/network/kdeconnect-kde/-/merge_requests/600#note_884500

When bluetooth doesn't exist on the machine at all, QTConnectivity
tries to communicate with Bluez via dbus and introduces a 30 odd second
pause. That's not necessarily a problem in concept, however this blocks
the main thread of KDEConnect, which also then blocks the main thread
of Plasma on logon and causes tremendous delays and very broken
behaviour.

For the life of me, I cannot find a way to do "is bluetooth ok" without
QTConnect kicking off the dbus call so I think the only option is to
thread off the startup of the providers so that pauses don't block
the whole process.

I've just tested this here and my logon with bluetooth missing went
from approx 35 seconds down to about 2.

Ready for input/feedback whenever people have time; in my testing at the moment it seems to completely break the behaviour of KDEConnect (i.e. things can't connect), I'm guessing this is something to do with the effect of wrapping everything in the QThread. I'll dig into that next and see if I can figure it out.


(cherry picked from commit bb146a76d06a9039d55661a3e4fc42176c078643)

4beb8c65 Fixing hanging startup/logon when bluetooth is unavailable

Co-authored-by: Rob Emery <kde@mintsoft.net>

M  +15   -4    core/daemon.cpp

https://invent.kde.org/network/kdeconnect-kde/-/commit/8eff1dcca79efc0fe7bf1f6320f40692e0d313d7
Comment 19 Simon Redman 2024-08-01 18:55:35 UTC
Hey all. We believe we have fixed this, and we are reenabling Bluetooth by default in KDE Connect 24.08 - please let us know if you notice anything fishy.