I3status-rust: Bluetooth devices' MAC addresses may not be present in D-Bus in all circumstances

[atheriel]

@marzzzello reports in the Bluetooth PR, #357:

I just have the problem that when bluetooth is off, I get
Error in block 'bluetooth': Failed find a device with matching MAC address.
It would be good to ignore that case and not to let i3status-rust fail

I have been unable to replicate this. If anyone else can find the source of the issue, it would be much appreciated.

[SWW13]

The error may appear when the controller is disabled, at least that's when I get that error.
For me that's a common case because I only enable the controller while using it.

I've looked into the code and I'm not sure how to workaround this without a big overhead.
There could be an optional path config to skip the search, but then the icon is missing / wrong when the controller is disabled. This also needs an extra documentation on how to obtain the path.

[mweinelt]

I usually have two bluetooth devices I work with, a trackball and headsets. Currently neither one is connected to my PC, but the trackball appears in upower -d, while the headset does not. I restarted upower ~15 hours ago and it was working before that. I have used the trackball since, but haven't used the headset, so I can only assume that the module currently requires state from upower that is only held in memory and is lost upon restart of the service.

The module should idealy be more forgiving about missing bluetooth devices. If picking the correct icon is an issue then maybe let me pick one in the config.

{"version": 1, "click_events": true}
[[{"background":"#000000","color":"#dc322f","full_text":" Error in block 'bluetooth': Failed find a device with matching MAC address. ","separator":false,"separator_block_width":0}]


Error in block 'bluetooth': Failed find a device with matching MAC address.
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: "SendError(..)"', src/libcore/result.rs:1188:5
stack backtrace:
   0:     0x562fe39cba23 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h5f0f4503ed3baebc
   1:     0x562fe39f434d - core::fmt::write::h3ebd5957a5c2d94b
   2:     0x562fe39c9495 - std::io::Write::write_fmt::h93da027fbe21e40d
   3:     0x562fe39cfcbe - std::panicking::default_hook::{{closure}}::h761ba90b2222ffcf
   4:     0x562fe39cf9d0 - std::panicking::default_hook::hafa8f7b104f5e325
   5:     0x562fe39d039b - std::panicking::rust_panic_with_hook::hfbb6a993878e9b09
   6:     0x562fe39cff4e - rust_begin_unwind
   7:     0x562fe39f6d2e - core::panicking::panic_fmt::h70304ecceb719acb
   8:     0x562fe39fd9a7 - core::result::unwrap_failed::h17b23c17ab3624d7
   9:     0x562fe37be9de - i3status_rs::blocks::battery::UpowerDevice::monitor::{{closure}}::hafd7a37efdc81602
  10:     0x562fe37b080e - std::sys_common::backtrace::__rust_begin_short_backtrace::hcc9164267531247f
  11:     0x562fe386c56e - std::panicking::try::do_call::h7eac8ae0b9cbb002
  12:     0x562fe39e154a - __rust_maybe_catch_panic
  13:     0x562fe37f0154 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hb42456d972505a54
  14:     0x562fe39d903f - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::he9dcb7073be13c65
  15:     0x562fe39c9b90 - std::sys_common::thread::start_thread::h9ce8f903e84fe8e9
  16:     0x562fe39d8976 - std::sys::unix::thread::Thread::new::thread_start::h5e894f0575174d9e
  17:     0x7fcd54847edd - start_thread
  18:     0x7fcd5475c9bf - __clone
  19:                0x0 - <unknown>

Edit: It also crashes like this with the headsets commented out, so I'm not really sure what i3status-rs expects from upower here.

[atheriel]

I believe the block communicates with the D-Bus interface of Linux's bluetooth stack (bluez), not UPower. So you might want to check out devices in e.g. bluetoothctl.

[mweinelt]

I think it communicates with UPower since that is part of the calltrace, but I'm obviously guessing.

   9:     0x562fe37be9de - i3status_rs::blocks::battery::UpowerDevice::monitor::{{closure}}::hafd7a37efdc81602

[atheriel]

Thanks for your patience -- the calltrace is from an unrelated panic in the battery block, so I don't think it is directly related.

[mtellezj]

I have the same issue. bluetoothctl list show:
Controller 34:13:E8:44:63:C0 aldebaran [default]

and hciconfigshow:

hci0:   Type: Primary  Bus: USB
    BD Address: 34:13:E8:44:63:C0  ACL MTU: 1021:4  SCO MTU: 96:6
    UP RUNNING PSCAN 
    RX bytes:16314 acl:4 sco:0 events:2515 errors:0
    TX bytes:605401 acl:5 sco:0 commands:2497 errors:0

but I'm still getting "Error in block 'bluetooth': failed find a device with matching MAC address". My block config is:

[[block]]
block = "bluetooth"
mac = "34:13:E8:44:63:C0"
label = " aldebaran"

I get the same error with or without handsfree connected.

[ammgws]

The block checks for the device in org.bluez.Device1. Can you check what is actually there using d-feet or busctl?

[ammgws]

@mtellezj Are you able to provide any further information? I don't have hardware with bluetooth support so I cannot attempt a fix without some debugging from users.

[SWW13]

Here is an info dump for people who don't have a bluetooth device to test the behavior:

Device enabled (X = bt adapter mac, Y/Z client mac):

$ bluetoothctl list
Controller XX:XX:XX:XX:XX:XX localhost [default]
$ ls /sys/class/bluetooth/*
/sys/class/bluetooth/hci0@  /sys/class/bluetooth/hci0:256@
$ busctl tree | grep bluez
Service org.bluez:
  └─/org/bluez
    └─/org/bluez/hci0
      ├─/org/bluez/hci0/dev_YY_YY_YY_YY_YY_YY
      [...]
      └─/org/bluez/hci0/dev_ZZ_ZZ_ZZ_ZZ_ZZ_ZZ

Device disabled:

$ bluetoothctl list
(empty output)
$ ls /sys/class/bluetooth
(empty output)
$ busctl tree | grep bluez
Service org.bluez:
  └─/org/bluez

My workaround for quit some time now is: https://github.com/SWW13/i3status-rust/commit/594b598716abb908bad5eccf560685a0988e38a9 (rebased against current master)
But I don't really like the solution so far, that's why I never polished it.

@ammgws If you need something specific let me know.

[ammgws]

Could you run these commands while turning off/on your bluetooth?:
dbus-monitor "interface='org.freedesktop.DBus',member='NameOwnerChanged',path='/org/freedesktop/DBus',arg0namespace='org.bluez'" or dbus-monitor "interface='org.freedesktop.DBus',member='NameOwnerChanged',path='/org/freedesktop/DBus',arg0namespace='org.bluez.hci0'"

[SWW13]

No output for turn on/off with neither commands. Besides this when the command is executed:

signal time=1607839527.650750 sender=org.freedesktop.DBus -> destination=:1.375 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.375"
signal time=1607839527.650781 sender=org.freedesktop.DBus -> destination=:1.375 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.375"

(time and destination changes for each execution)

[ammgws]

Hmm there should surely be a signal somewhere when devices are registered on the bus... just need to find the right place to look. Maybe just try running dbus-monitor by itself and see if you can spot something in the output.

[SWW13]

Doesn't look like there is an event for the adapter, only for connected devices.

Turning the bluetooth adapter off: (headset disconnected event appears):

signal time=1607840298.439876 sender=org.freedesktop.DBus -> destination=:1.384 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.384"
signal time=1607840298.439950 sender=org.freedesktop.DBus -> destination=:1.384 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.384"
method call time=1607840301.360236 sender=:1.8 -> destination=org.freedesktop.DBus serial=24 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RequestName
   string "org.freedesktop.ReserveDevice1.Audio0"
   uint32 5
signal time=1607840301.360315 sender=org.freedesktop.DBus -> destination=(null destination) serial=114 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "org.freedesktop.ReserveDevice1.Audio0"
   string ""
   string ":1.8"
signal time=1607840301.360362 sender=org.freedesktop.DBus -> destination=:1.8 serial=46 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string "org.freedesktop.ReserveDevice1.Audio0"
method return time=1607840301.360390 sender=org.freedesktop.DBus -> destination=:1.8 serial=47 reply_serial=24
   uint32 1

Turning the bluetooth adapter on: (headset connected event appears with a delay after the adapter was turned on and after device is connected, probably when audio output is available):

signal time=1607840344.208650 sender=org.freedesktop.DBus -> destination=:1.387 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.387"
signal time=1607840344.208694 sender=org.freedesktop.DBus -> destination=:1.387 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.387"
method call time=1607840357.796630 sender=:1.8 -> destination=org.freedesktop.DBus serial=25 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=ReleaseName
   string "org.freedesktop.ReserveDevice1.Audio0"
signal time=1607840357.796694 sender=org.freedesktop.DBus -> destination=:1.8 serial=48 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string "org.freedesktop.ReserveDevice1.Audio0"
signal time=1607840357.796715 sender=org.freedesktop.DBus -> destination=(null destination) serial=121 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "org.freedesktop.ReserveDevice1.Audio0"
   string ":1.8"
   string ""
method return time=1607840357.796743 sender=org.freedesktop.DBus -> destination=:1.8 serial=49 reply_serial=25
   uint32 1

[ammgws]

Sorry maybe I'm confused about the original issue but what is your block config?

[[block]]
block = "bluetooth"
mac = "X or Y/Z??" // X = bt adapter mac, Y/Z client mac

[SWW13]

Maybe that was a bit confusing or I'm missing the point.

The only thing observable with DBus when turning the bluetooth adapter on / off (without touching the headset) was seeing the headset connection change. (I've change the text above to make it a bit more clear.)

My config looks like:

[[block]]
block = "bluetooth"
mac = "YY:YY:YY:YY:YY:YY"
path = "/org/bluez/hci0/dev_YY_YY_YY_YY_YY_YY"
icon = "audio-card"

Where path is my workaround for the issue and mac is therefor ignored, so a missing hci0 is no longer fatal. (See https://github.com/SWW13/i3status-rust/blob/594b598716abb908bad5eccf560685a0988e38a9/src/blocks/bluetooth.rs#L205 for details)

[ammgws]

I was hoping there would be some signals when the devices (e.g. /org/bluez/hci0/dev_YY_YY_YY_YY_YY_YY) show up on the bus because that would mean we could just monitor the bus for that signal and only attempt to grab info when it's there.

[SWW13]

bluetoothctl does somehow listen for events (or busy checks for them?), maybe it's worth looking into how they do it.

$ bluetoothctl
[bluetooth]# list
(empty)

*turn on adapter*
[NEW] Controller XX:XX:XX:XX:XX:XX localhost [default]
[NEW] Device YY:YY:YY:YY:YY:YY Some Headset
[NEW] Device ZZ:ZZ:ZZ:ZZ:ZZ:ZZ Some Other Device
[CHG] Controller XX:XX:XX:XX:XX:XX Powered: yes
[...]

[bluetooth]# list
Controller XX:XX:XX:XX:XX:XX localhost [default]

*turn off*
[DEL] Device YY:YY:YY:YY:YY:YY Some Headset
[DEL] Device ZZ:ZZ:ZZ:ZZ:ZZ:ZZ Some Other Device
[CHG] Controller XX:XX:XX:XX:XX:XX Powered: no
[DEL] Controller XX:XX:XX:XX:XX:XX localhost [default]

[marzzzello]

Why can't we use rfkill (blueberry uses that too)?

[SWW13]

Looks like it will only allow listening for adapter change events, but at least that would remove a busy checking.

adapter turned on:

$ rfkill --json
{
   "": [
      {"id":0, "type":"bluetooth", "device":"tpacpi_bluetooth_sw", "soft":"unblocked", "hard":"unblocked"},
      {"id":1, "type":"wlan", "device":"phy0", "soft":"unblocked", "hard":"unblocked"},
      {"id":10, "type":"bluetooth", "device":"hci0", "soft":"unblocked", "hard":"unblocked"}
   ]
}

adapter turned off:

$ rfkill --json
{
   "": [
      {"id":0, "type":"bluetooth", "device":"tpacpi_bluetooth_sw", "soft":"blocked", "hard":"unblocked"},
      {"id":1, "type":"wlan", "device":"phy0", "soft":"unblocked", "hard":"unblocked"}
   ]
}

events:

$ rfkill event
2020-12-13 14:33:07,728293+01:00: idx 0 type 2 op 0 soft 1 hard 0
2020-12-13 14:33:07,728340+01:00: idx 1 type 1 op 0 soft 0 hard 0
2020-12-13 14:33:08,821081+01:00: idx 0 type 2 op 2 soft 0 hard 0
2020-12-13 14:33:09,235082+01:00: idx 9 type 2 op 0 soft 0 hard 0
2020-12-13 14:33:09,373942+01:00: idx 0 type 2 op 2 soft 1 hard 0
2020-12-13 14:33:09,373994+01:00: idx 9 type 2 op 2 soft 1 hard 0

Note: idx 9 is the bluetooth adapter id, which increments on every turn on/off.

[ammgws]

Actually can you try dbus-monitor --system?

[SWW13]

That looks good (detailed log below):

interface=org.freedesktop.DBus.ObjectManager; member=InterfacesAdded
   object path "/org/bluez/hci0/dev_YY_YY_YY_YY_YY_YY"

turn adapter on

$ dbus-monitor --system
[...]
signal time=1607951140.598681 sender=:1.5 -> destination=(null destination) serial=818 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesAdded
   object path "/org/bluez/hci0"
   array [
      dict entry(
         string "org.freedesktop.DBus.Introspectable"
         array [
         ]
      )
      dict entry(
         string "org.bluez.Adapter1"
         array [
            dict entry(
               string "Address"
               variant                   string "XX:XX:XX:XX:XX:XX"
            )
            dict entry(
               string "AddressType"
               variant                   string "public"
            )
            dict entry(
               string "Name"
               variant                   string "localhost"
            )
            dict entry(
               string "Alias"
               variant                   string "thinkNose"
            )
            dict entry(
               string "Class"
               variant                   uint32 0
            )
            dict entry(
               string "Powered"
               variant                   boolean false
            )
            dict entry(
               string "Discoverable"
               variant                   boolean false
            )
            dict entry(
               string "DiscoverableTimeout"
               variant                   uint32 180
            )
            dict entry(
               string "Pairable"
               variant                   boolean false
            )
            dict entry(
               string "PairableTimeout"
               variant                   uint32 0
            )
            dict entry(
               string "Discovering"
               variant                   boolean false
            )
            dict entry(
               string "UUIDs"
               variant                   array [
                     string "00001112-0000-1000-8000-00805f9b34fb"
                     string "0000110e-0000-1000-8000-00805f9b34fb"
                     string "00001200-0000-1000-8000-00805f9b34fb"
                     string "00001108-0000-1000-8000-00805f9b34fb"
                     string "0000110c-0000-1000-8000-00805f9b34fb"
                     string "00001800-0000-1000-8000-00805f9b34fb"
                     string "00001801-0000-1000-8000-00805f9b34fb"
                     string "0000180a-0000-1000-8000-00805f9b34fb"
                  ]
            )
            dict entry(
               string "Modalias"
               variant                   string "usb:v1D6Bp0246d0537"
            )
            dict entry(
               string "Roles"
               variant                   array [
                     string "central"
                     string "peripheral"
                  ]
            )
         ]
      )
      dict entry(
         string "org.freedesktop.DBus.Properties"
         array [
         ]
      )
      dict entry(
         string "org.bluez.GattManager1"
         array [
         ]
      )
      dict entry(
         string "org.bluez.LEAdvertisingManager1"
         array [
            dict entry(
               string "ActiveInstances"
               variant                   byte 0
            )
            dict entry(
               string "SupportedInstances"
               variant                   byte 5
            )
            dict entry(
               string "SupportedIncludes"
               variant                   array [
                     string "tx-power"
                     string "appearance"
                     string "local-name"
                  ]
            )
         ]
      )
      dict entry(
         string "org.bluez.Media1"
         array [
         ]
      )
      dict entry(
         string "org.bluez.NetworkServer1"
         array [
         ]
      )
   ]
[...]
signal time=1607951140.603635 sender=:1.5 -> destination=(null destination) serial=822 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesAdded
   object path "/org/bluez/hci0/dev_YY_YY_YY_YY_YY_YY"
   array [
      dict entry(
         string "org.freedesktop.DBus.Introspectable"
         array [
         ]
      )
      dict entry(
         string "org.bluez.Device1"
         array [
            dict entry(
               string "Address"
               variant                   string "YY:YY:YY:YY:YY:YY"
            )
            dict entry(
               string "AddressType"
               variant                   string "public"
            )
            dict entry(
               string "Name"
               variant                   string "Some Headset"
            )
            dict entry(
               string "Alias"
               variant                   string "Some Headset"
            )
            dict entry(
               string "Class"
               variant                   uint32 2360344
            )
            dict entry(
               string "Icon"
               variant                   string "audio-card"
            )
            dict entry(
               string "Paired"
               variant                   boolean true
            )
            dict entry(
               string "Trusted"
               variant                   boolean true
            )
            dict entry(
               string "Blocked"
               variant                   boolean false
            )
            dict entry(
               string "LegacyPairing"
               variant                   boolean false
            )
            dict entry(
               string "Connected"
               variant                   boolean false
            )
            dict entry(
               string "UUIDs"
               variant                   array [
                     string "00001108-0000-1000-8000-00805f9b34fb"
                     string "0000110b-0000-1000-8000-00805f9b34fb"
                     string "0000110c-0000-1000-8000-00805f9b34fb"
                     string "0000110d-0000-1000-8000-00805f9b34fb"
                     string "0000110e-0000-1000-8000-00805f9b34fb"
                     string "0000111e-0000-1000-8000-00805f9b34fb"
                     string "00001200-0000-1000-8000-00805f9b34fb"
                  ]
            )
            dict entry(
               string "Modalias"
               variant                   string "bluetooth:v0103p1008d0002"
            )
            dict entry(
               string "Adapter"
               variant                   object path "/org/bluez/hci0"
            )
            dict entry(
               string "ServicesResolved"
               variant                   boolean false
            )
         ]
      )
      dict entry(
         string "org.freedesktop.DBus.Properties"
         array [
         ]
      )
      dict entry(
         string "org.bluez.MediaControl1"
         array [
            dict entry(
               string "Connected"
               variant                   boolean false
            )
         ]
      )
   ]
[...]

turn adapter off

$ dbus-monitor --system
[...]
signal time=1607951023.759085 sender=:1.5 -> destination=(null destination) serial=505 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_YY_YY_YY_YY_YY_YY"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.Device1"
      string "org.bluez.MediaControl1"
   ]
[...]
signal time=1607951023.759192 sender=:1.5 -> destination=(null destination) serial=510 path=/org/bluez/hci0; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.Adapter1"
   array [
      dict entry(
         string "Class"
         variant             uint32 0
      )
      dict entry(
         string "Powered"
         variant             boolean false
      )
      dict entry(
         string "Discovering"
         variant             boolean false
      )
   ]
   array [
   ]
signal time=1607951023.759573 sender=:1.5 -> destination=(null destination) serial=515 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.Adapter1"
      string "org.bluez.LEAdvertisingManager1"
      string "org.bluez.GattManager1"
      string "org.bluez.NetworkServer1"
      string "org.bluez.Media1"
   ]
[...]

[ammgws]

OK that looks very promising. I will try procure a bluetooth adapter so I can start working on a solution.

[ammgws]

@SWW13 See if #986 is any better
(code needs some love later, but it seems to do the job so need testers to be sure!)

[marzzzello]

986 looks good. If Bluetooth is off it says  unavailable.

I would prefer X or off instead of unavailable or completely hidden because it's shorter.
Too bad that there is no icon for bluetooth off. At least not here https://fontawesome.com/icons?d=gallery&q=bluetooth

[ammgws]

I will add a format string to take care of that. And yeah I couldn't find an icon either

[SWW13]

Works fine for me, thanks :) Maybe the "x" for network devices would be a good unavailable format string default:
https://github.com/greshake/i3status-rust/blob/7f8cbf6e29b8208807c207caeaab114e66f70a15/src/blocks/net.rs#L874

[ammgws]

OK that confirms it is working as intended. However the code itself needs a lot of work:

• at the moment I just added another thread to house the code that addresses this issue, however the bluetooth block already has a thread and they really should be consolidated
• similarly to how the music block used to behave, the bluetooth block listens for PropertiesChanged signals in a thread and then in the update function it manually calls various methods on the bus to get the info it wants to show in the bar. However, this info should already be present in the message body of the PropertiesChanged signal itself so we can avoid all those superfluous calls.
• When the controller is not present, the controller name (e.g. hci0) cannot be known, and just for now I have hardcoded it in due to the way the other parts of the block work. However this isn't optimal even if it is made configurable. I am pretty sure we can make the code "controller name" agnostic when merging together the two threads mentioned above, which will solve this point.
• probably should put this behind a allow_missing flag like the battery block (at least to be consistent)
• similar to above, add hide_missing instead of lumping it in together with hide_disconnected
• add the format strings mentioned above

[ram02z]

+1 for the allow_missing flag. The whole status bar becomes unusable unless bluetooth is turned on at all times.