MySensors entities are not properly set when activating scenes/automations in Home Assistant

[feanor-anglin]

I have the same problem as described here: home-assistant/core#59388

When sending multiple messages at the same time from HA to MySensors nodes I frequently experience some messages remain undelivered. The author of the issue I've linked to has managed to identify the problem is on MySensors side, but haven't provided any details. In my opinion this is a really serious disadvantage, probably the most important I experience using MySensors in my project. Can we do something about it? :)

Additional details: I use Ethernet Gateway and RS485; the problem is also present when using Serial Gateway and wireless communication.

[virtual-maker]

See also issue #1512.

@feanor-anglin Hi, do you also use signing? And do you use NRF24 radios for wireless?

[feanor-anglin]

No, I don't use signing, since I use RS485 wired communication. The guy from home assistant issue said he used wireless.

[virtual-maker]

I assume it has to do with RS485.
Can you provide debug logs from gateway and node? I think best is to start a discussion in MySensors forum for this.

[feanor-anglin]

Unfortunately, I can't provide debug from gateway, since there is too little memory to enable it. But, the author of the issue I've linked has provided some.

2021-11-08 18:56:31 DEBUG (MainThread) [mysensors.transport] Sending 6;0;1;1;41;ffff60b8                                                                                                                           
2021-11-08 18:56:31 DEBUG (MainThread) [mysensors.transport] Sending 7;0;1;1;2;1                                                                                                                                   
2021-11-08 18:56:31 DEBUG (MainThread) [mysensors.transport] Sending 7;0;1;1;3;89
2021-11-08 18:56:31 DEBUG (MainThread) [mysensors.transport] Sending 7;0;1;1;41;ffff00d6
2021-11-08 18:56:31 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736274 TSF:MSG:SEND,0-0-6-6,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2021-11-08 18:56:31 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736274 TSF:MSG:SEND,0-0-6-6,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2021-11-08 18:56:31 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736282 !MCO:PRO:RC=1
2021-11-08 18:56:31 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736282 !MCO:PRO:RC=1
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736321 !TSF:MSG:SEND,0-0-7-7,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=NACK:
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736321 !TSF:MSG:SEND,0-0-7-7,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=NACK:
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736328 !TSF:MSG:SIGN FAIL
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736328 !TSF:MSG:SIGN FAIL
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736332 TSF:MSG:READ,6-6-0,s=255,c=3,t=17,pt=6,l=25,sg=0:<NONCE>
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736332 TSF:MSG:READ,6-6-0,s=255,c=3,t=17,pt=6,l=25,sg=0:<NONCE>
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736339 !MCO:PRO:RC=1
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736339 !MCO:PRO:RC=1
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736378 !TSF:MSG:SEND,0-0-7-7,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=NACK:
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736378 !TSF:MSG:SEND,0-0-7-7,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=NACK:
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736385 !TSF:MSG:SIGN FAIL
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736385 !TSF:MSG:SIGN FAIL
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736389 !MCO:PRO:RC=1
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736389 !MCO:PRO:RC=1
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736428 !TSF:MSG:SEND,0-0-7-7,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=NACK:
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736428 !TSF:MSG:SEND,0-0-7-7,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=NACK:
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736435 !TSF:MSG:SIGN FAIL
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736435 !TSF:MSG:SIGN FAIL
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736439 !MCO:PRO:RC=1
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107736439 !MCO:PRO:RC=1
2021-11-08 18:56:32 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107736442 !MCO:PRO:RC=1
...
2021-11-08 18:56:36 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;9;1107741282 !TSF:MSG:SIGN FAIL                                                                                                  
2021-11-08 18:56:36 DEBUG (MainThread) [mysensors.handler] n:0 c:255 t:3 s:9 p:1107741282 !TSF:MSG:SIGN FAIL

[mfalkvidd]

Those messages show signing failures, so the cause of those messages is probably not related to your setup.

[feanor-anglin]

Ok, so it seems there are 2 kinds of problems with sending messages with short time interval: signing problem and RS485 problem. Shortly I will try to check if the issue is also applicable to wireless setup with no signing and RS485 setup under domoticz (serial and Ethernet).

Do you guys think we should move this discussion to mysensors forum?

[mfalkvidd]

Github is better if the problem is related to the library code.
The forum is better for general troubleshooting, as there are many more people with practical experience of MySensors in the forum.

Since we're really at the troubleshooting stage, we might get better help in the forum. Hopefully someone with a RS485 setup can chime in.

[dgertych-monterail]

I've debugged exact same problem, I did not use signing. I've used PJON with gateway-node communication, but it's not on that layer IMHO. I could reproduce the issue even on the serial gateway without any node too.

You can simply flood the gateway with a lot of messages, and only part of the messages gets executed and the others are lost. That's why in many places you recommend using wait() to not flood the gateway. Unfortunately, the Home Assistant sends messages in async nearly at the same time.

In comparison, I've noticed that OpenHab configuration has the sendDelay property https://github.com/tobof/openhab-addons/wiki/Configuration#configuring-the-gateway, but didn't manage to test it.

Does the gateway implement any buffer for received messages?

[feanor-anglin]

@chytreg I came to the same conclusion about this issue, very nice to hear you support it. The sendDelay you are talking about seems very nice workaround. It should be proposed to HA-MySensors integration devs.

[dgertych-monterail]

@feanor-anglin Looks like Domoticz implements sendDelay too.

As for HomeAssistant they are using pymysensors with the asyncio.
I'm not sure if this send method is blocking or not, but it's worth to try put some sleep there and check.

[feanor-anglin]

@chytreg I've reported this issue to HA and included your findings. Hope something will be finally done with this.

[feanor-anglin]

It seems HA dev requires the sendDelay parameter to be put into the official MySensors documentation. @mfalkvidd, are you the right person to ask for it?

[mfalkvidd]

@feanor-anglin sorry, I don't understand. MySensors does not have anything called sendDelay. According to a comment above, openHab does have such a property. But would it really make sense for MySensors to document a property that exists in openHab?

[dgertych-monterail]

I did some tests, with HA and Domowicz here are my findings, https://gist.github.com/chytreg/dcd1c7449fca25e9480c7c463d7ec031
My setup: ESP8266 as TCP Gateway + 1 Node on Arduino Mega, with 16 relays, I use PJON.

You can simply flood the gateway with a lot of messages, and only part of the messages gets executed and the others are lost. That's why in many places you recommend using wait() to not flood the gateway. Unfortunately, the Home Assistant sends messages in async nearly at the same time

It's not about flooding the gateway, it's about that node requires some time to process the messages. I think it's not even a HA vs Domowicz thing. In my simple node sketch when I remove wait(100) I receive a lot of NACK on node part.

The same happens in HA, because it sends all the command in the same time to the Node.
Domoticz on the other hand send command in the queue with some delay so the Node has time to process them.

There is one thing I don't understand why I need to use wait(100) is it hardware limitation or software one? Thus I believe Domowicz / OpenHub implemented send in synchronous / queued way. cc @mfalkvidd

I did some recordings:
Domoticz: Turn ON/OFF all relays => NO NACKs on Node

IMG_2361.1.mov

HA: Turn ON all relays => NACKs on Node

IMG_2362.1.mov