search

fl4p / batmon-ha

Add-on for Home Assistant to connect JK, JBD, Daly, ANT, SOK and Supervolt BMS via Bluetooth
MIT License
313 stars 60 forks source link

JBD times out constantly after a few minutes of successful sampling #203

Open coconup opened 9 months ago

coconup commented 9 months ago

I'm running batmon in standalone mode through docker as outlined here (on a Raspberry Pi):

https://github.com/fl4p/batmon-ha/issues/25#issuecomment-1952473454

This is my options.json file:

{
  "devices": [
    {
      "address": "A4:C1:38:0B:79:22",
      "type": "jbd",
      "alias": "jbd1"
    }
  ],
  "sample_period": 15.0,
  "publish_period": 30.0,
  "concurrent_sampling": false
}

Everything runs smoothly for a few minutes, then suddenly I start getting timeouts and not a single successful update goes through:

16:03:41 INFO [sampling] Bleak version 0.20.2
16:03:41 ERROR [main] 1 exceptions occurred fetching BMSs
16:03:41 ERROR [main] Error (num 2, max 0) reading BMS: timeout waiting for 3
16:03:41 ERROR [main] Stack: Traceback (most recent call last):
  File "/usr/lib/python3.11/asyncio/tasks.py", line 500, in wait_for
    return fut.result()
           ^^^^^^^^^^^^
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/app/bmslib/__init__.py", line 81, in wait_for
    return await asyncio.wait_for(self._futures.get(name), timeout)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/tasks.py", line 502, in wait_for
    raise exceptions.TimeoutError() from exc

TimeoutError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/app/./main.py", line 36, in fetch_loop
    if await fn():
       ^^^^^^^^^^
  File "/app/./main.py", line 321, in fn
    raise exceptions[0]
  File "/app/./main.py", line 316, in fn
    await t()
  File "/app/bmslib/sampling.py", line 159, in __call__
    s = await self._sample_inner()
        ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/bmslib/sampling.py", line 241, in _sample_inner
    sample = await bms.fetch()
             ^^^^^^^^^^^^^^^^^
  File "/app/bmslib/models/jbd.py", line 75, in fetch
    buf = await self._q(cmd=0x03)
          ^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/bmslib/models/jbd.py", line 69, in _q
    return await self._fetch_futures.wait_for(cmd, self.TIMEOUT)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/bmslib/__init__.py", line 84, in wait_for
    raise asyncio.TimeoutError("timeout waiting for %s" % name)
TimeoutError: timeout waiting for 3
16:03:56 INFO [sampling] connecting bms JbdBt(A4:C1:38:0B:79:22,jbd1)
16:03:57 INFO [sampling] connected bms JbdBt(A4:C1:38:0B:79:22,jbd1)!

Note that the log hangs forever at the last line when this happens. No new logs are ever added

This is how the same scenario looks with verbose logging enabled:


# ... all looking good above here

15:15:43 INFO [sampling] connected bms JbdBt(A4:C1:38:0B:79:22,jbd1)!
15:15:43 DEBUG [client] Write Characteristic 0000ff02-0000-1000-8000-00805f9b34fb | /org/bluez/hci0/dev_A4_C1_38_0B_79_22/service000f/char0014: b'\xdd\xa5\x03\x00\xff\xfdw'
15:15:43 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_0B_79_22/service000f/char0010): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\xdd\x03\x00\x1b\x05,\x00\x00Rdbp\x00\x00)<\x00\x00\x00\x00'))>}, []]
15:15:43 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_0B_79_22/service000f/char0010): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x00\x00\x17T\x03\x04\x02\x0bq\x0bv\xfcVw'))>}, []]
15:15:43 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_0B_79_22/service000f/char0010): ['org.bluez.GattCharacteristic1', {'Notifying': <dbus_fast.signature.Variant ('b', False)>}, []]
15:15:43 DEBUG [client] Disconnecting (/org/bluez/hci0/dev_A4_C1_38_0B_79_22)
15:15:43 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_84_C6_92_13_C0_F4/service002c/char002d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\xff\x03\x02\x00\x04\x90S'))>}, []]
15:16:05 DEBUG [client] Sending PINGREQ
15:16:05 DEBUG [client] Received PINGRESP
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_54_7B_09_15_9F_0A', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_78_A5_04_7B_12_8A', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_39_D0_1E_02_6F_0E', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_61_18_41_E5_EC_FB', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_5F_65_6B_BF_80_B0', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_4F_16_7A_41_16_4D', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_60_9F_F9_30_DC_87', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_DB_F1_20_34_A7_1A', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_54_51_CC_95_D4_E9', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:10 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_7C_DC_EE_E9_95_7D', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_E1_A1_83_8A_98_09', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_53_64_B1_6E_CD_E1', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_79_9E_96_24_1F_BB', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_58_74_21_7A_68_37', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_4C_81_FB_DA_B6_79', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_72_4D_4A_F5_56_DA', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_EC_81_93_59_7E_35', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_5B_9A_60_8D_56_51', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_D4_D4_DA_7D_B2_82', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_53_42_A4_D4_4B_42', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_F0_B3_EC_0B_41_FC', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_54_B7_E5_B4_A8_79', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_65_B9_E8_00_FE_A0', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_9C_3E_53_28_DB_20', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_06_45_4E_04_52_E9', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_70_88_03_E3_B7_26', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_57_19_1D_40_91_20', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_6C_A0_10_BC_AE_AE', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_64_49_04_07_B3_54', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_74_40_A9_02_90_1F', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_61_70_AE_86_B0_92', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:11 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_51_64_20_DC_3E_CE', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
15:16:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:17:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:17:05 DEBUG [client] Sending PINGREQ
15:17:05 DEBUG [client] Received PINGRESP
15:17:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:18:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:18:05 DEBUG [client] Sending PINGREQ
15:18:05 DEBUG [client] Received PINGRESP
15:18:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:19:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:19:05 DEBUG [client] Sending PINGREQ
15:19:05 DEBUG [client] Received PINGRESP
15:19:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:20:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:20:05 DEBUG [client] Sending PINGREQ
15:20:05 DEBUG [client] Received PINGRESP
15:20:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:21:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:21:05 DEBUG [client] Sending PINGREQ
15:21:05 DEBUG [client] Received PINGRESP
15:21:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:22:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:22:05 DEBUG [client] Sending PINGREQ
15:22:05 DEBUG [client] Received PINGRESP
15:22:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:23:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:23:05 DEBUG [client] Sending PINGREQ
15:23:05 DEBUG [client] Received PINGRESP
15:23:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:24:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:24:05 DEBUG [client] Sending PINGREQ
15:24:05 DEBUG [client] Received PINGRESP
15:24:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:25:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:25:05 DEBUG [client] Sending PINGREQ
15:25:05 DEBUG [client] Received PINGRESP
15:25:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:26:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:26:05 DEBUG [client] Sending PINGREQ
15:26:05 DEBUG [client] Received PINGRESP
15:26:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:27:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:27:05 DEBUG [client] Sending PINGREQ
15:27:05 DEBUG [client] Received PINGRESP
15:27:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:28:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:28:06 DEBUG [client] Sending PINGREQ
15:28:06 DEBUG [client] Received PINGRESP
15:28:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:29:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:29:06 DEBUG [client] Sending PINGREQ
15:29:06 DEBUG [client] Received PINGRESP
15:29:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:30:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:30:06 DEBUG [client] Sending PINGREQ
15:30:06 DEBUG [client] Received PINGRESP
15:30:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:31:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:31:06 DEBUG [client] Sending PINGREQ
15:31:06 DEBUG [client] Received PINGRESP
15:31:35 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:32:05 DEBUG [manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
15:32:06 DEBUG [client] Sending PINGREQ
15:32:06 DEBUG [client] Received PINGRESP

Finally - but this might be an unrelated issue - many times after restarting the container, I get this error:

15:39:06 INFO [sampling] Bleak version 0.20.2
15:39:06 ERROR [main] 1 exceptions occurred fetching BMSs
15:39:06 ERROR [main] Error (num 12, max 0) reading BMS: [org.bluez.Error.InProgress] Operation already in progress
15:39:06 ERROR [main] Stack: Traceback (most recent call last):
  File "/app/./main.py", line 36, in fetch_loop
    if await fn():
       ^^^^^^^^^^
  File "/app/./main.py", line 321, in fn
    raise exceptions[0]
  File "/app/./main.py", line 316, in fn
    await t()
  File "/app/bmslib/sampling.py", line 155, in __call__
    s = await self._sample_inner()
        ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/bmslib/sampling.py", line 227, in _sample_inner
    async with bms:
  File "/app/bmslib/bt.py", line 345, in __aenter__
    await self.connect()
  File "/app/bmslib/models/jbd.py", line 53, in connect
    await super().connect(**kwargs)
  File "/app/bmslib/bt.py", line 237, in connect
    await self._connect_client(timeout=timeout)
  File "/app/bmslib/bt.py", line 186, in _connect_client
    await asyncio.wait_for(self.client.connect(timeout=timeout), timeout=timeout + 1)
  File "/usr/lib/python3.11/asyncio/tasks.py", line 489, in wait_for
    return fut.result()
           ^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/bleak/__init__.py", line 531, in connect
    return await self._backend.connect(**kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/bleak/backends/bluezdbus/client.py", line 124, in connect
    device = await BleakScanner.find_device_by_address(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/bleak/__init__.py", line 310, in find_device_by_address
    return await cls.find_device_by_filter(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/bleak/__init__.py", line 369, in find_device_by_filter
    async with cls(detection_callback=apply_filter, **kwargs):
  File "/usr/lib/python3.11/site-packages/bleak/__init__.py", line 152, in __aenter__
    await self._backend.start()
  File "/usr/lib/python3.11/site-packages/bleak/backends/bluezdbus/scanner.py", line 191, in start
    self._stop = await manager.active_scan(
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/bleak/backends/bluezdbus/manager.py", line 368, in active_scan
    assert_reply(reply)
  File "/usr/lib/python3.11/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.InProgress] Operation already in progress

The only way out of this last issue is a reboot or running systemctl restart bluetooth on the host. I suspect when the container restarts, some child process is not terminated.

coconup commented 9 months ago

Update: it appears this is only happening when other processes (in my case in a separate container) access other bluetooth devices.

fl4p commented 9 months ago

Does it recover after the timeout?

For the Operation already in progress issue, did you try bt_power_cycle ?

coconup commented 9 months ago

@fl4p it appears the issue only occurs when some other service is accessing the bluetooth. In my case, I have another container fetching data from my Renogy MPPT controller. Both services (the renogy and batmon) poll for data every 15 seconds.

It seems when I turn the renogy container off, batmon works fine and without interruption. If the renogy service is running, batmon starts showing the behaviour above very quickly. To answer your first question - it never recovers after the timeout and it appears the only way to regain connectivity to the BMS is to restart the bluetooth in my Raspberry Pi. I suspect therefore that some orphan connection is left behind when the timeout occurs, which keeps the BMS's bluetooth busy.

As an additional piece of info, this is the library I am using to communicate with the MPPT controller: https://github.com/cyrils/renogy-bt

That one never seems to lose connectivity because of batmon running alongside it.

peteretep commented 9 months ago

Aah, I have a similar issue that could be due to the same reason - I'm using the victron hacs integration to access my victron mptt controller. Will disable that integration and try it out, not a big deal as the solar isn't producing much at all up in Shetland. But it would be great to have them both working.

ThomasCr commented 1 month ago

I have the same error:

Sep 30 16:49:37 rpitemp python3[2691]: 16:49:37 INFO [sampling] Bleak version 0.13.1a1
Sep 30 16:49:37 rpitemp python3[2691]: 16:49:37 ERROR [main] 1 exceptions occurred fetching BMSs
Sep 30 16:49:37 rpitemp python3[2691]: 16:49:37 ERROR [main] Error (num 7, max 0) reading BMS: timeout waiting for 3
Sep 30 16:49:37 rpitemp python3[2691]: 16:49:37 ERROR [main] Stack: Traceback (most recent call last):
Sep 30 16:49:37 rpitemp python3[2691]:   File "/usr/lib/python3.11/asyncio/tasks.py", line 490, in wait_for
Sep 30 16:49:37 rpitemp python3[2691]:     return fut.result()
Sep 30 16:49:37 rpitemp python3[2691]:            ^^^^^^^^^^^^
Sep 30 16:49:37 rpitemp python3[2691]: asyncio.exceptions.CancelledError
Sep 30 16:49:37 rpitemp python3[2691]: The above exception was the direct cause of the following exception:
Sep 30 16:49:37 rpitemp python3[2691]: Traceback (most recent call last):
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/bmslib/__init__.py", line 81, in wait_for
Sep 30 16:49:37 rpitemp python3[2691]:     return await asyncio.wait_for(self._futures.get(name), timeout)
Sep 30 16:49:37 rpitemp python3[2691]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Sep 30 16:49:37 rpitemp python3[2691]:   File "/usr/lib/python3.11/asyncio/tasks.py", line 492, in wait_for
Sep 30 16:49:37 rpitemp python3[2691]:     raise exceptions.TimeoutError() from exc
Sep 30 16:49:37 rpitemp python3[2691]: TimeoutError
Sep 30 16:49:37 rpitemp python3[2691]: During handling of the above exception, another exception occurred:
Sep 30 16:49:37 rpitemp python3[2691]: Traceback (most recent call last):
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/main.py", line 36, in fetch_loop
Sep 30 16:49:37 rpitemp python3[2691]:     if await fn():
Sep 30 16:49:37 rpitemp python3[2691]:        ^^^^^^^^^^
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/main.py", line 319, in fn
Sep 30 16:49:37 rpitemp python3[2691]:     raise exceptions[0]
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/main.py", line 314, in fn
Sep 30 16:49:37 rpitemp python3[2691]:     await t()
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/bmslib/sampling.py", line 155, in __call__
Sep 30 16:49:37 rpitemp python3[2691]:     s = await self._sample_inner()
Sep 30 16:49:37 rpitemp python3[2691]:         ^^^^^^^^^^^^^^^^^^^^^^^^^^
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/bmslib/sampling.py", line 237, in _sample_inner
Sep 30 16:49:37 rpitemp python3[2691]:     sample = await bms.fetch()
Sep 30 16:49:37 rpitemp python3[2691]:              ^^^^^^^^^^^^^^^^^
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/bmslib/models/jbd.py", line 75, in fetch
Sep 30 16:49:37 rpitemp python3[2691]:     buf = await self._q(cmd=0x03)
Sep 30 16:49:37 rpitemp python3[2691]:           ^^^^^^^^^^^^^^^^^^^^^^^
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/bmslib/models/jbd.py", line 69, in _q
Sep 30 16:49:37 rpitemp python3[2691]:     return await self._fetch_futures.wait_for(cmd, self.TIMEOUT)
Sep 30 16:49:37 rpitemp python3[2691]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Sep 30 16:49:37 rpitemp python3[2691]:   File "/opt/batmon-ha/bmslib/__init__.py", line 84, in wait_for
Sep 30 16:49:37 rpitemp python3[2691]:     raise asyncio.TimeoutError("timeout waiting for %s" % name)
Sep 30 16:49:37 rpitemp python3[2691]: TimeoutError: timeout waiting for 3
Sep 30 16:49:38 rpitemp python3[2691]: 16:49:38 INFO [sampling] connecting bms JbdBt(10:A5:62:23:B8:B5,jbd1)
Sep 30 16:49:39 rpitemp python3[2691]: 16:49:39 ERROR [bt] [org.bluez.Error.Failed] le-connection-abort-by-local, starting scanner

But I don't have any other application which is communication with the BMS and also the BT interface of the Raspberry Pi Zero 2 W is no used by any other app.

Maybe a protocol implementation error? Can we supply any detailed logs?

ThomasCr commented 1 month ago

I was searching yesterday for more information`s about the BMS which is build into my Vatrer Power 51.2v 100ah LiFePo4 battery - it should be Jiabaida / JBD SP16S020

Informations from Overkill Solar App: Manufacturer: ZJDY Firmware Version: 6.2 Device Name: SP16S020L16S100A

I also found maybe some useful informations on that download page: JDB RS485-RS232-UART-Bluetooth-Communication Protocol