sputnikdev / eclipse-smarthome-bluetooth-binding

Eclipse SmartHome Bluetooth Binding
46 stars 10 forks source link

Gigaset G-tag gets stale shortly after added #52

Open thelaoshi opened 6 years ago

thelaoshi commented 6 years ago

My tag somehow gets stale and offline soon after I added it from the inbox. It never gets discovered anymore nor does it get online I totally have to remove BT things and restart OH to get it back into discovery

Here is the debug output:


2018-06-07 01:39:34.232 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 0; New: 0; Rediscovered: 5; Stale: 0
2018-06-07 01:39:42.833 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel online is linked although the handler was already disposed.
2018-06-07 01:39:42.837 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel last-updated is linked although the handler was already disposed.
2018-06-07 01:39:42.840 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel rssi is linked although the handler was already disposed.
2018-06-07 01:39:42.844 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel tx-power is linked although the handler was already disposed.
2018-06-07 01:39:42.847 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel estimated-distance is linked although the handler was already disposed.
2018-06-07 01:39:42.850 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel adapter is linked although the handler was already disposed.
2018-06-07 01:39:42.854 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel location is linked although the handler was already disposed.
2018-06-07 01:39:42.859 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel connected is linked although the handler was already disposed.
2018-06-07 01:39:42.862 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel connection-control is linked although the handler was already disposed.
2018-06-07 01:39:42.866 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel connected-adapter is linked although the handler was already disposed.
2018-06-07 01:39:42.869 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BluetoothDeviceHandler of thing bluetooth:ble:7C2F80A1231C tried checking if channel authenticated is linked although the handler was already disposed.
2018-06-07 01:39:42.878 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Creating a new governor: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.896 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Initializing governor: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.898 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Initializing combined device governor: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.903 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Creating a new governor: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.914 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Initializing governor: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.916 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Trying to find object factory: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.918 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Protocol is unknown. Trying to find factory amongst discovered adapters: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.921 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Matching adapter found amongst discovered adapters: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.933 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - A new native object has been acquired: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.935 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Initializing governor with the new native object: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.937 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Initializing device governor: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:42.940 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Enabling RSSI notification: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : true
2018-06-07 01:39:42.947 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Enabling connection notification: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : true
2018-06-07 01:39:42.953 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Enabling services resolved notification: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : true
2018-06-07 01:39:42.958 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Enabling blocked notification: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : true
2018-06-07 01:39:42.964 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Enabling manufacturer data notification: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : true
2018-06-07 01:39:42.970 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Enabling service data notification: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : true
2018-06-07 01:39:42.978 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isPowered): /B8:27:EB:84:CA:F2 / 18cf040
2018-06-07 01:39:42.983 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isConnected): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:42.986 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying manager listeners (governor ready): 0 : true
2018-06-07 01:39:42.987 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isPowered): /B8:27:EB:84:CA:F2 / 18cf040
2018-06-07 01:39:42.991 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isConnected): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:42.993 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Registering a new delegate: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : 0
2018-06-07 01:39:42.999 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Initializing safe operations: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:43.002 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Setting blocked control: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : false
2018-06-07 01:39:43.004 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Setting connection control: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : false / false
2018-06-07 01:39:43.007 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting online: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false / false
2018-06-07 01:39:43.029 [DEBUG] [anager.impl.CompletableFutureService] - Trying to complete future immediately: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : org.sputnikdev.bluetooth.manager.impl.CombinedDeviceGovernorImpl$DeviceGovernorHandler$$Lambda$608/15678951@1929ce9
2018-06-07 01:39:43.032 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Initializing unsafe operations: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:43.036 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (getBluetoothClass): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.040 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isBleEnabled): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.045 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (getName): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.049 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (getAlias): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.054 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (getRSSI): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.060 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting ready: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false / true
2018-06-07 01:39:43.067 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isBlocked): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.070 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting blocked: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false / false
2018-06-07 01:39:43.075 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isConnected): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.078 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting connected: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false / false
2018-06-07 01:39:43.087 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isServicesResolved): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.090 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Initializing unsafe operations successfully completed: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:43.092 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Combined device governor initialization performed: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C
2018-06-07 01:39:43.096 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Checking if delegates are stale: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C / false / false
2018-06-07 01:39:43.096 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Setting blocked control: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : false
2018-06-07 01:39:43.101 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Updating connection target: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false
2018-06-07 01:39:43.106 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Current target / new target: null / /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:39:43.265 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (setAlias): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.278 [WARN ] [.core.thing.binding.BaseThingHandler] - BaseThingHandler.initialize() will be removed soon, ThingStatus can be set manually via updateStatus(ThingStatus.ONLINE)
2018-06-07 01:39:43.281 [DEBUG] [anager.impl.CompletableFutureService] - Trying to complete future immediately: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : org.sputnikdev.bluetooth.manager.BluetoothGovernor$$Lambda$569/1513948@188a85d
2018-06-07 01:39:43.312 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting connection control: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false
2018-06-07 01:39:43.332 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (getRSSI): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.336 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Setting connection control: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : false / false
2018-06-07 01:39:43.355 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (getRSSI): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.364 [DEBUG] [anager.impl.CompletableFutureService] - Trying to complete future immediately: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : org.sputnikdev.bluetooth.manager.BluetoothGovernor$$Lambda$569/1513948@188a85d
2018-06-07 01:39:43.371 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (setAlias): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:39:43.443 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:39:44.268 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 5 discovered devices
2018-06-07 01:39:44.273 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:39:44.280 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:39:44.289 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:39:44.295 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C [Gigaset G-tag] : 1
2018-06-07 01:39:44.300 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
2018-06-07 01:39:44.307 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 0; New: 0; Rediscovered: 5; Stale: 0
2018-06-07 01:39:52.654 [DEBUG] [oth.manager.impl.AdapterGovernorImpl] - Updating adapter governor: /B8:27:EB:84:CA:F2
2018-06-07 01:39:53.448 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:39:54.343 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 5 discovered devices
2018-06-07 01:39:54.346 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:39:54.351 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:39:54.357 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:39:54.363 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C [Gigaset G-tag] : 1
2018-06-07 01:39:54.368 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
2018-06-07 01:39:54.374 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 0; New: 0; Rediscovered: 5; Stale: 0
2018-06-07 01:40:02.994 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isPowered): /B8:27:EB:84:CA:F2 / 18cf040
2018-06-07 01:40:02.998 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isConnected): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:40:03.001 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Updating online state: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : false (current) / true (new)
2018-06-07 01:40:03.003 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Notifying device governor listener (online): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : 1 : true
2018-06-07 01:40:03.008 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting online: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false / true
2018-06-07 01:40:03.109 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Checking if delegates are stale: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C / false / false
2018-06-07 01:40:03.113 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Updating connection target: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false
2018-06-07 01:40:03.117 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Current target / new target: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:40:03.456 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:40:04.410 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 5 discovered devices
2018-06-07 01:40:04.415 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:40:04.421 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:40:04.428 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:40:04.434 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C [Gigaset G-tag] : 1
2018-06-07 01:40:04.438 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
2018-06-07 01:40:04.444 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 0; New: 0; Rediscovered: 5; Stale: 0
2018-06-07 01:40:12.663 [DEBUG] [oth.manager.impl.AdapterGovernorImpl] - Updating adapter governor: /B8:27:EB:84:CA:F2
2018-06-07 01:40:13.511 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:40:14.479 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 5 discovered devices
2018-06-07 01:40:14.483 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:40:14.489 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:40:14.497 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:40:14.508 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C [Gigaset G-tag] : 1
2018-06-07 01:40:14.514 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
2018-06-07 01:40:14.522 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 0; New: 0; Rediscovered: 5; Stale: 0
2018-06-07 01:40:23.013 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isPowered): /B8:27:EB:84:CA:F2 / 18cf040
2018-06-07 01:40:23.017 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isConnected): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:40:23.121 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Checking if delegates are stale: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C / false / false
2018-06-07 01:40:23.125 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Updating connection target: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false
2018-06-07 01:40:23.128 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Current target / new target: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:40:23.516 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:40:24.560 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 5 discovered devices
2018-06-07 01:40:24.565 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:40:24.576 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:40:24.591 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:40:24.601 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C [Gigaset G-tag] : 1
2018-06-07 01:40:24.610 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
2018-06-07 01:40:24.622 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 0; New: 0; Rediscovered: 5; Stale: 0
2018-06-07 01:40:32.667 [DEBUG] [oth.manager.impl.AdapterGovernorImpl] - Updating adapter governor: /B8:27:EB:84:CA:F2
2018-06-07 01:40:33.523 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:40:34.657 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 5 discovered devices
2018-06-07 01:40:34.662 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:40:34.667 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:40:34.674 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:40:34.680 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C [Gigaset G-tag] : 1
2018-06-07 01:40:34.685 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
2018-06-07 01:40:34.692 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 0; New: 0; Rediscovered: 5; Stale: 0
2018-06-07 01:40:43.021 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isPowered): /B8:27:EB:84:CA:F2 / 18cf040
2018-06-07 01:40:43.025 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isConnected): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / 1c3b900
2018-06-07 01:40:43.132 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Checking if delegates are stale: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C / false / false
2018-06-07 01:40:43.134 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Interacting with native object (isDiscovering): /B8:27:EB:84:CA:F2 / 18cf040
2018-06-07 01:40:43.141 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Device /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C last advertised (never) ago and last interacted (60s) ago. Stale timeout: 120s. Device is considered stale: true
2018-06-07 01:40:43.143 [WARN ] [ager.impl.CombinedDeviceGovernorImpl] - Possible stale object detected: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C
2018-06-07 01:40:43.147 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Resetting governor. Descendants first: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:40:43.160 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Resetting device governor: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:40:43.163 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Updating online state: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : true (current) / false (new)
2018-06-07 01:40:43.165 [DEBUG] [ooth.manager.impl.DeviceGovernorImpl] - Notifying device governor listener (online): /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : 1 : false
2018-06-07 01:40:43.167 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting online: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : true / false
2018-06-07 01:40:43.170 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Delegate changed ready state: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C : false
2018-06-07 01:40:43.170 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Trying to find object factory: tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:40:43.173 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Services unresolved (listener): /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C
2018-06-07 01:40:43.189 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting connected: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false / false
2018-06-07 01:40:43.205 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Setting ready: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : true / false
2018-06-07 01:40:43.210 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying manager listeners (governor ready): 0 : false
2018-06-07 01:40:43.223 [DEBUG] [impl.AbstractBluetoothObjectGovernor] - Governor has been reset: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:40:43.226 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Updating connection target: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false
2018-06-07 01:40:43.229 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Current target / new target: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:40:43.531 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:40:44.727 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 4 discovered devices
2018-06-07 01:40:44.731 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Device has been lost: tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:40:44.738 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:40:44.743 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:40:44.750 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:40:44.758 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
2018-06-07 01:40:44.765 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 1; New: 0; Rediscovered: 4; Stale: 0
2018-06-07 01:40:52.672 [DEBUG] [oth.manager.impl.AdapterGovernorImpl] - Updating adapter governor: /B8:27:EB:84:CA:F2
2018-06-07 01:40:53.538 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:40:54.794 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 4 discovered devices
2018-06-07 01:40:54.799 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:40:54.807 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:40:54.817 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:40:54.824 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
2018-06-07 01:40:54.831 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Lost: 0; New: 0; Rediscovered: 4; Stale: 0
2018-06-07 01:41:03.030 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Trying to find object factory: tinyb://B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:41:03.232 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Checking if delegates are stale: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C / false / false
2018-06-07 01:41:03.234 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Updating connection target: /XX:XX:XX:XX:XX:XX/7C:2F:80:A1:23:1C : false
2018-06-07 01:41:03.236 [DEBUG] [ager.impl.CombinedDeviceGovernorImpl] - Current target / new target: /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C / /B8:27:EB:84:CA:F2/7C:2F:80:A1:23:1C
2018-06-07 01:41:03.546 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 1 discovered adapters
2018-06-07 01:41:04.861 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Transport [tinyb] reported 4 discovered devices
2018-06-07 01:41:04.866 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/78:BD:BC:CC:D8:60 [78-BD-BC-CC-D8-60] : 1
2018-06-07 01:41:04.873 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/94:65:2D:7B:BE:A2 [OnePlus 5] : 1
2018-06-07 01:41:04.881 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/58:C5:CB:FE:6B:FC [Gear Fit2 Pro (6BFC)] : 1
2018-06-07 01:41:04.887 [DEBUG] [th.manager.impl.BluetoothManagerImpl] - Notifying device discovery listeners (discovered): [Device] tinyb://B8:27:EB:84:CA:F2/5C:49:7D:78:14:97 [[TV] Samsung 7 Series (49)] : 1
thelaoshi commented 6 years ago

Ok seems I narrowed it a bit down. If I restart the bluetooth daemon the Device gets online again, but after a few minutes I see this in the log:

Jun 07 02:23:52 rasp3 kernel: Bluetooth: hci0 command 0x200c tx timeout
Jun 07 02:23:52 rasp3 kernel: Bluetooth: Failed to disable LE scan: status 0x1f

And afterwards the binding seems to loose the connection to the item.

vkolotov commented 6 years ago

hi @thelaoshi, what version of Bluez are you running?

Make sure you use 5.47 version which is the most stable.

thelaoshi commented 6 years ago

Hey, I initially tried the Arch Bundled version which is 5.49. Thats where I got the errors. Then I tried 5.47 but I did no reload/restart. So I first thought, that there is no difference, but today I tried everything again and switched back to 5.47 and now it seems to work :-) I see even more things now, too.

I now have this in the syslog though:

Jun 09 09:34:37 rasp3 [3147]: failed to execute '/usr/bin/hciconfig' '/usr/bin/hciconfig hci0:64 up': No such file or directory
Jun 09 09:34:37 rasp3 systemd-udevd[3146]: Process '/usr/bin/hciconfig hci0:64 up' failed with exit code 2.

Seems that hciconfig is not in the bluez default package ? Is it needed for anything? Not sure if just another packages from my os tries to use it.

thelaoshi commented 6 years ago

Guess I was too optimistic .... still the same with 5.47. And the same error msg I posted above.

vkolotov commented 6 years ago

Right. It seems to me there is something wrong with the adapter driver or the adapter itself. According to your logs, it fails to stop scanning process. Could you please try to disable scan by using the bluetoothctl?

pi@raspberrypi:~ $ bluetoothctl 
select <adapter mac>
[bluetooth]# scan off
Discovery stopped

Have a look if it generates the same error in your syslog.

thelaoshi commented 6 years ago

No it doesnt, but i get the message Failed to stop discovery: org.bluez.Error.Failed directly in bluetoothctl.

I'm running openhab on an Rasp 3 with onboard bluetooth.

thelaoshi commented 6 years ago

Ah ok i guess thats because discovery is already disabled ... somehow. If I try "scan on", scan off" I dont get the error msg.

And in the binding logs I seen, that it still finds the discovered items + I see them in the inbox. Still the added things are offline and in the logs it looks like the binding does not find them.

tried around with bluetoothctl and I just found out, that just a "power off" seems to help for a few minutes. The binding seems to notice that the power is off and turns it on again and finds the devices again too. Until the error message in the syslogs pops up again...

vkolotov commented 6 years ago

What's your kernel version? It seems to me there was a bug introduced in some recent versions of linux kernel:

https://bbs.archlinux.org/viewtopic.php?id=230366

I'm running

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.9.35-v7+ #1014 SMP Fri Jun 30 14:47:43 BST 2017 armv7l GNU/Linux
xrucka commented 6 years ago

Hi, I can confirm the bug on raspberry pi 3; I'm using OpenSuSE Leap 42.3 aarch64; the bug seems to span rather deep (and for quite some time). I'm using external bluetooth dongle, I was not able to find the issue within the bluetooth stack, rather than USB one, as usb over IP based dongles work fine to me.

In general, the issue is that bluez is waiting for confirmation from dongle, which never comes - possibly due to lost packet.

Btw, the SuSE kernel numbering reports 4.4.126 ; but there is the issue of custom numbering - SuSE guys often backport a lot of patches from higher upstream kernel releases.

xrucka commented 6 years ago

Furthermore, in my experience, resetting the bluetooth dongle via hciconfig hci0 reset allows for recovery without restarting the bluetoothd, which can be automated upon parsing dmesg output. However, this requires elevated priviledges.

Unfortunately, the broken tx timeout also disrupts ongoing connections. I'm not sure whether the connected clients keep the broken connection or not, but I'm not able to connect to any other device unless I perform the reset.

The usbip dongle I currently use is shared from another raspberry pi 3, running libreelec with 4.9.80 kernel. So far, it works without any issues (though, I'm currently using custom bluetooth transport provider, that bypases tinyb and uses direct dbus calls instead).

vkolotov commented 6 years ago

Hey @xrucka,

(though, I'm currently using custom bluetooth transport provider, that bypases tinyb and uses direct dbus calls instead)

This is really awesome! I was going to use this library to do so! TinyB is annoying useless layer.

xrucka commented 6 years ago

This is really awesome! I was going to use this library to do so! TinyB is annoying useless layer.

I ended up using it's upstream and wrote this. It might still have some issues (it still needs native libraries as the dbus library relies on unix sockets, which - at least back in java 1.5 - were not supported).

Unfortunately, I do not have enough experience with maven to force include of system classpath into the jar file, so it needs manual jar manifest modifications. Feel free to use it / comment on it / develop it further.

vkolotov commented 6 years ago

@xrucka this is very cool, I was dreaming to get rid of TinyB. I'll have a look what we can do to improve maven stuff and soon roll out your awesome transport!

vkolotov commented 6 years ago

BTW, those native libs are already in OH, both java-dbus (unfortunately the original one) and sockets ("utils"-something).

xrucka commented 6 years ago

Referencing the original issue, as this seems quite related: #https://github.com/sputnikdev/eclipse-smarthome-bluetooth-binding-tinyb-transport/issues/1

thelaoshi commented 6 years ago

I'm on Linux version 4.14.44-1-ARCH (builduser@leming) (gcc version 8.1.0 (GCC)) #1 SMP Fri Jun 1 13:13:07 UTC 2018

on my raspberry it helps to just do a "power off" with bluetoothctl. Seems as the binding recognizes this and then restarts the connection?