[bluetooth] bluez errors when removing thing : Roaming Bluetooth Controller - Generic Connectable Bluetooth Device

HowardShank commented 3 years ago

Expected Behavior

Clicking Delete Thing transitions to Removing and then throws exception. Thing is never removed.

Current Behavior

After clicking "Delete Thing" button, the following is logged:

2021-02-18 13:09:51.726 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.dispose()' on 'org.openhab.binding.bluetooth.BeaconBluetoothHandler@1b87f7f': Method "Disconnect" with signature "" on interface "org.bluez.Device1" doesn't exist org.freedesktop.dbus.errors.UnknownObject: Method "Disconnect" with signature "" on interface "org.bluez.Device1" doesn't exist at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?] at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:?] at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?] at java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[?:?] at org.freedesktop.dbus.errors.Error.getException(Error.java:157) ~[?:?] at org.freedesktop.dbus.errors.Error.throwException(Error.java:187) ~[?:?] at org.freedesktop.dbus.RemoteInvocationHandler.executeRemoteMethod(RemoteInvocationHandler.java:164) ~[?:?] at org.freedesktop.dbus.RemoteInvocationHandler.invoke(RemoteInvocationHandler.java:228) ~[?:?] at com.sun.proxy.$Proxy283.Disconnect(Unknown Source) ~[?:?] at com.github.hypfvieh.bluetooth.wrapper.BluetoothDevice.disconnect(BluetoothDevice.java:434) ~[?:?] at org.openhab.binding.bluetooth.bluez.internal.BlueZBluetoothDevice.disconnect(BlueZBluetoothDevice.java:197) ~[?:?] at org.openhab.binding.bluetooth.BeaconBluetoothHandler.dispose(BeaconBluetoothHandler.java:140) ~[?:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?] at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?] at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:834) [?:?] 2021-02-18 13:09:51.748 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while disposing handler of thing 'bluetooth:beacon:hci0:068e77709f47': Method "Disconnect" with signature "" on interface "org.bluez.Device1" doesn't exist org.freedesktop.dbus.errors.UnknownObject: Method "Disconnect" with signature "" on interface "org.bluez.Device1" doesn't exist at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?] at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:?] at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?] at java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[?:?] at org.freedesktop.dbus.errors.Error.getException(Error.java:157) ~[?:?] at org.freedesktop.dbus.errors.Error.throwException(Error.java:187) ~[?:?] at org.freedesktop.dbus.RemoteInvocationHandler.executeRemoteMethod(RemoteInvocationHandler.java:164) ~[?:?] at org.freedesktop.dbus.RemoteInvocationHandler.invoke(RemoteInvocationHandler.java:228) ~[?:?] at com.sun.proxy.$Proxy283.Disconnect(Unknown Source) ~[?:?] at com.github.hypfvieh.bluetooth.wrapper.BluetoothDevice.disconnect(BluetoothDevice.java:434) ~[?:?] at org.openhab.binding.bluetooth.bluez.internal.BlueZBluetoothDevice.disconnect(BlueZBluetoothDevice.java:197) ~[?:?] at org.openhab.binding.bluetooth.BeaconBluetoothHandler.dispose(BeaconBluetoothHandler.java:140) ~[?:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?] at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?] at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:834) [?:?]

Possible Solution

Steps to Reproduce (for Bugs)

Added Bluetooth Binding
Scanned for things for Bluetooth
Added items from inbox that were discovered.
Attempted to remove non-functioning thing: Roaming Bluetooth Controller - Generic Connectable Bluetooth Device

Context

Was trying to remove a non-functioning bluetooth thing.

Your Environment

Version used: (e.g., openHAB and add-on versions)
OpenHab 3.0.1
Bluetooth Binding 3.0.1 runtimeInfo: version: 3.0.1 buildString: Release Build locale: en_US systemInfo: configFolder: /etc/openhab userdataFolder: /var/lib/openhab logFolder: /var/log/openhab javaVersion: 11.0.10 javaVendor: Azul Systems, Inc. javaVendorVersion: Zulu11.45+27-CA osName: Linux osVersion: 5.10.11-v7l+ osArchitecture: arm availableProcessors: 4 freeMemory: 91732392 totalMemory: 243462144 bindings:
- bluetooth
- http
- logreader
- mqtt
- network
- onkyo
- samsungtv
- smartthings
- sonos
- tplinksmarthome
- zigbee
- zwave clientInfo: device: ios: false android: false androidChrome: false desktop: true iphone: false ipod: false ipad: false edge: false ie: false firefox: false macos: false windows: true cordova: false phonegap: false electron: false nwjs: false webView: false webview: false standalone: false os: windows pixelRatio: 1.5 prefersColorScheme: light isSecureContext: false locationbarVisible: true menubarVisible: true navigator: cookieEnabled: true deviceMemory: N/A hardwareConcurrency: 24 language: en-US languages:
  - en-US
  - en onLine: true platform: Win32 screen: width: 2560 height: 1440 colorDepth: 24 support: touch: false pointerEvents: true observer: true passiveListener: true gestures: false intersectionObserver: true themeOptions: dark: dark filled: true pageTransitionAnimation: default bars: light homeNavbar: default homeBackground: default expandableCardAnimation: default userAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.150 Safari/537.36 timestamp: 2021-02-18T20:41:18.589Z
Environment name and version (e.g. Chrome 76, Java 8, Node.js 12.9, ...):
Operating System and version (desktop or mobile, Windows 10, Raspbian Buster, ...): OpenHabian Raspberry Pi 4 - 4GB

Skinah commented 3 years ago

In case you did not know, you can click the delete button a second time and it force removes the thing. The first time you try it will wait for the binding to gracefully remove the thing which may require deregistering certain components.

lsiepel commented 1 year ago

@HowardShank can you confirm this is still an issue? If so i might look into this and try to get it fixed.

pbloigu commented 1 year ago

Hello,

I'm observing this same issue with RuuviTags. When there are RuuviTags in ERROR state I see the same stack trace is the logs when I disable the Bluetooth Interface thing. I'm guessing it tries to remove all of the Bluetooth things attached to the interface, and then fails.

Here's the stack trace.

2023-09-05 18:14:28.332 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while disposing handler of thing 'bluetooth:ruuvitag_beacon:hci0:e12cd47b86a8': Method "Disconnect" with signature "" on interface "org.bluez.Device1" doesn't exist
org.freedesktop.dbus.errors.UnknownObject: Method "Disconnect" with signature "" on interface "org.bluez.Device1" doesn't exist
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
        at java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499) ~[?:?]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:480) ~[?:?]
        at org.freedesktop.dbus.errors.Error.getException(Error.java:157) ~[?:?]
        at org.freedesktop.dbus.errors.Error.throwException(Error.java:187) ~[?:?]
        at org.freedesktop.dbus.RemoteInvocationHandler.executeRemoteMethod(RemoteInvocationHandler.java:164) ~[?:?]
        at org.freedesktop.dbus.RemoteInvocationHandler.invoke(RemoteInvocationHandler.java:228) ~[?:?]
        at jdk.proxy32.$Proxy194.Disconnect(Unknown Source) ~[?:?]
        at com.github.hypfvieh.bluetooth.wrapper.BluetoothDevice.disconnect(BluetoothDevice.java:434) ~[?:?]
        at org.openhab.binding.bluetooth.bluez.internal.BlueZBluetoothDevice.disconnect(BlueZBluetoothDevice.java:199) ~[?:?]
        at org.openhab.binding.bluetooth.BeaconBluetoothHandler.dispose(BeaconBluetoothHandler.java:139) ~[?:?]
        at org.openhab.binding.bluetooth.ruuvitag.internal.RuuviTagHandler.dispose(RuuviTagHandler.java:88) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:147) ~[?:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]

However, I'm not sure if this should actually be fixed in the bluez-dbus code, since it seems to assume the device actually has a Disconnectmethod while it obviously doesn't. See here: https://github.com/hypfvieh/bluez-dbus/blob/0e49c67d8578984cad0de174faacdcdbc435bce7/bluez-dbus/src/main/java/com/github/hypfvieh/bluetooth/wrapper/BluetoothDevice.java#L434C36-L434C36

lsiepel commented 1 year ago

For reference: https://github.com/hypfvieh/bluez-dbus/issues/61

lsiepel commented 9 months ago

It looks like the issue is much deeper in one of the dependencies. As a workaround we could wrap the call in the dispose method and re-route it to debug level.

openhab / openhab-addons