Logitech mouse takes ~30 seconds to start working after boot or resume with bluez 5.62

[AdamWill]

This is an upstream report of https://bugzilla.redhat.com/show_bug.cgi?id=2019970 . As described there, I've found that with bluez 5.62 (on Fedora Rawhide), my Bluetooth mouse (a Logitech MX Master 3) takes ~30 seconds to start working after boot or resume from suspend. With Bluez 5.61 it works right when I reach the login screen on boot, and more or less immediately after resume from suspend.

I noticed that with 5.62 I see only one set of initialization messages in the system log, at the exact time the device starts working:

Nov 03 10:59:41 xps13k.happyassassin.net kernel: logitech-hidpp-device 0005:046D:B023.000A: HID++ 4.5 device connected.
Nov 03 10:59:42 xps13k.happyassassin.net upowerd[1488]: treating change event as add on /sys/devices/virtual/misc/uhid/0005:046D:B023.000A/power_supply/hidpp_battery_0
Nov 03 10:59:42 xps13k.happyassassin.net kernel: input: Logitech Wireless Mouse MX Master 3 as /devices/virtual/misc/uhid/0005:046D:B023.000A/input/input39
Nov 03 10:59:42 xps13k.happyassassin.net kernel: logitech-hidpp-device 0005:046D:B023.000A: input,hidraw8: BLUETOOTH HID v0.15 Keyboard [Logitech Wireless Mouse MX Master 3] on 9c:b6:d0:d0:d1:be
Nov 03 10:59:42 xps13k.happyassassin.net systemd-logind[1042]: Watching system buttons on /dev/input/event28 (Logitech Wireless Mouse MX Master 3)

but with 5.61 I see two sets, the first earlier but messier, the second later but cleaner (identical to the 5.62 messages):

Nov 03 11:20:27 xps13k.happyassassin.net bluetoothd[1086]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Nov 03 11:20:27 xps13k.happyassassin.net bluetoothd[1086]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Nov 03 11:20:27 xps13k.happyassassin.net bluetoothd[1086]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Nov 03 11:20:27 xps13k.happyassassin.net bluetoothd[1086]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Nov 03 11:20:27 xps13k.happyassassin.net bluetoothd[1086]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Nov 03 11:20:27 xps13k.happyassassin.net bluetoothd[1086]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Nov 03 11:20:27 xps13k.happyassassin.net bluetoothd[1086]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Nov 03 11:20:27 xps13k.happyassassin.net kernel: input: MX Master 3 Keyboard as /devices/virtual/misc/uhid/0005:046D:B023.0009/input/input36
Nov 03 11:20:27 xps13k.happyassassin.net kernel: input: MX Master 3 Mouse as /devices/virtual/misc/uhid/0005:046D:B023.0009/input/input37
Nov 03 11:20:27 xps13k.happyassassin.net kernel: hid-generic 0005:046D:B023.0009: input,hidraw8: BLUETOOTH HID v0.15 Keyboard [MX Master 3] on 9c:b6:d0:d0:d1:be
Nov 03 11:20:27 xps13k.happyassassin.net kernel: logitech-hidpp-device 0005:046D:B023.0009: HID++ 4.5 device connected.
Nov 03 11:20:27 xps13k.happyassassin.net kernel: input: Logitech Wireless Mouse MX Master 3 as /devices/virtual/misc/uhid/0005:046D:B023.0009/input/input39
Nov 03 11:20:27 xps13k.happyassassin.net kernel: logitech-hidpp-device 0005:046D:B023.0009: input,hidraw8: BLUETOOTH HID v0.15 Keyboard [Logitech Wireless Mouse MX Master 3] on 9c:b6:d0:d0:d1:be
Nov 03 11:20:27 xps13k.happyassassin.net gnome-shell[1504]: Could not open device /dev/input/event29: Could not get device info for path /dev/input/event29: No such file or directory
Nov 03 11:20:27 xps13k.happyassassin.net gnome-shell[1504]: Could not open device /dev/input/event28: GDBus.Error:System.Error.ENODEV: No such device
Nov 03 11:20:27 xps13k.happyassassin.net upowerd[1564]: treating change event as add on /sys/devices/virtual/misc/uhid/0005:046D:B023.0009/power_supply/hidpp_battery_0
Nov 03 11:20:27 xps13k.happyassassin.net systemd-logind[1111]: Watching system buttons on /dev/input/event28 (Logitech Wireless Mouse MX Master 3)

...

Nov 03 11:20:59 xps13k.happyassassin.net kernel: logitech-hidpp-device 0005:046D:B023.000A: HID++ 4.5 device connected.
Nov 03 11:20:59 xps13k.happyassassin.net upowerd[1564]: treating change event as add on /sys/devices/virtual/misc/uhid/0005:046D:B023.000A/power_supply/hidpp_battery_1
Nov 03 11:21:00 xps13k.happyassassin.net kernel: input: Logitech Wireless Mouse MX Master 3 as /devices/virtual/misc/uhid/0005:046D:B023.000A/input/input40
Nov 03 11:21:00 xps13k.happyassassin.net kernel: logitech-hidpp-device 0005:046D:B023.000A: input,hidraw8: BLUETOOTH HID v0.15 Keyboard [Logitech Wireless Mouse MX Master 3] on 9c:b6:d0:d0:d1:be
Nov 03 11:21:00 xps13k.happyassassin.net systemd-logind[1111]: Watching system buttons on /dev/input/event28 (Logitech Wireless Mouse MX Master 3)

[yeezy69]

Seems probably related to #220

[AdamWill]

yeah, may well be. I guess it's the same at the start, then on my system something triggers the system to find it after 30 seconds, which doesn't happen for those other folks (or they just weren't patient enough :>) Thanks!