[bluetooth.govee] Unstable connection / sporadic or no updates

dhilgarth commented 2 years ago

Expected Behavior

The connection to the Govee device should be stable. Stable meaning:

It shouldn't switch between ONLINE, OFFLINE (COMMUNICATION_ERROR) and OFFLINE without apparent reason.
When connected, it should update the channels in the configured interval

Current Behavior

Connection is unstable. With the device right next to the RPi, it switches between ONLINE, OFFLINE (COMMUNICATION_ERROR) and OFFLINE. But even when ONLINE, it doesn't realiably update the values My log:

It's now 18:40, so 16 minutes after the yellow WARN entry in the log. It came ONLINE on 18:18, so it didn't update the channels even once in that 22 minutes, although it is set to update every minute. Whenever the state switched to UNKNOWN, I edited and saved the Thing. Also, more issue reports in the Community: https://community.openhab.org/t/govee-bluetooth-binding/115543/22

Steps to Reproduce (for Bugs)

For me: Just add a Govee H5075 and check the logs where it's obvious that it's unreliable

Context

I'm trying to get a consistent reading of my temperature and humidity to graph them and understand thermal insulation issues in my home at night.

Your Environment

openHABian on SD card in RPi 4 2GB. Freshly installed today according to https://www.openhab.org/download/ -> "Option 1: Flash the openHABian image to a SD card (Recommended)"

Technical Details:

runtimeInfo:
  version: 3.3.0
  buildString: Release Build
locale: en-DE
systemInfo:
  configFolder: /etc/openhab
  userdataFolder: /var/lib/openhab
  logFolder: /var/log/openhab
  javaVersion: 11.0.16
  javaVendor: Raspbian
  osName: Linux
  osVersion: 5.15.61-v7l+
  osArchitecture: arm
  availableProcessors: 4
  freeMemory: 28031368
  totalMemory: 154140672
  startLevel: 100
bindings:
  - bluetooth
  - homematic
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
    prefersColorScheme: dark
  isSecureContext: false
  locationbarVisible: true
  menubarVisible: true
  navigator:
    cookieEnabled: true
    deviceMemory: N/A
    hardwareConcurrency: 14
    language: en-US
    languages:
      - en-US
    onLine: true
    platform: Win32
  screen:
    width: 3840
    height: 1600
    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/105.0.0.0 Safari/537.36
timestamp: 2022-09-20T16:47:49.234Z

My config: Bluetooth interface Thing:

UID: bluetooth:bluez:hci0
label: Bluetooth Interface openhabian
thingTypeUID: bluetooth:bluez
configuration:
  backgroundDiscovery: false
  inactiveDeviceCleanupThreshold: 300
  address: E4:5F:01:D5:5D:23
  inactiveDeviceCleanupInterval: 60

Govee Hygrometer Thing:

UID: bluetooth:goveeHygrometerMonitor:hci0:a4c13865b28e
label: Govee Temperature Humidity Monitor (Pool)
thingTypeUID: bluetooth:goveeHygrometerMonitor
configuration:
  temperatureWarningMax: 0
  humidityWarningMax: 0
  address: A4:C1:38:65:B2:8E
  humidityWarningMin: 0
  refreshInterval: 60
  temperatureWarningMin: 0
  temperatureWarningAlarm: false
  humidityWarningAlarm: false
bridgeUID: bluetooth:bluez:hci0

davidoe commented 1 year ago

I have the same problem with a Govee H5102

lsiepel commented 1 year ago

Could you set the binding at debug log level? And (if not allready) update to 3.4.0 stable? If you can share the generated log file, especially at the start of the online/offline flipping, i might look into this.

sfranzis commented 1 year ago

Im running on 3.4.0 and experiencing the same with two H5075.

lsiepel commented 1 year ago

Can you share a trace log ? Prefer to have a seperate log just for the bluetooth.govee binding.

sfranzis commented 1 year ago

Here my current log. Stopped working after a few minutes. Reboot fixes the issue again.


2023-01-02 16:23:54.354 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetTemHumCommand
2023-01-02 16:26:54.408 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - refreshing temperature, humidity, and battery
2023-01-02 16:26:54.409 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetBatteryCommand
2023-01-02 16:26:54.472 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetTemHumCommand
2023-01-02 16:29:54.518 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - refreshing temperature, humidity, and battery
2023-01-02 16:29:54.518 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetBatteryCommand
2023-01-02 16:29:54.582 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetTemHumCommand
2023-01-02 16:32:54.643 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - refreshing temperature, humidity, and battery
2023-01-02 16:32:54.644 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetBatteryCommand
2023-01-02 16:32:54.702 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetTemHumCommand
2023-01-02 16:35:54.789 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - refreshing temperature, humidity, and battery
2023-01-02 16:35:54.790 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetBatteryCommand
2023-01-02 16:35:54.812 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - Failed to get battery: org.freedesktop.dbus.exceptions.DBusExecutionException: In Progress
2023-01-02 16:35:54.813 [WARN ] [ovee.internal.GoveeHygrometerHandler] - unable to refresh
java.util.concurrent.CompletionException: java.util.concurrent.ExecutionException: org.freedesktop.dbus.exceptions.DBusExecutionException: In Progress
    at java.util.concurrent.CompletableFuture.reportJoin(CompletableFuture.java:412) ~[?:?]
    at java.util.concurrent.CompletableFuture.join(CompletableFuture.java:2044) ~[?:?]
    at org.openhab.binding.bluetooth.govee.internal.GoveeHygrometerHandler.lambda$2(GoveeHygrometerHandler.java:124) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
    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:829) [?:?]
Caused by: java.util.concurrent.ExecutionException: org.freedesktop.dbus.exceptions.DBusExecutionException: In Progress
    at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395) ~[?:?]
    at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999) ~[?:?]
    at org.openhab.binding.bluetooth.ConnectedBluetoothHandler.lambda$4(ConnectedBluetoothHandler.java:208) ~[?:?]
    at org.openhab.binding.bluetooth.util.RetryFuture$CallableTask.run(RetryFuture.java:67) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    ... 3 more
Caused by: org.freedesktop.dbus.exceptions.DBusExecutionException: In Progress
    at jdk.internal.reflect.GeneratedConstructorAccessor195.newInstance(Unknown Source) ~[?:?]
    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.$Proxy331.StartNotify(Unknown Source) ~[?:?]
    at com.github.hypfvieh.bluetooth.wrapper.BluetoothGattCharacteristic.startNotify(BluetoothGattCharacteristic.java:235) ~[?:?]
    at org.openhab.binding.bluetooth.bluez.internal.BlueZBluetoothDevice.lambda$3(BlueZBluetoothDevice.java:279) ~[?:?]
    at org.openhab.binding.bluetooth.util.RetryFuture$CallableTask.run(RetryFuture.java:67) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    ... 3 more

crun11 commented 1 year ago

Hello, is there already a solution for this? I have the same problem. It always works only shortly after setup or a reboot. The thing then has the status online, but there is no update and warning messages are written in the openhab.log.

lsiepel commented 1 year ago

What value do you have for refresh interval?

2023-01-02 16:32:54.643 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - refreshing temperature, humidity, and battery
2023-01-02 16:32:54.644 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetBatteryCommand
2023-01-02 16:32:54.702 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetTemHumCommand

2023-01-02 16:35:54.789 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - refreshing temperature, humidity, and battery
2023-01-02 16:35:54.790 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - sending message: GetBatteryCommand
2023-01-02 16:35:54.812 [DEBUG] [ovee.internal.GoveeHygrometerHandler] - Failed to get battery: org.freedesktop.dbus.exceptions.DBusExecutionException: In Progress

Looking at the log, i see two queries to the device. 140ms in between. The error is "In Progress". So my interim conclusion would be that the call from the first is not yet finished.

These lines of code: https://github.com/openhab/openhab-addons/blob/main/bundles/org.openhab.binding.bluetooth.govee/src/main/java/org/openhab/binding/bluetooth/govee/internal/GoveeHygrometerHandler.java#L120-L132

In the end it looks like the message is send by the underlying dependency bluetooth gattserial, that probably has some dependency on the org.freedesktop.dbus that throws the exception. When looking for this namespace, only bluetooth.bluez comes up, but that is confusing as it is not in the dependency list of bluetooth.govee.

The fix might be adding some check to wait before it becomes available, or just update these dependencies. When it comes down to dependencies, my knowledge is limited.

openhab / openhab-addons