Home assistant triggers a mysensor light, nothing happens

[Richard van der Plas]

I have my aquarium lights connected through NRF24L01+ to my Ethernet Pi gateway which is also running Home assistant.
Homeassistant starts an automation (which is shown in the log).
the trigger starts @ 18:06
This occasionally happens, also with other sensors (motion activated).
How can i troubleshoot further ?
Looks like something with the radio, but it's only with the automations, when i manually flick the switch it just goes
Is there someway you can force the gateway to retry ?

Mysensors log:

mysgw: Client 0: 4;2;1;0;2;1
mysgw: !TSF:MSG:SEND,0-0-4-4,s=2,c=1,t=2,pt=0,l=1,sg=0,ft=0,st=NACK:1
mysgw: Client 0: 4;2;1;0;3;4
mysgw: !TSF:MSG:SEND,0-0-4-4,s=2,c=1,t=3,pt=0,l=1,sg=0,ft=0,st=NACK:4
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 4;1;1;0;2;0
mysgw: !TSF:MSG:SEND,0-0-4-4,s=1,c=1,t=2,pt=0,l=1,sg=0,ft=0,st=NACK:0
mysgw: Client 0: 0;255;3;0;2;
mysgw: TSF:MSG:READ,4-4-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
mysgw: TSF:MSG:BC
mysgw: TSF:MSG:FPAR REQ,ID=4
mysgw: TSF:PNG:SEND,TO=0
mysgw: TSF:CKU:OK
mysgw: TSF:MSG:GWL OK
mysgw: TSF:MSG:SEND,0-0-4-4,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: TSF:MSG:READ,4-4-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
mysgw: TSF:MSG:BC
mysgw: TSF:MSG:FPAR REQ,ID=4
mysgw: TSF:PNG:SEND,TO=0
mysgw: TSF:CKU:OK
mysgw: TSF:MSG:GWL OK
mysgw: TSF:MSG:SEND,0-0-4-4,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:READ,4-4-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
mysgw: TSF:MSG:PINGED,ID=4,HP=1
mysgw: TSF:MSG:SEND,0-0-4-4,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=OK:1
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: TSF:MSG:READ,4-4-0,s=0,c=1,t=0,pt=7,l=5,sg=0:24.25
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: TSF:SRT:OK
mysgw: TSF:SAN:OK
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: Client 0: 0;255;3;0;2;
mysgw: TSF:MSG:READ,3-4-0,s=2,c=1,t=1,pt=7,l=5,sg=0:54.0

Home assistant log of the trigger

hass[1366]: #033[32m2017-11-02 17:08:42 INFO (MainThread) [homeassistant.helpers.script] Script aqua_to_night: Running script#033[0m
hass[1366]: #033[32m2017-11-02 17:08:42 INFO (MainThread) [homeassistant.helpers.script] Script aqua_to_night: Executing step call service#033[0m
hass[1366]: #033[32m2017-11-02 17:08:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service_data=entity_id=light.aquarium_4_2, brightness=10, domain=light, service=turn_on, service_call_id=1970958224-421>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state automation.aquarium_night_light_on_auto=on; id=Aqua Verlichting nacht Auto, friendly_name=Aquarium Night Light On Auto, last_triggered=2017-11-02T18:08:42.394140+01:00 @ 2017-10-29T22:18:42.206057+01:00>, entity_id=automation.aquarium_night_light_on_auto, old_state=<state automation.aquarium_night_light_on_auto=on; id=Aqua Verlichting nacht Auto, friendly_name=Aquarium Night Light On Auto, last_triggered=2017-11-01T18:10:35.996885+01:00 @ 2017-10-29T22:18:42.206057+01:00>>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1970958224-421>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1970958224-420>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state script.aqua_to_night=on; can_cancel=True, friendly_name=aqua_to_night, last_triggered=2017-11-02T18:08:42.378463+01:00, last_action=call service @ 2017-11-02T18:08:42.436591+01:00>, entity_id=script.aqua_to_night, old_state=<state script.aqua_to_night=off; can_cancel=True, friendly_name=aqua_to_night, last_triggered=2017-11-01T18:10:42.955284+01:00 @ 2017-11-
02T07:38:32.985038+01:00>>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:45 INFO (MainThread) [homeassistant.components.http] Serving /api/12345678901234567890/lights to 192.168.1.113 (auth: False)#033[0m
hass[1366]: #033[32m2017-11-02 17:08:49 INFO (MainThread) [homeassistant.helpers.script] Script aqua_to_night: Executing step call service#033[0m
hass[1366]: #033[32m2017-11-02 17:08:49 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service_data=entity_id=light.aquarium_4_1, domain=light, service=turn_off, service_call_id=1970958224-422>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:49 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1970958224-422>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:49 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state script.aqua_to_night=off; can_cancel=True, friendly_name=aqua_to_night, last_triggered=2017-11-02T18:08:49.352941+01:00 @ 2017-11-02T18:08:49.370529+01:00>, entity_id=script.aqua_to_night, old_state=<state script.aqua_to_night=on; can_cancel=True, friendly_name=aqua_to_night, last_triggered=2017-11-02T18:08:42.378463+01:00, last_action=call service @ 2017-11-02T18:08:42.436591+01:00>>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:49 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state group.all_scripts=off; entity_id=('script.aqua_to_day', 'script.aqua_to_night', 'script.choose_tuner_slamfm', 'script.onkyo_off', 'script.onkyo_on', 'script.police_lights', 'script.tuner_slamfm', 'script.tuner_sublime'), friendly_name=all scripts, auto=True, hidden=True, assumed_state=False, order=6 @ 2017-11-02T18:08:42.443423+01:00>>#033[0m
hass[1366]: #033[32m2017-11-02 17:08:55 INFO (MainThread) ```

[Richard van der Plas]

some add-on
finally able to split my log files this one keeps popping up every few seconds, could that be interfering with other messages ?

Nov  3 14:48:07 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:48:17 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:48:27 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:48:37 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:48:47 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:48:57 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:49:07 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:49:17 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:49:27 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:49:37 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:49:47 raspberrypi mysgw: Client 0: 0;255;3;0;2;
Nov  3 14:49:57 raspberrypi mysgw: Client 0: 0;255;3;0;2;

[martinhjelmare]

The NACKs suggests the radio communication is not always working. Make sure you follow the radio setup best practices. See here for troubleshooting flow chart:
https://forum.mysensors.org/topic/666/debug-faq-and-how-ask-for-help

0;255;3;0;2;

This is just the controller asking the gateway for version, as a way to check the ethernet connection is still alive.

[Richard van der Plas]

Ok checked everything, added capacitors to my radio's and even a small antenna as told in: https://hackaday.com/2015/08/15/hacking-a-nrf24l01-radio-for-longer-range/
but the range seems to be the issue, the sensors who are 3-4 meters distance of the device work, but one 7 meters & 2 walls away have no connection.
Looking up some info on the wireless modules they should work 30+ meters, so im completely confused
It really seems to be a distance issue, moved the pi gateway to the same floor as the sensors are on, and the number of nacks reduces big time.
But i still havent find a way to let MySensors gateway set a retry numer (as well as the sensors).

[martinhjelmare]

There's already a built in low level mechanism for three resends, if I remember correctly. I'd suggest to try to make the radio communication more stable than to try to add resend of messages on a high level. Try to change power source for more and more stable power. Try to change radio for another sample.

How are you powering the gateway?

You can also play around with the power setting of the radio, low-max. Both higher and lower setting can make a difference.

[Richard van der Plas]

@martinhjelmare changed the antennas again for another design, and send the level to max, and today it seems to be stable.
Proof is in the pudding, he needs to control my aqarium lights twice a day. that's the one thats missing.
al my sensors are power with power regulators, so that should be good.
if the issue is persisent, i will try further.