shm-et340 breaks dbus-mqtt

[dominikfe]

Hi!
After some investigation I could isolate the reason, why dbus-mqtt in VenusOS is dying constantly with the following error message in /var/log/dbus-mqtt/current:

@400000006352c6dd24b60c64 INFO:dbus_mqtt:[Scanning] service: com.victronenergy.grid.cgwacs_ttyUSB0_di30_mb1
@400000006352c6dd26049cd4 ERROR:connection:Exception in handler for D-Bus signal:
@400000006352c6dd2604b05c Traceback (most recent call last):
@400000006352c6dd2604bc14   File "/opt/victronenergy/dbus-mqtt/dbus_mqtt.py", line 397, in _scan_dbus_service
@400000006352c6dd2604cbb4     items = self._get_dbus_value(service, '/')
@400000006352c6dd2604d76c   File "/opt/victronenergy/dbus-mqtt/dbus_mqtt.py", line 533, in _get_dbus_value
@400000006352c6dd2604e324     return self._dbus_conn.call_blocking(service, path, None, 'GetValue', '', [])
@400000006352c6dd26060434   File "/usr/lib/python3.8/site-packages/dbus/connection.py", line 652, in call_blocking
@400000006352c6dd260613d4     reply_message = self.send_message_with_reply_and_block(
@400000006352c6dd26061f8c dbus.exceptions.DBusException: org.freedesktop.DBus.Error.UnknownMethod: Unknown / invalid method
@400000006352c6dd26062f2c 
@400000006352c6dd260636fc During handling of the above exception, another exception occurred:
@400000006352c6dd2606a844 
@400000006352c6dd2606b014 Traceback (most recent call last):
@400000006352c6dd2606bbcc   File "/usr/lib/python3.8/site-packages/dbus/connection.py", line 232, in maybe_handle_message
@400000006352c6dd2606cb6c     self._handler(*args, **kwargs)
@400000006352c6dd2606d724   File "/opt/victronenergy/dbus-mqtt/dbus_mqtt.py", line 365, in _dbus_name_owner_changed
@400000006352c6dd2606e6c4     self._scan_dbus_service(name, publish=True)
@400000006352c6dd2607503c   File "/opt/victronenergy/dbus-mqtt/dbus_mqtt.py", line 401, in _scan_dbus_service
@400000006352c6dd2608520c     self._introspect(service, device_instance, '/', publish)
@400000006352c6dd260861ac   File "/opt/victronenergy/dbus-mqtt/dbus_mqtt.py", line 441, in _introspect
@400000006352c6dd26086d64     self._introspect(service, device_instance, p, publish=publish)
@400000006352c6dd2608791c   File "/opt/victronenergy/dbus-mqtt/dbus_mqtt.py", line 423, in _introspect
@400000006352c6dd260888bc     value = self._dbus_conn.call_blocking(service, path, None, 'Introspect', '', [])
@400000006352c6dd260a1b14   File "/usr/lib/python3.8/site-packages/dbus/connection.py", line 652, in call_blocking
@400000006352c6dd260a2e9c     reply_message = self.send_message_with_reply_and_block(
@400000006352c6dd260a3a54 dbus.exceptions.DBusException: org.freedesktop.DBus.Error.UnknownMethod: Unknown / invalid method

When I disable shm-et340 and restart the system, dbus-mqtt runs perfectly until I start shm-et340.
Can you please have a look, if your code is sending any odd data to dbus causing dbus.mqtt to die, please?

Problem exists with all versions of VenusOS 2.9x

[slankes]

I've had this happen to me as well and it also seems to have affected the data that is sent/not sent to the vrm portal.

I am running this fork to support my EM-1 https://github.com/fishpepper/shm-et340 and it seems that after upgrading to the latest beta (3.00~14) of venus os things have changed.

I am not comfotable yet saying that things are working now but what I can state is:

1. The gridmeter still shows data
2. vrm portal data is current (this was usually only current when I stopped the shm-et340 process)
3. the error in the above logfile no longer appears

[henne49]

I can confirm, the update to beta, seems to fix it for me

[slankes]

My comment seems to have been too early. After a few days the error is back and while the local system still works fine, what is shown in vrm is again incorrect.

[henne49]

same here, not correct anymore.

[henne49]

But a reboot of Venus OS fixes it again as well.

[slankes]

I've added some more debugging to the python script:

--- connection.py.orig	2023-01-09 13:28:11.950297004 +0100
+++ connection.py	2023-01-09 13:32:43.983470326 +0100
@@ -663,9 +663,15 @@
             raise
 
         # make a blocking call
-        reply_message = self.send_message_with_reply_and_block(
-            message, timeout)
-        args_list = reply_message.get_args_list(**get_args_opts)
+        try:
+            reply_message = self.send_message_with_reply_and_block(
+                message, timeout)
+            args_list = reply_message.get_args_list(**get_args_opts)
+        except Exception as e:
+            logging.basicConfig()
+            _logger.error('Unable to send message %s / %s / %s', 
+                          e.__class__, e, message)
+            raise
         if len(args_list) == 0:
             return None

and that is the addition log output that I gathered:

@4000000063c7cc5832069e24 INFO:dbus_mqtt:[Scanning] service: com.victronenergy.battery.socketcan_can0
@4000000063c7cc5832c2cdec INFO:dbus_mqtt:[Scanning] service: com.victronenergy.system
@4000000063c7cc5834f41d3c INFO:dbus_mqtt:[Scanning] service: com.victronenergy.fronius
@4000000063c7cc58352585ac ERROR:connection:Unable to send message <class 'dbus.exceptions.DBusException'> / org.freedesktop.DBus.Error.UnknownObject: No such object path '/DeviceInstance' / <dbus.lowlevel.MethodCallMessage path: /DeviceInstance, iface: n/a, member: GetValue dest: com.victronenergy.fronius>
@4000000063c7cc5835756acc INFO:dbus_mqtt:[Scanning] service: com.victronenergy.vebus.ttyS4
@4000000063c7cc58377d314c INFO:dbus_mqtt:[Scanning] service: com.victronenergy.grid.cgwacs_ttyUSB0_di30_mb1
@4000000063c7cc5837e8acec ERROR:connection:Unable to send message <class 'dbus.exceptions.DBusException'> / org.freedesktop.DBus.Error.UnknownMethod: Unknown / invalid method / <dbus.lowlevel.MethodCallMessage path: /, iface: n/a, member: GetValue dest: com.victronenergy.grid.cgwacs_ttyUSB0_di30_mb1>
@4000000063c7cc583867f6dc ERROR:connection:Unable to send message <class 'dbus.exceptions.DBusException'> / org.freedesktop.DBus.Error.UnknownMethod: Unknown / invalid method / <dbus.lowlevel.MethodCallMessage path: /ProductName, 

[fishpepper]

I made a "hacky" workaround for this issue by patching dbus-mqtt.py

/data/dbus-mqtt.patch

--- dbus_mqtt.py
+++ dbus_mqtt_patched.py
@@ -381,6 +381,9 @@
        def _scan_dbus_service(self, service, publish=False):
                try:
                        logging.info('[Scanning] service: {}'.format(service))
+                       if service == "com.victronenergy.grid.cgwacs_ttyUSB0_di30_mb1":
+                               logging.info('[Scanning] --> ignored shm340 dbus bridge')
+                               return
                        try:
                                device_instance = int(self._get_dbus_value(service, '/DeviceInstance'))
                        except dbus.exceptions.DBusException as e:

(this basically tells this script to ignore shm340 data)

and then added this to my /data/rc.local

patch /opt/victronenergy/dbus-mqtt/dbus_mqtt.py < /data/dbus-mqtt.patch

This seems to fix it for me. However this is just a temporary fix as updates to the dbus2mqtt service might break it.
The clean way would be to fix this dbus service. I think the crash is related to this warning:

@400000006485ead60af2e11c WARNING:dbus_mqtt:[Scanning] com.victronenergy.qwacs does not provide an item listing

[fishpepper]

I disliked the "hackiness" of that approach and added a fix to my shm-et340 branch,
see https://github.com/fishpepper/shm-et340/tree/fix-9-dbus2mqtt .

Still kind of hacky but at least it requires no venus modification :)
Needs testing, but seems to work the last hour for my setup :)

(released bin here: v0.4a https://github.com/fishpepper/shm-et340/releases)

[mitchese]

This looks a lot less hacky and really nice, thanks! Looking at your improvements helps me learn a lot. Do you mind if I merge this back in, as I think it's much better than what I have at the moment.