[bluetooth] Airthings stops updating, also not using refreshinterval

jmelhus commented 3 years ago

Expected Behavior

Fetch updated values from Airthings Wave Plus device at the specified refreshinterval.

Current Behavior

It's fetching values intermittently and at very short intervals, sometimes just seconds between. After some minutes it stops updating. The RSSI values continues to update. Image showing behaviour:

openhab log displays:

2021-01-15 13:06:09.448 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.bluetooth.airthings.internal.AirthingsWavePlusHandler@58fabbce': Duplicate channels bluetooth:airthings_wave_plus:adapter1:sensor1:rssi
java.lang.IllegalArgumentException: Duplicate channels bluetooth:airthings_wave_plus:adapter1:sensor1:rssi
        at org.eclipse.smarthome.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:165) ~[?:?]
        at org.eclipse.smarthome.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:157) ~[?:?]
        at org.eclipse.smarthome.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:153) ~[?:?]
        at org.eclipse.smarthome.core.thing.binding.builder.ThingBuilder.withChannel(ThingBuilder.java:76) ~[?:?]
        at org.openhab.binding.bluetooth.BeaconBluetoothHandler.initialize(BeaconBluetoothHandler.java:107) ~[?:?]
        at org.openhab.binding.bluetooth.airthings.internal.AirthingsWavePlusHandler.initialize(AirthingsWavePlusHandler.java:81) ~[?:?]
        at sun.reflect.GeneratedMethodAccessor80.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_265]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_265]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_265]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
2021-01-15 13:06:09.448 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'bluetooth:airthings_wave_plus:adapter1:sensor1': Duplicate channels bluetooth:airthings_wave_plus:adapter1:sensor1:rssi
java.lang.IllegalArgumentException: Duplicate channels bluetooth:airthings_wave_plus:adapter1:sensor1:rssi
        at org.eclipse.smarthome.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:165) ~[?:?]
        at org.eclipse.smarthome.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:157) ~[?:?]
        at org.eclipse.smarthome.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:153) ~[?:?]
        at org.eclipse.smarthome.core.thing.binding.builder.ThingBuilder.withChannel(ThingBuilder.java:76) ~[?:?]
        at org.openhab.binding.bluetooth.BeaconBluetoothHandler.initialize(BeaconBluetoothHandler.java:107) ~[?:?]
        at org.openhab.binding.bluetooth.airthings.internal.AirthingsWavePlusHandler.initialize(AirthingsWavePlusHandler.java:81) ~[?:?]
        at sun.reflect.GeneratedMethodAccessor80.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_265]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_265]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_265]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]

This is my Bluetooth dongle thing: Bridge bluetooth:bluegiga:adapter1 [ port="COM3", backgroundDiscovery=false ]

This is my Airthings thing: bluetooth:airthings_wave_plus:adapter1:sensor1 "Airthings Wave Plus Sensor 1" (bluetooth:bluegiga:adapter1) [ address="...", refreshInterval=600 ]

Possible Solution

Steps to Reproduce (for Bugs)

Context

Your Environment

Version used: openHAB 2.5.10, openHAB 2.5.11
Operating System and version (desktop or mobile, Windows 10, Raspbian Buster, ...): Windows 10, Zulu 8.48.0.53, jdk8.0.265

openhab-bot commented 3 years ago

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/bluetooth-bluegiga-airthings-wave-plus-issue/114239/3

kaikreuzer commented 3 years ago

@paulianttila & @cpmeister Any idea why we have duplicate RSSI channels?

cpmeister commented 3 years ago

Duplicate rssi was a bug that was already fixed for the 3.0 release. I don't believe the fix was backported for 2.5.x though.

pawel-sw commented 2 years ago

it is a more generic problem, the binding is using Java scheduler.scheduleWithFixedDelay to execute read periodically, whenever exception of any type is thrown there java will suppress subsequent executions see doc: https://docs.oracle.com/javase/7/docs/api/java/util/concurrent/ScheduledExecutorService.html

Some other examples that cause this bug:

Airthings if far from Bluetooth and sometimes the signal is lost during operation, same can happen in noisy environment
Bluetooth was busy with something else
Airthings device was read by phone at the same time
Any other bugs like poor support for given dongle by kernel

Example exception breaking the binding:


java.lang.NullPointerException: null
    at org.openhab.binding.bluetooth.bluez.internal.BlueZBluetoothDevice.readCharacteristic(BlueZBluetoothDevice.java:465) ~[?:?]
    at org.openhab.binding.bluetooth.airthings.internal.AbstractAirthingsHandler.read(AbstractAirthingsHandler.java:184) ~[?:?]
    at org.openhab.binding.bluetooth.airthings.internal.AbstractAirthingsHandler.execute(AbstractAirthingsHandler.java:127) ~[?:?]
    at org.openhab.binding.bluetooth.airthings.internal.AbstractAirthingsHandler.onConnectionStateChange(AbstractAirthingsHandler.java:261) ~[?:?]
    at org.openhab.binding.bluetooth.BluetoothDevice.notifyListeners(BluetoothDevice.java:396) ~[?:?]
    at org.openhab.binding.bluetooth.BaseBluetoothDevice.notifyListeners(BaseBluetoothDevice.java:343) ~[?:?]
    at org.openhab.binding.bluetooth.bluez.internal.BlueZBluetoothDevice.setConnectionState(BlueZBluetoothDevice.java:152) ~[?:?]
    at org.openhab.binding.bluetooth.bluez.internal.BlueZBluetoothDevice.connect(BlueZBluetoothDevice.java:188) ~[?:?]
    at org.openhab.binding.bluetooth.airthings.internal.AbstractAirthingsHandler.connect(AbstractAirthingsHandler.java:136) ~[?:?]
    at org.openhab.binding.bluetooth.airthings.internal.AbstractAirthingsHandler.execute(AbstractAirthingsHandler.java:123) ~[?:?]
    at org.openhab.binding.bluetooth.airthings.internal.AbstractAirthingsHandler.executePeridioc(AbstractAirthingsHandler.java:110) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]```

pawel-sw commented 2 years ago

you can try fixed version here https://openhab.jfrog.io/ui/native/libs-pullrequest-local/org/openhab/addons/bundles/org.openhab.binding.bluetooth.airthings/3.2.0-SNAPSHOT

openhab / openhab-addons