D-Bus subscription on PropertiesChanged does not seem to emit upon updated ServiceData

[sebastianhaas]

I created a sensor class for a Shelly BT H&T device that publishes temperature and humidity through a certain ServiceData advertisement. It appears to be quite similar if not the same as the ATC.js sensor class.

Setting the sensor up initially works flawlessly, however, it does not seem to pick up any updates. I inspected the D-Bus properties of the bluetooth device:
$ busctl introspect org.bluez /org/bluez/hci0/dev_7C_C6_B6_72_3A_48 org.bluez.Device1

NAME               TYPE      SIGNATURE RESULT/VALUE                             FLAGS
.CancelPairing     method    -         -                                        -
.Connect           method    -         -                                        -
.ConnectProfile    method    s         -                                        -
.Disconnect        method    -         -                                        -
.DisconnectProfile method    s         -                                        -
.Pair              method    -         -                                        -
.Adapter           property  o         "/org/bluez/hci0"                        emits-change
.Address           property  s         "7C:C6:B6:72:3A:48"                      emits-change
.AddressType       property  s         "public"                                 emits-change
.AdvertisingData   property  a{yv}     -                                        emits-change
.AdvertisingFlags  property  ay        1 6                                      emits-change
.Alias             property  s         "SBHT-003C"                              emits-change writable
.Appearance        property  q         -                                        emits-change
.Blocked           property  b         false                                    emits-change writable
.Bonded            property  b         false                                    emits-change
.Class             property  u         -                                        emits-change
.Connected         property  b         false                                    emits-change
.Icon              property  s         -                                        emits-change
.LegacyPairing     property  b         false                                    emits-change
.ManufacturerData  property  a{qv}     1 2985 ay 13 1 17 0 11 3 0 10 72 58 114… emits-change
.Modalias          property  s         -                                        emits-change
.Name              property  s         "SBHT-003C"                              emits-change
.Paired            property  b         false                                    emits-change
.RSSI              property  n         -51                                      emits-change
.ServiceData       property  a{sv}     1 "0000fcd2-0000-1000-8000-00805f9b34fb… emits-change
.ServicesResolved  property  b         false                                    emits-change
.Sets              property  a{oa{sv}} -                                        emits-change
.Trusted           property  b         false                                    emits-change writable
.TxPower           property  n         -                                        emits-change
.UUIDs             property  as        1 "0000fcd2-0000-1000-8000-00805f9b34fb" emits-change
.WakeAllowed       property  b         -                                        emits-change writable

which lists .ServiceData as emits-change.

Also, a call to
$ busctl get-property org.bluez /org/bluez/hci0/dev_7C_C6_B6_72_3A_48 org.bluez.Device1 ServiceData
yields the expected result:
a{sv} 1 "0000fcd2-0000-1000-8000-00805f9b34fb" ay 10 68 0 194 1 100 46 45 69 211 0 <- 21.1 degrees celcius, 45% humidity, 100% battery from rtl

Subsequent calls will eventually return an updated ServiceData array, or, especially while the device is not broadcasting to save battery (approx. 1 minute), the following error:

Failed to get property ServiceData on interface org.bluez.Device1: Method "Get" with signature "ss" on interface "org.freedesktop.DBus.Properties" doesn't exist

When setting up a monitor to pick up changes (which I assume is what this plugin basically does):
$ dbus-monitor --system "type='signal',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',path='/org/bluez/hci0/dev_7C_C6_B6_72_3A_48'"

I am seeing a few events like this every once in a while:

signal time=1740501693.856262 sender=:1.32 -> destination=(null destination) serial=998538 path=/org/bluez/hci0/dev_7C_C6_B6_72_3A_48; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.Device1"
   array [
      dict entry(
         string "RSSI"
         variant             int16 -50
      )
   ]
   array [
   ]

But never an update of the ServiceData property.

Please note that I do understand that I have just asked a bunch of questions regarding D-Bus (for which I am not an expert by any means) that are hardly related to your actual work on the plugin. However, I am still curious to know whether this setup, e.g. with different hardware, worked out correctly during your testing with the ATC.js sensor. Also, I assume you have had to build up lot of experience and knowlegde around the BlueZ D-Bus integration so maybe there is something that you can see clearly which I can't. Any help is appreciated, and thank you for your work on this plugin.

[naugehyde]

Hi Sebastian,

Thank you for the comprehensive diagnostics.

You are correct that if the Shelly device is broadcasting Service Data, D-Bus should emit changes and the plugin should respond appropriately.

Please attach the code (or create a pull request for review) and I'll take a look. I suspect it is a simple fix.

Best,

Andy

[sebastianhaas]

Hi Andy

const BTSensor = require("../BTSensor");

class ShellySBHT003C extends BTSensor {

    static SERVICE_SHELLY = "0000fcd2-0000-1000-8000-00805f9b34fb"

    async init() {
        await super.init()
        this.initMetadata()
    }
    
    static async identify(device) {
        var sd = await this.getDeviceProp(device, 'ServiceData')
        if (sd == null || sd.length==0) 
            return null
        else{
            const keys = Object.keys(sd)
            if (keys[0]==this.SERVICE_SHELLY) 
                return this
            else
                return null
        }
    }

    initMetadata() {
        this.addMetadatum(
            'temp', 'K', 'temperature',
            (buff) => { return parseFloat((273.15+(buff.readInt16LE(8))/10).toFixed(2)) }
        )
        this.addMetadatum(
            'humidity', 'ratio', 'humidity',
            (buff) => { return ((buff.readUInt8(6))/100) }
        )
    }

    propertiesChanged(props) {
        super.propertiesChanged(props)
        
        if (!props.hasOwnProperty("ServiceData")) { // <- no service data here
            this.debug("No ServiceData available for " + this.getDisplayName());
            return
        }

        const buff = this.getServiceData(this.constructor.SERVICE_SHELLY)
        if (!buff)
            throw new Error("Unable to get service data for " + this.getDisplayName())
        this.emitData("temp", buff)
        this.emitData("humidity", buff)
    }
}

module.exports=ShellySBHT003C

happy to create a PR at some point once it is working. Of course the check for ServiceData inside propertiesChanged() fails, which is somewhat expected given my dbus-monitor output from my initial posting.

Thank you for having a look at it!

[naugehyde]

Okay. The code looks solid.

Clearly if the device isn't broadcasting ServiceData/0000fcd2-0000-1000-8000-00805f9b34fb at an interval then the plugin won't update the path.

I don't have a Shelly H&T on hand so I can't test but if you're saying that the device never emits ServiceData on 0000FCD2 then you'll need another strategy for getting the temp and humidity.

I suspect that the device's update interval is long (> 1 minute to save battery) and if you wait long enough you'll get updates on 000FCD2 but I leave that to you to test.

[sebastianhaas]

The device is broadcasting ServiceData, however at a rate of 1 minute. 1 I can pick up those updates fine when using bluetoothctl, that is why I suspect this is a D-Bus-related issue.

My theory is: The device is getting "lost" on the D-Bus after a while when it stops advertising. During that time, it is not even possible to retrieve the value using get-property, it will yield the error I mentioned in my first post. As soon as the device broadcasts the next time, I can again read the updated .ServiceData property from the D-Bus. Due to the fact that the entire device seems to be lost

$ busctl introspect org.bluez /org/bluez/hci0/dev_7C_C6_B6_72_3A_48  
NAME TYPE SIGNATURE RESULT/VALUE FLAGS

or empty or whatever the correct term is, the property does not seem to be regarded as "updated" but entirely "new" and hence there is no emit signal on the bus.

This is the point where I wonder how it works out for the ATC.js, according to https://github.com/atc1441/ATC_MiThermometer the adverstising interval is a minute too? Can you, for instance, confirm that a device running the ATC firmware "stays" on the bus during all the time it isn't advertising using the busctl introspect command above?

[naugehyde]

I haven't seen any issues with D-Bus dropping BT updates at > 60s.

To confirm, bluetoothctl is reporting data for the device at ServiceData 0000fcd2 at regular intervals?

[naugehyde]

Also, to confirm: what if any output is your class producing?

Is the following line ever getting executed?

const buff = this.getServiceData(this.constructor.SERVICE_SHELLY)

[sebastianhaas]

I struggled to capture a reasonable bluetoothctl output, but here is what I could get from btmon:

btmon3.log

You can see timestamps #6596 [hci0] 50.681873 here, relative from the start of my capturing. It is easy to spot the approx. 60s advertising interval. Also, the service data is updating nicely from 4400a601642e2b45d800 to 4400af01642e2b45d800 (last captured frame). The device is increasing a counter, from a6 to af (166 to 175), a total of 9 advertisements 9*60 seconds is 540 which adds up very nicely to the observed 544.365579 seconds in my log. I'd say this all looks very much as expected.

Regarding your second question; yes this line is getting executed once after I start the signal-k server but never again, as the D-Bus fails to emit update signals for the .ServiceData property.

[sebastianhaas]

I am really starting to believe that there is a D-Bus issue. The object /org/bluez/hci0/dev_7C_C6_B6_72_3A_48 is deleted from the D-Bus between advertisements, so it (kind of) makes sense, that there is no signal emitted upon a property update, as there is nothing to be updated any more.

Question is, why am I seeing this, is it related to D-Bus, bluez, my Bluetooth adapter or the device. I maybe should have mentioned that I am running a rolling release distro with BlueZ version 5.79, Linux 6.13.2 so worst case, there is something coming up that breaks the plugin, best case its my hardware.

[naugehyde]

Safe to say the plugin isn't breaking but D-Bus might be.

Is there any way for me to get shell access to your system? It'd make this a lot easier.

[sebastianhaas]

Not short term, no, running this on my main computer at home.

I'll try to deploy this setup on a raspberry pi at some point and see if I can reproduce the issue there. In that case, I could probably provide you with ssh access.

Is there something in the mean time that I could provide that would be helpful?

[naugehyde]

I have seen situations where Bluez spuriously turns off the BT scanner. Can you confirm that the scanner is still on after the plugin starts up? It should be on for all processes. The plugin relies on the scanner being on.

[sebastianhaas]

Scanning is not the issue.

I added some log output to the plugin, seeing this after startup:

  bt-sensors-plugin-sk Found 7C:C6:B6:72:3A:48 +2s
  bt-sensors-plugin-sk identify called for 7C:C6:B6:72:3A:48
  bt-sensors-plugin-sk identified 7C:C6:B6:72:3A:48
  bt-sensors-plugin-sk instantiated 7C:C6:B6:72:3A:48 +10ms
  bt-sensors-plugin-sk Properties changed event received for Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -54 db / 76%) ▂ ▄ ▆  +3ms
  bt-sensors-plugin-sk Completed emitting data from updated properties for Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -54 db / 76%) ▂ ▄ ▆  +1ms
  bt-sensors-plugin-sk Listening for changes from Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -54 db / 76%) ▂ ▄ ▆  +0ms
  bt-sensors-plugin-sk Properties changed event received for Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -75 db / 43%) ▂ ▄  +243ms
  bt-sensors-plugin-sk No ServiceData available for Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -75 db / 43%) ▂ ▄  +0ms

So you can see, the service data is being picked up correctly once.

After that I keep seeing this periodically, from time to time.

  bt-sensors-plugin-sk identify called for 7C:C6:B6:72:3A:48
  bt-sensors-plugin-sk no service found of 7C:C6:B6:72:3A:48
  bt-sensors-plugin-sk Properties changed event received for Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -54 db / 76%) ▂ ▄ ▆  +2s
  bt-sensors-plugin-sk No ServiceData available for Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -54 db / 76%) ▂ ▄ ▆  +0ms
  bt-sensors-plugin-sk Properties changed event received for Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -54 db / 76%) ▂ ▄ ▆  +313ms
  bt-sensors-plugin-sk No ServiceData available for Shelly BT H&T (7C:C6:B6:72:3A:48 RSSI: -54 db / 76%) ▂ ▄ ▆  +0ms

And the reason for this is, that the D-Bus is only emitting RSSI-type signals, but never for ServiceData changed. The first time it does work is probably due to the inner structure of your plugin, so propertyChanged() is called during instantiation but not because of an actual D-Bus event in that case.

I am running bluetoothctl in a seperate process, it keeps spamming scan results as long as signalk is running.

[sebastianhaas]

Interestingly enough, the Shelly does have a button that once pressed, makes the device immediately publish data.

If I press the button, it will always be picked up on D-Bus, but also after that, it will disappear again and any subsequent periodic, regular advertisments will go unnoticed on D-Bus.

[naugehyde]

If you're getting RSSI updates, the plugin is working as designed.

I cannot explain why your system isn't emitting ServiceData updates for the device.

I'm eager to help but it will be very difficult to do so without a Shelly H&T device to test with or shell access to your system.

If you're running Linux at home, I would be able to SSH in provided you start SSHd and set up a VPN like Zerotier or Tailscale and give me temporary access.

It's interesting that D-Bus is updated on button press but I can't help further w/o access to the device.

[sebastianhaas]

Found the issue, I believe.

It all comes down to this https://github.com/bluez/bluez/blob/4465c577778d812702d752dfd2812e25a2f69b31/src/device.c#L2292 (note the parameter duplicate).

This is a Bluez "feature" called de-duplication. The idea is to avoid spamming the scan result with devices that are already known, and it targets towards a usage scenario, where people discover the device once, and then connect to it. So in that case, you are not interested in subsequent updates of the same device. However, this essentially blocks the way how the ATC.js or Shelly work.

You can turn de-duplication off in bluetoothctl using

menu scan
duplicate-data on
back
scan le

from https://stackoverflow.com/questions/55336017/disable-filter-duplicates-setting-for-le-set-scan-enable-command.

Doing that and my device keeps popping up on D-Bus including ServiceData updated.

Now, if you had an idea how to make the underlying D-Bus node library update a bluez kernel parameter, this issue would be resolved ;)

More reading:
hbldh/bleak#235 (library facing the same challenge)

[naugehyde]

That looks like the issue! Thank you!

Duplicate-data indeed needs to be on for ServiceData dependent devices to function as designed. Duplicate-data is on by default in current and recent Raspi-OS and Ubuntu distros AFAIK so the issue hasn't come up before. (I have an ATC device on my boat that works without any issues on both distros).

If you could investigate a little further and determine which distros have duplicate-data off by default and how to best ensure that duplicate data is on at boot, that'd be great. After that please update the plugin's README with what you discover and add the README to your pull request for the Shelly device.

Thanks again. Great work!

[naugehyde]

FWIW I am NOT able to recreate the problem with the ATC on my boat.

When Duplicate-data is set to off, D-Bus and consequently the plugin both update as expected (albeit every 2-5 minutes or so.).

(Bluez version 5.55)

[sebastianhaas]

Documentation on this was wrong in BlueZ: bluez/bluez#1113
Also, in order to establish the actually intended default, this PR needs to be accepted first: chrvadala/node-ble#82

With these changes in place, I can somewhat reliably pick up my sensor data every minute for more than an hour now.

I will create a PR for the Shelly BT H&T once I confirm it is working on the typical boating hardware, e.g. a Pi.