Blueman-applet wrong battery percentage in Notification

[Chr1s70ph]

blueman: 2.2.4-1 BlueZ: 5.63-2 Distribution: Linux manjaro 5.16.14-1-MANJARO Desktop environment: i3wm

• [x] I have consulted the Troubleshooting page and done my best effort to follow.

Connecting my XBOX-Controller displays a wrong battery percentage in the notification. As seen in the logs below, blueman does fetch 50% first (thats what is sent in the notification) and only afterwards fetches the correct battery percentage.

blueman-applet 15.39.31 DEBUG    Base:60 do_g_properties_changed: /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF {'Connected': True}
blueman-applet 15.39.32 DEBUG    Base:60 do_g_properties_changed: /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF {'Percentage': 50}
blueman-applet 15.39.32 DEBUG    Base:60 do_g_properties_changed: /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF {'ServicesResolved': True}
blueman-applet 15.39.36 DEBUG    Base:60 do_g_properties_changed: /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF {'Percentage': 78}

This is not a Controller driver issue, already discussed in XPADNEO-Issue #342

[cschramm]

Sounds like that's what the device provides via Bluetooth. You can double-check where BlueZ gets its values from by enabling debugging output for bluetoothd using -d src/battery.c,profiles/battery/battery.c (or even look into the raw data with btmon if you feel adventurous).

Our Battery applet plugin currently shows the percentage on connection and that is obviously the 50 %. I think there's nothing we can do to avoid it. What we could do is change the concept of the plugin and send notifications on changes as well, so that at least the 78 % will get reported (~4 seconds later).

[infirit]

I don't have an Xbox controller but I'll check how hid-nintendo handles this. I don't think it currently reports battery level at all but if it does I'll report back.

edit: It doesn't report battery levels

[Chr1s70ph]

This is the output of bluetoothd

```console bluetoothd[46166]: Bluetooth daemon 5.63 bluetoothd[46166]: MinConnectionInterval=7 bluetoothd[46166]: MaxConnectionInterval=9 bluetoothd[46166]: ConnectionLatency=0 bluetoothd[46166]: Starting SDP server bluetoothd[46166]: Bluetooth management interface 1.21 initialized bluetoothd[46166]: profiles/battery/battery.c:batt_probe() BATT profile probe (F4:6A:D7:E6:73:BF) bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/ldac_hq bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/ldac_sq bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/ldac_mq bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSink/aptx_hd bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/aptx_hd bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSink/aptx bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/aptx bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSink/sbc bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/sbc bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSink/sbc_xq_453 bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/sbc_xq_453 bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSink/sbc_xq_512 bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/sbc_xq_512 bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSink/sbc_xq_552 bluetoothd[46166]: Endpoint registered: sender=:1.43 path=/MediaEndpoint/A2DPSource/sbc_xq_552 bluetoothd[46166]: profiles/battery/battery.c:batt_accept() BATT profile accept (F4:6A:D7:E6:73:BF) bluetoothd[46166]: src/battery.c:btd_battery_register() path = /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF bluetoothd[46166]: src/battery.c:btd_battery_register() registered Battery object: /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF bluetoothd[46166]: profiles/battery/battery.c:parse_battery_level() Battery Level updated: 50% bluetoothd[46166]: src/battery.c:btd_battery_update() path = /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF bluetoothd[46166]: profiles/battery/battery.c:batt_io_ccc_written_cb() Battery Level: notification enabled bluetoothd[46166]: profiles/battery/battery.c:parse_battery_level() Battery Level updated: 77% bluetoothd[46166]: src/battery.c:btd_battery_update() path = /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF ```

To me it looks like, the battery level update function is called, before the device is fully connected and in the state to transmit the correct battery level. (Hence Battery Level: notification enabled after the 50%, and right before the 77% notification)

What we could do is change the concept of the plugin and send notifications on changes as well

I think that would not be the best practice. Batteries tend to lose power over time, so there would be a new notification for each percentage change. Seems kind of overkill to me

Also noteworthy: Sometimes it actually fetches the correct value. As seen in my bluetoothd logs, profiles/battery/battery.c:parse_battery_level() is called twice. In the case, that the correct value is fetched already, the function does not fire a second time.

[cschramm]

I don't think BlueZ is at fault. The situation very much seems like the device offers a Battery Service with a Battery Level State (0x2A1B) characteristic with initial value 50. Why do you think the device isn't fully connected at when it gets parsed?

[Chr1s70ph]

Looking at the dmesg logs I can see, that the notification is sent, before I get this message: [16706.196454] xpadneo 0005:045E:0B13.001E: Xbox Wireless Controller [f4:6a:d7:e6:73:bf] connected. I am no time wizard, but that makes me believe, that the notification is sent before it is fully connected. The update to the battery percentage is sent about 3-4 seconds after the controller is fully connected.

[cschramm]

In your initial blueman-applet log we can see that the device gets connected, the initial battery percentage gets read and service resolution finishes. The reason Percentage gets set before ServicesResolved is that the initial read is part of the service resolution. It makes sense that xpadneo picks up the device later as it's a HID driver and the HID device gets created during or even after service resolution.

At the point where bluetoothd reads the Battery Level State, it's already subscribed to changes and from its perspective everything is set up when service resolution is done, so the device still provides 50 % and there is no clue that it might be wrong and get updated 4 seconds later because the device has to rethink what it said 4 seconds earlier.

The question is what happens after those 4 seconds. It might be that some higher level (HID, proprietary, whatever) setup finishes and causes the device to provide a different value. That's on a completely different layer than the Bluetooth services, though, and I don't really expect xpadneo to spend 4 seconds with any setup.

[infirit]

We could delay a few seconds before reporting the battery level but 4 seconds is too long.

[Chr1s70ph]

I did some more digging, and found out, that in between those two battery notifications, some features are started and updated (?)

bluetoothd[90167]: src/battery.c:btd_battery_register() registered Battery object: /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF
bluetoothd[90167]: profiles/battery/battery.c:parse_battery_level() Battery Level updated: 50%
bluetoothd[90167]: src/battery.c:btd_battery_update() path = /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF
bluetoothd[90167]: profiles/battery/battery.c:batt_io_ccc_written_cb() Battery Level: notification enabled
bluetoothd[90167]: profiles/input/hog-lib.c:forward_report() Sending report type 2 ID 3 to handle 0x22
bluetoothd[90167]: attrib/gattrib.c:g_attrib_unref() 0x55b03e1d3d10: g_attrib_unref=2 
bluetoothd[90167]: src/device.c:gatt_debug() Primary services found: 6
bluetoothd[90167]: src/device.c:gatt_debug() start: 0x0001, end: 0x0007, uuid: 00001800-0000-1000-8000-00805f9b34fb
bluetoothd[90167]: src/device.c:gatt_debug() start: 0x0008, end: 0x0008, uuid: 00001801-0000-1000-8000-00805f9b34fb
bluetoothd[90167]: src/device.c:gatt_debug() start: 0x0009, end: 0x0011, uuid: 0000180a-0000-1000-8000-00805f9b34fb
bluetoothd[90167]: src/device.c:gatt_debug() start: 0x0012, end: 0x0015, uuid: 0000180f-0000-1000-8000-00805f9b34fb
bluetoothd[90167]: src/device.c:gatt_debug() start: 0x0016, end: 0x0023, uuid: 00001812-0000-1000-8000-00805f9b34fb
bluetoothd[90167]: src/device.c:gatt_debug() start: 0x0024, end: 0x002a, uuid: 00000001-5f60-4c4f-9c83-a7953298d40d
bluetoothd[90167]: src/device.c:gatt_client_ready_cb() status: success, error: 10
bluetoothd[90167]: src/gatt-client.c:btd_gatt_client_ready() GATT client ready
bluetoothd[90167]: src/gatt-client.c:create_services() Exporting objects for GATT services: F4:6A:D7:E6:73:BF
bluetoothd[90167]: src/gatt-client.c:btd_gatt_client_ready() Features 0x00
bluetoothd[90167]: src/gatt-client.c:btd_gatt_client_ready() Update Features 0x00
bluetoothd[90167]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF err 0
bluetoothd[90167]: src/device.c:gatt_debug() (chan 0x55b03e1ce650) ATT PDU received: 0x1b
bluetoothd[90167]: profiles/battery/battery.c:parse_battery_level() Battery Level updated: 100%
bluetoothd[90167]: src/battery.c:btd_battery_update() path = /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF

[cschramm]

@Chr1s70ph: There are no timestamps, so I cannot see where the ~4 seconds delay is, but I'd guess that everything up to and including

src/device.c:device_svc_resolved() /org/bluez/hci0/dev_F4_6A_D7_E6_73_BF err 0

gets emitted before that gap.

src/device.c:gatt_debug() (chan 0x55b03e1ce650) ATT PDU received: 0x1b

is just the incoming battery level update.

[Chr1s70ph]

Sorry, I forgot to add the timestamps.

I think this is hopeless, and I'll just have to write a script, that either removes the battery percentage from the notification, or brainstorm something else.

[cschramm]

If it's just the notification that bugs you, you can disable the Battery plugin.

I'm happy to add a workaround to blueman if we find any criteria that indicates that the initial level is wrong and / or that a proper value will only be available after a certain event. So far it looks like the device just provides a 50 % value initially and as that value is absolutely fine in general (actually a lot of devices show discrete values like 100 %, 50 %, 20%, ..., so 50 % is very likely), the only possibilities I see are either delaying the notification by ~5 seconds in general or hard-coding something for the specific device.

[kakra]

The maintainer of xpadneo here...

The way it works is that xpadneo creates a power supply device and attaches it to the controller the first time we receive a HID battery report. That incident is logged with "battery detected" by xpadneo in dmesg. So if xpadneo never receives such a report, no battery will be created. It fixed strange 50% issues in the past. With the new BLE firmware of the controller, we no longer get battery reports from the device, thus no power supply is registered, no "battery detected" message is logged.

The delay of 4 seconds rings some bells, tho. After booting the controller, it reports battery status updates multiple times usually 4 seconds apart, and the first report only came after around 4 seconds, (almost) never immediately. It probably still does the same with BLE, with the difference that this information never passes through xpadneo. That 4 seconds timer is not always consistent, sometimes, the first report came in immediately, sometimes it took even 30 seconds or more. It's probably some calibration routine inside the firmware that causes it.

So whatever piece of software creates the battery device, it should do it only after actually receiving the first report, not on the pure assumption that the device has support for such a feature. I've looked at different implementations during my research, and it looked like common sense to init the battery device with 50% before the first update was received, and that's actually why I changed my implementation to create the xpadneo battery only after receiving the first report. It may explain what we are seeing.

[cschramm]

Hey @kakra,

whatever piece of software creates the battery device, it should do it only after actually receiving the first report, not on the pure assumption that the device has support for such a feature

not sure what you mean with "piece of software that creates the battery device". What's going on is that the device itself exposes a BLE Battery Level GATT characteristic and BlueZ picks it up and exposes the value on its D-Bus API where blueman picks it up. You can tell from the bluetoothd logs that the characteristic is available, so the 50 % is coming from the device itself.

There (typically) are no periodic events for GATT characteristics as long as nothing changes, so we cannot just await a second value in general as we'd not show anything for most devices then.

[infirit]

How about we:

1. Delay the notification a second.
2. Set the timeout of the notification to 4 seconds (by the end it should have updated the battery level)
3. If we get a different battery level within those 3 seconds we replace the notification with a new one, once.

I really think delaying it for 5 seconds is way too long. My BLE mouse connects instantly so a notification showing after using it for 5 seconds is weird.

[kakra]

Ah, okay, so blueman just pushes a notification to the desktop, it's not actually a live sensor?

So I'm seeing this in upower -d:

# First call
Device: /org/freedesktop/UPower/devices/gaming_input_dev_44_16_22_BD_48_69
  native-path:          /org/bluez/hci0/dev_44_16_22_BD_48_69
  model:                Xbox Wireless Controller
  serial:               44:16:22:BD:48:69
  power supply:         no
  updated:              Fr 08 Apr 2022 21:16:00 CEST (4 seconds ago)
  has history:          yes
  has statistics:       no
  gaming-input
    rechargeable:        no
    warning-level:       none
    percentage:          50%
    icon-name:          'battery-missing-symbolic'

# Second call
Device: /org/freedesktop/UPower/devices/gaming_input_dev_44_16_22_BD_48_69
  native-path:          /org/bluez/hci0/dev_44_16_22_BD_48_69
  model:                Xbox Wireless Controller
  serial:               44:16:22:BD:48:69
  power supply:         no
  updated:              Fr 08 Apr 2022 21:16:05 CEST (13 seconds ago)
  has history:          yes
  has statistics:       no
  gaming-input
    rechargeable:        no
    warning-level:       none
    percentage:          100%
    icon-name:          'battery-missing-symbolic'

KDE seems to query that to display battery info, it only generates notifications if the capacity falls to critical.

The battery level can fall quite dramatically throughout a longer gaming session, the controller support a battery live of 20-40 hours (also depending on age of the battery). If you do an 8 hour gaming session, that's almost 50% of the battery capacity in the worst case. So why not always replace the notification on changes? It seems weird to see a capacity notification that's potentially 8 hours out of date. OTOH, I know nothing about blueman because I don't use it, take my suggestions as totally uneducated words. I can only tell you how the controller is working. ;-)

[infirit]

UPower gets it's information from dbus interface org.bluez.Battery1, the same interface we use in Blueman.

The notification we are talking about here is shown when a device is connected. It can optionally show the battery percentage, but it is only shown once. It's not a notification meant to show the state of the battery over time.

We are dealing with the same problem described in #342. Neither xpadneo nor Blueman are at "fault" but at least we have a better understanding why it happens. Now chris and I have to figure out a way to not confuse the users.

I do appreciate you contributing to the discussion.

@Chr1s70ph I'm reopening this and make it a feature request. If you rather not get notification you unsubscribe but I hope you are willing to test when we come up with something :-)

[cschramm]

1. Delay the notification a second.
2. Set the timeout of the notification to 4 seconds (by the end it should have updated the battery level)
3. If we get a different battery level within those 3 seconds we **replace** the notification with a new one, once.

:thinking:

What's the idea behind step 1?

The idea behind step 2 is that it gives us a defined time for which the notification is displayed, right? I guess we could go without that and keep relying on the notification daemon's default timeout: We could just pick a fixed time span, say 5 seconds, for which we'll keep listening for updates and replace the notification. In the standard case, nothing will change. In case an update comes in within 5 seconds, it will get updated and keep showing for the daemon's default time. In the unusual case that the timeout is less than 5 seconds, it will lead to a second notification, but that shouldn't hurt.

[Chr1s70ph]

@Chr1s70ph I'm reopening this and make it a feature request. If you rather not get notification you unsubscribe but I hope you are willing to test when we come up with something :-)

Sure, Id like to test it 👍🏼

[infirit]

What's the idea behind step 1?

The idea behind step 2 is that it gives us a defined time for which the notification is displayed, right?

Mixing two approaches in my head :sweat_smile:. Just delaying for 5 seconds is indeed the same. I'm testing the battery on my bluetooth headphones and they also need a slight delay so I'll be testing with 5 seconds.

[Chr1s70ph]

@infirit I know this has already been merged, but I have done some initial testing, and the problem seems to be resolved. Thank you for investing all that time into fixing this!

[infirit]

Ah, sorry @Chr1s70ph, forgot to post an update here. Thanks for confirming.