Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
coconup opened this issue Feb 19, 2024 · 4 comments
Open

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

coconup opened this issue Feb 19, 2024 · 4 comments

Comments

@coconup
Copy link

coconup commented Feb 19, 2024 •
edited

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

#25 (comment)

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
Copy link
Author

coconup commented Feb 19, 2024

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

@fl4p
Copy link
Owner

fl4p commented Feb 20, 2024

Does it recover after the timeout?

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

@coconup
Copy link
Author

coconup commented Feb 20, 2024 •
edited

@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
Copy link

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@peteretep @fl4p @coconup