[WIP] Fix/retry refresh on exception #49

kassick · 2021-11-21T00:39:44Z

After upgrading to Fedora 35, I've noticed that after suspension or long periods with the screen locked, the extension would not reload properly -- no device would show in the menu.

I have observed that on such occasions there would be some message likeCould not create bluez object manager: GDBus.Error:org.freedesktop.DBus.Error.NoReply: Remote peer disconnected

Further debugging has shown that

bluetooth.service restarts with Disconnected from D-Bus. Exiting.
BluetoothController::_getDefaultAdapter would return null
no new signals arrive at the extension

The restarting of bluez seems to happen every suspend/resume and when the screen remains locked for some time.

It seems to be a race condition where the extension instantiates a client that holds a reference to an instance that's about to be killed, and the client does not check the bus for a new instance afterwards.

I implemented this workaround that tries to reconnect on such occasions, but I'm not very happy with it... what happens when the daemon restarts mid-session? Will the extension receive any signal that can eventually trigger a refresh?

(a few tests here have shown that the client will happily point to the new instance in this last case and behaves normally)

I left the MR in [WIP] to discuss if there's some more robust sollution.

_connectSignal is overwritten by `Utils.addSignalsHelperMethods`

Sometimes the already instantiated bluetooth client goes into a weird state where it does not communicate with the bluez daemon anymore. This change forces the recreation of the client when it fails to refresh

bjarosze · 2021-11-22T12:08:06Z

Are there some easy steps to reproduce it? I am using Fedora 35 since beta and never noticed that problem (I go into suspend mode every day).

Getting adapter and devices methods are copy pasted from gnome shell code. Maybe I missed something?
Like those two signals connected (this is from ui/status/bluetooth.js):

this._proxy = new RfkillManagerProxy(Gio.DBus.session, BUS_NAME, OBJECT_PATH,
                                             (proxy, error) => {
                                                 if (error) {
                                                     log(error.message);
                                                     return;
                                                 }

                                                 this._sync();
                                             });
this._proxy.connect('g-properties-changed', this._queueSync.bind(this));

and

        Main.sessionMode.connect('updated', this._sync.bind(this));

Some maybe it would be enough to refresh on those signals? I don't know what are they responsible for 😄

kassick · 2021-11-22T12:55:24Z

Are there some easy steps to reproduce it?

The issue always happened after Suspend/resume and after leaving the screen locked for some time

I am using Fedora 35 since beta and never noticed that problem (I go into suspend mode every day).

Hmmm so I my have a cursed installation :/
I'll try to figure out if anything in my setup deviated from the standard f35

Getting adapter and devices methods are copy pasted from gnome shell code. Maybe I missed something?
Like those two signals connected (this is from ui/status/bluetooth.js):

this._proxy = new RfkillManagerProxy(Gio.DBus.session, BUS_NAME, OBJECT_PATH,
                                             (proxy, error) => {
                                                 if (error) {
                                                     log(error.message);
                                                     return;
                                                 }

                                                 this._sync();
                                             });
this._proxy.connect('g-properties-changed', this._queueSync.bind(this));

I'll take a look if this signal is fired here

and

    Main.sessionMode.connect('updated', this._sync.bind(this));

This one you bind to refresh() in extension.js at the end of BluetoothQuickConnect::_connectControllerSignals ;)

Some maybe it would be enough to refresh on those signals? I don't know what are they responsible for

I'll test and let you know

kassick · 2021-11-22T12:59:00Z

BTW, this is NOT GOOD TO MERGE

I've just unlocked my screen and it's stuck in a refresh loop :(

kassick · 2021-11-22T17:26:40Z

Left the computer locked during lunch. When I came back, the keyboard was still paired, so I entered my password on the bt keyboard. Soon afterwards, I noticed that the extension was missing all the devices.

Did not see the message I added on rfkill's g-properties-changed, so it does not seem like that the extension was missing a signal that it should handle.

nov 22 14:16:50 thnkpd gnome-shell[2522]: [bluetooth-quick-connect] Initializing extension
nov 22 14:16:50 thnkpd dbus-broker[1493]: Peer :1.8 is being disconnected as it sent a message with an invalid body.
nov 22 14:16:50 thnkpd gnome-shell[2522]: [bluetooth-quick-connect] Testing bluetoothctl
nov 22 14:16:50 thnkpd bluetoothd[1444]: Disconnected from D-Bus. Exiting.
nov 22 14:16:50 thnkpd bluetoothd[1444]: Endpoint unregistered: sender=:1.101 path=/MediaEndpoint/A2DPSource/ldac
nov 22 14:16:50 thnkpd bluetoothd[1444]: Endpoint unregistered: sender=:1.101 path=/MediaEndpoint/A2DPSource/aac
nov 22 14:16:50 thnkpd bluetoothd[1444]: Endpoint unregistered: sender=:1.101 path=/MediaEndpoint/A2DPSink/sbc
nov 22 14:16:50 thnkpd bluetoothd[1444]: Endpoint unregistered: sender=:1.101 path=/MediaEndpoint/A2DPSource/sbc
nov 22 14:16:50 thnkpd bluetoothd[1444]: Endpoint unregistered: sender=:1.101 path=/MediaEndpoint/A2DPSink/sbc_xq
nov 22 14:16:50 thnkpd bluetoothd[1444]: Endpoint unregistered: sender=:1.101 path=/MediaEndpoint/A2DPSource/sbc_xq
nov 22 14:16:50 thnkpd bluetoothd[1444]: Endpoint unregistered: sender=:1.101 path=/MediaEndpoint/A2DPSource/faststream
nov 22 14:16:50 thnkpd bluetoothd[1444]: Endpoint unregistered: sender=:1.101 path=/MediaEndpoint/A2DPSource/faststream_duplex
nov 22 14:16:50 thnkpd bluetoothd[1444]: Destroy Adv Monitor Manager
nov 22 14:16:50 thnkpd bluetoothd[1444]: Battery Provider Manager destroyed
nov 22 14:16:50 thnkpd bluetoothd[1444]: Stopping SDP server
nov 22 14:16:50 thnkpd bluetoothd[1444]: Exit
nov 22 14:16:50 thnkpd systemd[1]: bluetooth.service: Deactivated successfully.
nov 22 14:16:50 thnkpd audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=bluetoo>
nov 22 14:16:50 thnkpd systemd[1]: bluetooth.service: Consumed 11.296s CPU time.
nov 22 14:16:50 thnkpd systemd[1]: Starting Bluetooth service...
nov 22 14:16:50 thnkpd gnome-shell[2522]: [bluetooth-quick-connect] Test succeeded
nov 22 14:16:50 thnkpd gnome-shell[2522]: [bluetooth-quick-connect] Enabling extension
nov 22 14:16:50 thnkpd gnome-shell[2522]: [bluetooth-quick-connect] Refreshing devices list
nov 22 14:16:50 thnkpd gnome-shell[2522]: [bluetooth-quick-connect] Connecting bluetooth controller signals
nov 22 14:16:50 thnkpd gnome-shell[2522]: [bluetooth-quick-connect] Connecting idle monitor
nov 22 14:16:50 thnkpd gnome-shell[2522]: Could not create bluez object manager: GDBus.Error:org.freedesktop.DBus.Error.NoReply: Remote pee>
nov 22 14:16:50 thnkpd bluetoothd[15171]: src/main.c:btd_parse_experimental() Invalid Experimental UUID: none
nov 22 14:16:50 thnkpd bluetoothd[15171]: Bluetooth daemon 5.62
nov 22 14:16:50 thnkpd systemd[1]: Started Bluetooth service.
nov 22 14:16:50 thnkpd audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=blueto>
nov 22 14:16:50 thnkpd bluetoothd[15171]: Starting SDP server
nov 22 14:16:50 thnkpd bluetoothd[15171]: Bluetooth management interface 1.21 initialized
nov 22 14:16:50 thnkpd bluetoothd[15171]: Battery Provider Manager created
nov 22 14:16:50 thnkpd bluetoothd[15171]: Failed to set privacy: Rejected (0x0b)
nov 22 14:16:50 thnkpd bluetoothd[15171]: Adv Monitor Manager created with supported features:0x00000001, enabled features:0x00000001, max >
nov 22 14:16:50 thnkpd audit: BPF prog-id=68 op=LOAD
nov 22 14:16:50 thnkpd audit: BPF prog-id=69 op=LOAD
nov 22 14:16:50 thnkpd systemd[1]: Starting Hostname Service...
nov 22 14:16:50 thnkpd NetworkManager[1567]: <info>  [1637601410.5745] agent-manager: agent[54f715af0524ac7c,:1.90/org.gnome.Shell.NetworkA>
nov 22 14:16:50 thnkpd systemd[1]: Started Hostname Service.
nov 22 14:16:50 thnkpd audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=system>
nov 22 14:16:50 thnkpd bluetoothd[15171]: Player registered: sender=:1.101 path=/media_player1
nov 22 14:16:50 thnkpd bluetoothd[15171]: Endpoint registered: sender=:1.101 path=/MediaEndpoint/A2DPSource/ldac
nov 22 14:16:50 thnkpd bluetoothd[15171]: Endpoint registered: sender=:1.101 path=/MediaEndpoint/A2DPSource/aac
nov 22 14:16:50 thnkpd bluetoothd[15171]: Endpoint registered: sender=:1.101 path=/MediaEndpoint/A2DPSink/sbc
nov 22 14:16:50 thnkpd bluetoothd[15171]: Endpoint registered: sender=:1.101 path=/MediaEndpoint/A2DPSource/sbc
nov 22 14:16:50 thnkpd bluetoothd[15171]: Endpoint registered: sender=:1.101 path=/MediaEndpoint/A2DPSink/sbc_xq
nov 22 14:16:50 thnkpd bluetoothd[15171]: Endpoint registered: sender=:1.101 path=/MediaEndpoint/A2DPSource/faststream_duplex
nov 22 14:16:51 thnkpd bluetoothd[15171]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
<previous line repeated several times>
nov 22 14:16:51 thnkpd kernel: input: MX Anywhere 2S Keyboard as /devices/virtual/misc/uhid/0005:046D:B01A.0006/input/input42
nov 22 14:16:51 thnkpd kernel: input: MX Anywhere 2S Mouse as /devices/virtual/misc/uhid/0005:046D:B01A.0006/input/input43
nov 22 14:16:51 thnkpd kernel: hid-generic 0005:046D:B01A.0006: input,hidraw1: BLUETOOTH HID v0.03 Keyboard [MX Anywhere 2S] on cc:f9:e4:80:48:4a
nov 22 14:16:52 thnkpd systemd-logind[1460]: Watching system buttons on /dev/input/event21 (MX Anywhere 2S Keyboard)
nov 22 14:16:54 thnkpd gnome-shell[2522]: [bluetooth-quick-connect] Menu toggled: true

kassick · 2021-11-22T18:02:46Z

Maybe related: https://bugs.archlinux.org/task/72540 -- someone reporting that bluez disconencted after using bluetoothctl -- exactly what the extension does upon initialization.

EDIT: ltracing bluetoothctl --version it does not seem like it touches anything in dbus, so it's unlikely to be causing the daemon to restart.

depadiernos · 2023-01-20T04:57:26Z

Just chiming in to say that I also see this issue where I would get an error popup regarding bluetoothctl and from there, the extension no longer works.

I am running Archlinux.

kassick added 6 commits November 20, 2021 21:03

fix: retry refresh on exception

45d8287

fix: use right method name

37ca270

chore: remove unused method

53f2139

_connectSignal is overwritten by `Utils.addSignalsHelperMethods`

feat: add _disconnectSubjectSignals method

9d8320c

fix: when failing to refresh, try to recreate the bluetooth client

a419a75

Sometimes the already instantiated bluetooth client goes into a weird state where it does not communicate with the bluez daemon anymore. This change forces the recreation of the client when it fails to refresh

refactor: use List.filter to filter lists

8f8bb05

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[WIP] Fix/retry refresh on exception #49

[WIP] Fix/retry refresh on exception #49

kassick commented Nov 21, 2021

bjarosze commented Nov 22, 2021 •

edited

Loading

kassick commented Nov 22, 2021 •

edited

Loading

kassick commented Nov 22, 2021

kassick commented Nov 22, 2021

kassick commented Nov 22, 2021 •

edited

Loading

depadiernos commented Jan 20, 2023

[WIP] Fix/retry refresh on exception #49

Are you sure you want to change the base?

[WIP] Fix/retry refresh on exception #49

Conversation

kassick commented Nov 21, 2021

bjarosze commented Nov 22, 2021 • edited Loading

kassick commented Nov 22, 2021 • edited Loading

kassick commented Nov 22, 2021

kassick commented Nov 22, 2021

kassick commented Nov 22, 2021 • edited Loading

depadiernos commented Jan 20, 2023

bjarosze commented Nov 22, 2021 •

edited

Loading

kassick commented Nov 22, 2021 •

edited

Loading

kassick commented Nov 22, 2021 •

edited

Loading