[BUG] Uncontrolled/unexpected node msg reception

[pippajb]

I have noticed with recent past versions and and have just confirmed using v3.10~36 that there are issues with the rate of message reception from the victron nodes.

I am finding that the '5 second' transmission rate does not work, for example I count messages received for gps speed and see a continuous stream rather than one every 5 seconds (this did work sometime back).

Another 'related' issue is with multiplus switch position, here again the 5 second rule doesn't work, but further 'on change' doesn't either. Again I see multiple messages coming in even when there is no actual switch change (and the payload is unchanged from the previous)! I believe there are other nodes at fault also.

The result of this issue is heavily loading my dashboard.

Steps to reproduce the behaviour

This is a snapshot of my test flow:

Both counts increase unexpectedly.

Hardware

• Venus GX

Versions

• node-red-contrib-victron version: 1.5.0
• Venus OS version: v3.10~36

[dirkjanfaber]

Thank you. I'll try to reproduce this. Which add-on is used for the counter?

[pippajb]

Hi, the counter is just a simple node to increment a global when triggered, one global for each Count., the count being showed as a status.

[dirkjanfaber]

Understood, but which add-on provided that? I now used node-red-contrib-msg-counter and that one seems to count as I would have expected.

[pippajb]

I've just tested using node-red-contrib-msg-counter and still see the same issue, odd.

My flow is as follows:

[
    {
        "id": "afd84ad68566263c",
        "type": "subflow",
        "name": "Subflow 1",
        "info": "",
        "category": "",
        "in": [
            {
                "x": 60,
                "y": 80,
                "wires": [
                    {
                        "id": "4bc84f12b60f5f8a"
                    }
                ]
            }
        ],
        "out": [
            {
                "x": 320,
                "y": 80,
                "wires": [
                    {
                        "id": "4bc84f12b60f5f8a",
                        "port": 0
                    }
                ]
            }
        ],
        "env": [
            {
                "name": "Global",
                "type": "str",
                "value": ""
            }
        ],
        "meta": {},
        "color": "#DDAA99",
        "status": {
            "x": 320,
            "y": 140,
            "wires": [
                {
                    "id": "4bc84f12b60f5f8a",
                    "port": 0
                }
            ]
        }
    },
    {
        "id": "4bc84f12b60f5f8a",
        "type": "function",
        "z": "afd84ad68566263c",
        "name": "count",
        "func": "let cn = env.get(\"Global\");\n\nlet c = global.get(cn) || 0;\n\nc += 1;\n\nglobal.set(cn, c);\n\nreturn msg, { payload: c };",
        "outputs": 1,
        "noerr": 0,
        "initialize": "",
        "finalize": "",
        "libs": [],
        "x": 190,
        "y": 80,
        "wires": [
            []
        ]
    },
    {
        "id": "37e3dc4f19d3c3a8",
        "type": "victron-input-vebus",
        "z": "a391b0aaa47af7ca",
        "service": "com.victronenergy.vebus/261",
        "path": "/Mode",
        "serviceObj": {
            "service": "com.victronenergy.vebus/261",
            "name": "Multiplus"
        },
        "pathObj": {
            "path": "/Mode",
            "type": "enum",
            "name": "Switch Position",
            "enum": {
                "1": "Charger Only",
                "2": "Inverter Only",
                "3": "On",
                "4": "Off"
            }
        },
        "initial": "",
        "name": "",
        "onlyChanges": true,
        "x": 290,
        "y": 280,
        "wires": [
            [
                "9bb0e8f944bc39ff",
                "36d8cce074dc3bd3",
                "620949e31944d50c"
            ]
        ]
    },
    {
        "id": "9bb0e8f944bc39ff",
        "type": "subflow:afd84ad68566263c",
        "z": "a391b0aaa47af7ca",
        "name": "Count",
        "env": [
            {
                "name": "Global",
                "value": "mp_switch_position_rx_count",
                "type": "str"
            }
        ],
        "x": 510,
        "y": 280,
        "wires": [
            [
                "f8be936d9148a1b9"
            ]
        ]
    },
    {
        "id": "f8be936d9148a1b9",
        "type": "ui_text",
        "z": "a391b0aaa47af7ca",
        "group": "c8925b86dc3fff6a",
        "order": 1,
        "width": 0,
        "height": 0,
        "name": "",
        "label": "MP Switch Position Rx#",
        "format": "{{msg.payload}}",
        "layout": "row-spread",
        "className": "",
        "style": false,
        "font": "",
        "fontSize": 16,
        "color": "#000000",
        "x": 710,
        "y": 280,
        "wires": []
    },
    {
        "id": "36d8cce074dc3bd3",
        "type": "ui_text",
        "z": "a391b0aaa47af7ca",
        "group": "c8925b86dc3fff6a",
        "order": 2,
        "width": 0,
        "height": 0,
        "name": "",
        "label": "MP Switch Position",
        "format": "{{msg.payload}}",
        "layout": "row-spread",
        "className": "",
        "style": false,
        "font": "",
        "fontSize": 16,
        "color": "#000000",
        "x": 550,
        "y": 340,
        "wires": []
    },
    {
        "id": "aeb9067fea293224",
        "type": "comment",
        "z": "a391b0aaa47af7ca",
        "name": "Configured for On change",
        "info": "",
        "x": 290,
        "y": 240,
        "wires": []
    },
    {
        "id": "620949e31944d50c",
        "type": "msg-counter",
        "z": "a391b0aaa47af7ca",
        "name": "Bufferstack.IO msg counter",
        "x": 580,
        "y": 240,
        "wires": [
            [
                "e939c4f3e336304e"
            ]
        ]
    },
    {
        "id": "e939c4f3e336304e",
        "type": "debug",
        "z": "a391b0aaa47af7ca",
        "name": "debug 48",
        "active": true,
        "tosidebar": true,
        "console": false,
        "tostatus": false,
        "complete": "true",
        "targetType": "full",
        "statusVal": "",
        "statusType": "auto",
        "x": 800,
        "y": 240,
        "wires": []
    },
    {
        "id": "c8925b86dc3fff6a",
        "type": "ui_group",
        "name": "Group 1",
        "tab": "b2f23b6cb05cba5e",
        "order": 1,
        "disp": true,
        "width": 6
    },
    {
        "id": "b2f23b6cb05cba5e",
        "type": "ui_tab",
        "name": "Tab 1",
        "icon": "dashboard",
        "order": 1
    }
]

[dirkjanfaber]

I've been thinking a bit about it and to get back to your remark:

I am finding that the '5 second' transmission rate does not work, for example I count messages received for gps speed and see a continuous stream rather than one every 5 seconds (this did work sometime back).

What the node does, is send out a message every 5 seconds and on each value change. It is correct that this can result in more messages than just 1 per 5 seconds. If the value does not change, it outputs once every 5 seconds. With a gps, I can imagine that the value changes more frequently.

I cannot recall that the behavior of the node changed regarding this behavior during the last updates.

A limit rater can prevent this behavior. I'll keep this issue open, as it may be a good idea to also implement the limit rater within this node.

[tkurki]

Just making sure you are aware of https://cookbook.nodered.org/basic/rate-limit-message-stream

[pippajb]

I have used the delay node for this sort of purpose before. I went one better to ignore passing on any payload that is the same as the previous, thus only presenting a change downstream.

I think my expectations differed to the actual implementation, hence how this thread started.

If things are not to change I shall carry on using my implementation to 'rate limit', but I would still prefer to see it done at the source.

However, can anyone else confirm the issue I see with the multiplus switch position, I get a lot of messages as stated, even when there is no actual change!

[dirkjanfaber]

However, can anyone else confirm the issue I see with the multiplus switch position, I get a lot of messages as stated, even when there is no actual change!

The nodes respond to the dbus signals:

      this.bus.addMatch("type='signal',interface='com.victronenergy.BusItem',member='ItemsChanged'", () => { })
      this.bus.addMatch("type='signal',interface='com.victronenergy.BusItem',member='PropertiesChanged'", () => { })
      this.bus.addMatch("type='signal',member='NameOwnerChanged'", () => { })

If the devices sends an "ItemsChanged" or "PropertiesChanged", even when there is no change (which it should not do), then the node will assume the value changed and output the value.

On the commandline these signals can be made visible using dbus-monitor --system path=/,member=ItemsChanged (or putting PropertiesChanged, instead of ItemsChanged). This will also show all the other changes on the system, so it may be a bit hard to filter.

I tried replicating the issue on a system here with a Multiplus-II, but there I don't see any switch position changes.

Can you attach a chart graph to the node to show the points?

[{"id":"8ca4603bf48e84c9","type":"victron-input-vebus","z":"1d0b68fd941d658b","service":"com.victronenergy.vebus/257","path":"/Mode","serviceObj":{"service":"com.victronenergy.vebus/257","name":"MultiPlus-II 48/3000/35-32"},"pathObj":{"path":"/Mode","type":"enum","name":"Switch Position","enum":{"1":"Charger Only","2":"Inverter Only","3":"On","4":"Off"}},"initial":"","name":"","onlyChanges":true,"x":340,"y":260,"wires":[["585317a83da76204","0b47bd543be1bed3"]]},{"id":"585317a83da76204","type":"debug","z":"1d0b68fd941d658b","name":"debug 1","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"false","statusVal":"","statusType":"auto","x":740,"y":260,"wires":[]},{"id":"0b47bd543be1bed3","type":"ui_chart","z":"1d0b68fd941d658b","name":"","group":"c8925b86dc3fff6a","order":0,"width":0,"height":0,"label":"itemschanged","chartType":"line","legend":"false","xformat":"HH:mm:ss","interpolate":"linear","nodata":"","dot":true,"ymin":"","ymax":"","removeOlder":1,"removeOlderPoints":"","removeOlderUnit":"3600","cutout":0,"useOneColor":false,"useUTC":false,"colors":["#1f77b4","#aec7e8","#ff7f0e","#2ca02c","#98df8a","#d62728","#ff9896","#9467bd","#c5b0d5"],"outputs":1,"useDifferentColor":false,"className":"","x":740,"y":180,"wires":[[]]},{"id":"c8925b86dc3fff6a","type":"ui_group","name":"Group 1","tab":"b2f23b6cb05cba5e","order":1,"disp":true,"width":6},{"id":"b2f23b6cb05cba5e","type":"ui_tab","name":"Tab 1","icon":"dashboard","order":1}]

If the node outputs non-changing values (it does output once on each deploy), you should be seeing a lot more non-changing points in the graph.

[pippajb]

Attaching the graph for itemschanged does show that the value doesn't change for each message received. However, adding a graph to show the message reception count, shows that a lot of unexpected messages do arrive - over 100 per minute.

You are correct that 'dbus-monitor --system path=/,member=ItemsChanged' does output a lot and is near impossible to filter.
Doing 'dbus-monitor --system path=/,member=PropertiesChanged' shows:

signal time=1694446020.177471 sender=org.freedesktop.DBus -> destination=:1.5913 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
string ":1.5913"
signal time=1694446020.178719 sender=org.freedesktop.DBus -> destination=:1.5913 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
string ":1.5913"

and nothing more. All this is with a Multiplus, not a II though.

[dirkjanfaber]

The Node-RED node merely does what it happening on the dbus. Can you tell me a little bit more about the used Multiplus? Perhaps that firmware sends out the info too often. What type is it and is it running the latest firmware?

[pippajb]

One version off the latest I believe.

[dirkjanfaber]

There is a newer firmware (506), but there are no changes there regarding dbus changes. So that should not be it.
What also causes an ItemsChanged (or PropertiesChanged) message, is when you write the mode as well as read from it.
Can it be that you have another flow (or another process) writing the mode?

[pippajb]

The are no writing to multiplus switch position nodes in my flow. When I did a retest to document this issue I tested in isolation, the entirety of my flows is shown at the opening of this thread.

[dirkjanfaber]

I'd tried to reproduce this on a local system, but so far failed. If possible, I'd like to take a look at your system and see what is causing it. Can you enable remote support and provide your vrm id? You may also mail it to dfaber at victronenergy dot com if you don't want to provide it here.

[thepaulcooper]

I'm interested in this issue as my system relies on the five seconds message rate (I'm still on a pre v3 version of Venus). Has it been resolved? Thanks.

[pippajb]

I'm interested in this issue as my system relies on the five seconds message rate (I'm still on a pre v3 version of Venus). Has it been resolved? Thanks.

Hi Paul, I'm not ignoring you (honest). I am going back to basics to analysis this and my loading issues. As I am running into high CPU utilisation to the point things are breaking. This may still be due to high signal input rates, but will have a definitive answer in a couple of days.

[pippajb]

After 'some' modifications to my node-red and further testing I do have some results.

This testing has been performed using v3.20~2.

Here is an extract of my signal table, with two pairs of test input signals, one of which is configured to be a '5 second' update and one 'on change' (and rounded in case of the input voltage).

Please note, and as clarified by Victron, that '5 seconds' does not guarantee one message every 5 seconds! What it means is that if the data does not change you will get one message every 5 seconds, but for each change you will also get a message!!

Here are the results for an approximate 5 minute run:

Explanation on table headings:

1. Rx count - is the number of messages received from the victron signal node
2. Passed through - is logic to only pass through actual payload changes, to further reduce duplicate payloads, thus:
   2.1. Count - is the number of messages passed out of my signal processing subflow
   2.2. Time - is the last time a message was passed out
   2.3. Value - is the passed out payload

Starting with the simple case
mp_input_current_limit*, is a signal that does not change throughout the 5 min test.
Thus the '5 second' update indeed is seen approx every 5 seconds, ~60 in 5 mins as expected.
The 'on_change' again is only seen once, as expected.
The value is further confirmed not to be changing in both cases as only one message is passed through, as seen in the table.

The more complicated case
This one is hard to explain and IMO suggests some broken logic somewhere. The '5 second' option actually results in more messages being seen, possibly because messages are sent on a change and every 5 seconds (guessing). But I do seem to be getting a lot more messages from the victron node than expected, indicated by the rejection rate, ie my pass through logic is only passing a small number through as it does not see the payload change from one message to the next in many cases!

Overall I am seeing a bit of a mixed bag on various signals that I am dealing with in my system. Victron have raised an issue relating to the Multiplus switch position as I mentions at the top of this thread - they have confirmed an issue with the MkII dbus sending out excessive messages.

As regarding other messages that I see as excessive, in a 5 minute test run my pass through logic is rejecting 52% of all victron node messages!! Although the biggest hitter is the multiplus switch position

In conclusion
There do appear to be some issues, but with the recent Victron modifications and my further reducing passing on messages I am better able to run on my Venus GX, although loading does regularly spike high, it does now run better.

It would be appreciated if Victron could look into the other messages that I have highlighted to confirm or deny.

[dirkjanfaber]

@thepaulcooper: Have you seen https://github.com/victronenergy/node-red-contrib-victron/wiki/Example-Flows#only-messages-at-regular-intervals ? If you want regular intervals, this might help.

[thepaulcooper]

Hi. Thanks for that. Yes, I am very familiar with Node-Red and the possibility of using the method in the link, or indeed a Delay node set as a rate limiter. My issue is that I have 20 Victron input nodes and it seems to me to be unnecessary to have to add 20 Delay nodes to get back the previous behaviour of precisely 'one message every five seconds'. Before this change was introduced we were told that the previous behaviour would be an option, however this has been subtly changed to 'one message every five seconds plus all changes’ . That is not "backward compatibility" and breaks any previous flows that relied on precisely one message every five seconds. Yes, it is fixable with a Delay node, but why was it implemented like that?

…

On 19 Sep 2023, at 10:33, Dirk-Jan Faber ***@***.***> wrote: @thepaulcooper <https://github.com/thepaulcooper>: Have you seen https://github.com/victronenergy/node-red-contrib-victron/wiki/Example-Flows#only-messages-at-regular-intervals ? If you want regular intervals, this might help. — Reply to this email directly, view it on GitHub <#185 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AENQL5H6KFB4A52JN2ELWOTX3FRH7ANCNFSM6AAAAAA4QEVPSQ>. You are receiving this because you were mentioned.

[dirkjanfaber]

The technical change was due to switching from PropertiesChanged to ItemsChanged on the dbus, which causes this non-backward compatible change. This change was introduced to reduce the load on the dbus and is successfully doing that.

That being said, I hear you, when you want the old behaviour back. I think I may have an idea on bringing that back to the system (adding an option to ignore the ItemsChanged messages). But that would also mean that changes that occur during the 5 seconds and return back to the value of the last reported value will be missed by your nodes. Is that acceptable?

I am also curious about the use-case where the 5 second delay and no messages in between makes sense.

[thepaulcooper]

Thanks for the explanation @dirkjanfaber. To be honest, for most of the 20 input nodes it won't matter if there are additional messages to the one occurring every five seconds. However where it will matter is in two areas: 1) limiting the amount of data being fed into a Chart node – no more than once every five seconds gives a fixed number of data points for a time-based chart; 2) I am calculating an average using a Smooth node – the mean over a time period is calculated from a fixed number of messages. As I said before, these examples are fixable but I was just curious why the behaviour needed to change.