MySensors won't send notifications to nodes in SmartSleep

FlyingSaucrDude · February 19, 2022, 7:52am

I have a MySensors Arduino node that I want to be able to (a) save battery power by sleeping, and (b) be able to periodically send an updated configuration to. I’ve been trying to use SmartSleep and sending notifications via the notify.mysensors service, but the messages are never sent. If I never SmartSleep the node (and instead replace the call to smartSleep with delay) the messages are sent (and received fine).

Here’s the minimum code for my Arduino node:

#define MY_RADIO_RFM69
#define MY_DEBUG
#define MY_RFM69_SPI_CS SS
#define MY_RFM69_FREQUENCY RFM69_915MHZ
#define MY_RFM69_NEW_DRIVER

#include <MySensors.h>

#define ECHO_ID 1

MyMessage echoMsg(ECHO_ID, V_TEXT);

void presentation() {
  sendSketchInfo("sketch", "1.0");
  present(ECHO_ID, S_INFO, "echo");
}

void loop() {
  Serial.println("Sending a message");
  send(echoMsg.set("foo"));
  Serial.println("sleep/delay for 30 seconds");
  smartSleep(30000);
  //delay(30000);
  Serial.println("done with loop");
}

void receive(const MyMessage &message) {
  Serial.println("received a message");
}

If I run that, wait until it says “sleep/delay for 30 seconds”, and then try to call

service: notify.mysensors
data:
  message: bar
  target: echo

nothing happens. The Home Assistant log shows that it’s using the web_api to call the service, but that’s it.

Here’s the gateway debug log:

Feb 18 23:41:09 INFO  Starting gateway...
Feb 18 23:41:09 INFO  Protocol version - 2.4.0-alpha
Feb 18 23:41:09 DEBUG MCO:BGN:INIT GW,CP=RPNGL---,FQ=NA,REL=0,VER=2.4.0-alpha
Feb 18 23:41:09 DEBUG TSF:LRT:OK
Feb 18 23:41:09 DEBUG TSM:INIT
Feb 18 23:41:09 DEBUG TSF:WUR:MS=0
Feb 18 23:41:09 DEBUG TSM:INIT:TSP OK
Feb 18 23:41:09 DEBUG TSM:INIT:GW MODE
Feb 18 23:41:09 DEBUG TSM:READY:ID=0,PAR=0,DIS=0
Feb 18 23:41:09 DEBUG MCO:REG:NOT NEEDED
Feb 18 23:41:09 DEBUG Listening for connections on ���:5003
Feb 18 23:41:09 DEBUG MCO:BGN:STP
Feb 18 23:41:09 DEBUG MCO:BGN:INIT OK,TSP=1
Feb 18 23:41:09 DEBUG TSM:READY:NWD REQ
Feb 18 23:41:09 DEBUG ?TSF:MSG:SEND,0-0-255-255,s=255,c=3,t=20,pt=0,l=0,sg=0,ft=0,st=OK:
Feb 18 23:41:47 DEBUG New connection from 192.168.0.189
Feb 18 23:41:47 DEBUG GWT:TSA:C=0,CONNECTED
Feb 18 23:41:47 DEBUG Ethernet client disconnected.
Feb 18 23:41:47 DEBUG New connection from 192.168.0.189
Feb 18 23:41:47 DEBUG GWT:TSA:C=0,CONNECTED
Feb 18 23:41:47 DEBUG GWT:RFC:C=0,MSG=255;255;3;0;20;
Feb 18 23:41:47 DEBUG ?TSF:MSG:SEND,0-0-255-255,s=255,c=3,t=20,pt=1,l=1,sg=0,ft=0,st=OK:0
Feb 18 23:41:57 DEBUG GWT:RFC:C=0,MSG=0;255;3;0;2;
Feb 18 23:42:03 DEBUG TSF:MSG:READ,79-79-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
Feb 18 23:42:03 DEBUG TSF:MSG:BC
Feb 18 23:42:03 DEBUG TSF:MSG:FPAR REQ,ID=79
Feb 18 23:42:03 DEBUG TSF:PNG:SEND,TO=0
Feb 18 23:42:03 DEBUG TSF:CKU:OK
Feb 18 23:42:03 DEBUG TSF:MSG:GWL OK
Feb 18 23:42:04 DEBUG TSF:MSG:SEND,0-0-79-79,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0
Feb 18 23:42:05 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
Feb 18 23:42:05 DEBUG TSF:MSG:PINGED,ID=79,HP=1
Feb 18 23:42:05 DEBUG TSF:MSG:SEND,0-0-79-79,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=OK:1
Feb 18 23:42:05 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
Feb 18 23:42:05 DEBUG TSF:MSG:SEND,0-0-79-79,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
Feb 18 23:42:05 DEBUG TSF:MSG:READ,79-79-0,s=255,c=0,t=17,pt=0,l=5,sg=0:2.3.2
Feb 18 23:42:05 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
Feb 18 23:42:05 DEBUG GWT:RFC:C=0,MSG=79;255;3;0;6;I
Feb 18 23:42:05 DEBUG TSF:MSG:SEND,0-0-79-79,s=255,c=3,t=6,pt=0,l=1,sg=0,ft=0,st=OK:I
Feb 18 23:42:05 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=11,pt=0,l=6,sg=0:sketch
Feb 18 23:42:05 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.0
Feb 18 23:42:05 DEBUG TSF:MSG:READ,79-79-0,s=1,c=0,t=36,pt=0,l=4,sg=0:echo
Feb 18 23:42:05 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=26,pt=1,l=1,sg=0:2
Feb 18 23:42:06 DEBUG TSF:MSG:SEND,0-0-79-79,s=255,c=3,t=27,pt=1,l=1,sg=0,ft=0,st=OK:1
Feb 18 23:42:06 DEBUG TSF:MSG:READ,79-79-0,s=1,c=1,t=47,pt=0,l=3,sg=0:foo
Feb 18 23:42:06 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=32,pt=5,l=4,sg=0:500
Feb 18 23:42:07 DEBUG GWT:RFC:C=0,MSG=0;255;3;0;2;
Feb 18 23:42:17 DEBUG GWT:RFC:C=0,MSG=0;255;3;0;2;
Feb 18 23:42:27 DEBUG GWT:RFC:C=0,MSG=0;255;3;0;2;
Feb 18 23:42:37 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=33,pt=5,l=4,sg=0:30000
Feb 18 23:42:37 DEBUG TSF:MSG:READ,79-79-0,s=1,c=1,t=47,pt=0,l=3,sg=0:foo
Feb 18 23:42:37 DEBUG TSF:MSG:READ,79-79-0,s=255,c=3,t=32,pt=5,l=4,sg=0:500
Feb 18 23:42:38 DEBUG GWT:RFC:C=0,MSG=0;255;3;0;2;

Here’s the debug log from Home Assistant:

2022-02-18 23:41:47 INFO (MainThread) [mysensors.gateway_tcp] Trying to connect to ('192.168.0.175', 5003)
2022-02-18 23:41:47 INFO (MainThread) [mysensors.transport] Connected to <_SelectorSocketTransport fd=16 read=idle write=<idle, bufsize=0>>
2022-02-18 23:41:47 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;14;Gateway startup complete.
2022-02-18 23:41:47 INFO (MainThread) [mysensors.handler] n:0 c:255 t:3 s:14 p:Gateway startup complete.
2022-02-18 23:41:47 DEBUG (MainThread) [homeassistant.components.mysensors.gateway] Node update: node 0 child 255
2022-02-18 23:41:47 DEBUG (MainThread) [mysensors.transport] Sending 255;255;3;0;20;
2022-02-18 23:41:47 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;0;0;18;2.4.0-alpha
2022-02-18 23:41:47 DEBUG (MainThread) [homeassistant.components.mysensors.gateway] Node update: node 0 child 255
2022-02-18 23:41:57 DEBUG (SyncWorker_0) [mysensors.persistence] Saving sensors to persistence file /config/mysensors_a397ab33acaa0f0fb662a4081d3e46de.json
2022-02-18 23:41:57 DEBUG (MainThread) [mysensors.transport] Sending 0;255;3;0;2;
2022-02-18 23:41:57 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;2;2.4.0-alpha
2022-02-18 23:42:05 DEBUG (MainThread) [mysensors.transport] Receiving 79;255;0;0;17;2.3.2
2022-02-18 23:42:05 DEBUG (MainThread) [homeassistant.components.mysensors.gateway] Node update: node 79 child 255
2022-02-18 23:42:05 DEBUG (MainThread) [mysensors.transport] Receiving 79;255;3;0;6;0
2022-02-18 23:42:05 DEBUG (MainThread) [mysensors.transport] Sending 79;255;3;0;6;I
2022-02-18 23:42:05 DEBUG (MainThread) [mysensors.transport] Receiving 79;255;3;0;11;sketch
2022-02-18 23:42:05 DEBUG (MainThread) [homeassistant.components.mysensors.gateway] Node update: node 79 child 255
2022-02-18 23:42:05 DEBUG (MainThread) [mysensors.transport] Receiving 79;255;3;0;12;1.0
2022-02-18 23:42:05 DEBUG (MainThread) [homeassistant.components.mysensors.gateway] Node update: node 79 child 255
2022-02-18 23:42:05 DEBUG (MainThread) [mysensors.transport] Receiving 79;1;0;0;36;echo
2022-02-18 23:42:05 DEBUG (MainThread) [homeassistant.components.mysensors.gateway] Node update: node 79 child 1
2022-02-18 23:42:06 DEBUG (MainThread) [mysensors.transport] Receiving 79;1;1;0;47;foo
2022-02-18 23:42:06 DEBUG (MainThread) [homeassistant.components.mysensors.gateway] Node update: node 79 child 1
2022-02-18 23:42:06 DEBUG (MainThread) [homeassistant.components.mysensors.helpers] Discovering platform notify with devIds: [('a397ab33acaa0f0fb662a4081d3e46de', 79, 1, 47)]
2022-02-18 23:42:06 DEBUG (MainThread) [homeassistant.components.mysensors.helpers] Discovering platform sensor with devIds: [('a397ab33acaa0f0fb662a4081d3e46de', 79, 1, 47)]
2022-02-18 23:42:06 INFO (MainThread) [homeassistant.components.mysensors] Adding new devices: [<Entity echo>]
2022-02-18 23:42:06 INFO (MainThread) [homeassistant.components.notify] Setting up notify.mysensors
2022-02-18 23:42:06 INFO (MainThread) [homeassistant.components.mysensors] Adding new devices: [<MySensorsNotificationDevice echo>]
2022-02-18 23:42:06 DEBUG (MainThread) [homeassistant.components.mysensors.device] Entity update: echo: value_type 47, value = foo
2022-02-18 23:42:06 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new sensor.mysensors entity: sensor.echo
2022-02-18 23:42:06 DEBUG (MainThread) [mysensors.transport] Receiving 79;255;3;0;32;500
2022-02-18 23:42:07 DEBUG (SyncWorker_5) [mysensors.persistence] Saving sensors to persistence file /config/mysensors_a397ab33acaa0f0fb662a4081d3e46de.json
2022-02-18 23:42:07 DEBUG (MainThread) [mysensors.transport] Sending 0;255;3;0;2;
2022-02-18 23:42:07 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;2;2.4.0-alpha
2022-02-18 23:42:17 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script
2022-02-18 23:42:17 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service
2022-02-18 23:42:17 DEBUG (MainThread) [mysensors.transport] Sending 0;255;3;0;2;
2022-02-18 23:42:17 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;2;2.4.0-alpha
2022-02-18 23:42:27 DEBUG (MainThread) [mysensors.transport] Sending 0;255;3;0;2;
2022-02-18 23:42:27 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;2;2.4.0-alpha
2022-02-18 23:42:37 DEBUG (MainThread) [mysensors.transport] Receiving 79;255;3;0;33;30000
2022-02-18 23:42:37 DEBUG (MainThread) [mysensors.transport] Receiving 79;1;1;0;47;foo
2022-02-18 23:42:37 DEBUG (MainThread) [homeassistant.components.mysensors.gateway] Node update: node 79 child 1
2022-02-18 23:42:37 DEBUG (MainThread) [mysensors.transport] Receiving 79;255;3;0;32;500
2022-02-18 23:42:37 DEBUG (MainThread) [homeassistant.components.mysensors.device] Entity update: echo: value_type 47, value = foo
2022-02-18 23:42:38 DEBUG (MainThread) [mysensors.transport] Sending 0;255;3;0;2;
2022-02-18 23:42:38 DEBUG (MainThread) [mysensors.transport] Receiving 0;255;3;0;2;2.4.0-alpha

And here’s the debug log from the Arduino:

16 MCO:BGN:INIT NODE,CP=RPNNA---,FQ=16,REL=255,VER=2.3.2
26 TSM:INIT
28 TSF:WUR:MS=0
29 TSM:INIT:TSP OK
31 TSF:SID:OK,ID=79
33 TSM:FPAR
38 ?TSF:MSG:SEND,79-79-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
1035 TSF:MSG:READ,0-0-79,s=255,c=3,t=8,pt=1,l=1,sg=0:0
1040 TSF:MSG:FPAR OK,ID=0,D=1
2048 TSM:FPAR:OK
2049 TSM:ID
2050 TSM:ID:OK
2052 TSM:UPL
2065 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2289 TSF:MSG:READ,0-0-79,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2294 TSF:MSG:PONG RECV,HP=1
2296 TSM:UPL:OK
2298 TSM:READY:ID=79,PAR=0,DIS=1
2320 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
2537 TSF:MSG:READ,0-0-79,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
2557 TSF:MSG:SEND,79-79-0-0,s=255,c=0,t=17,pt=0,l=5,sg=0,ft=0,st=OK:2.3.2
2578 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
2609 TSF:MSG:READ,0-0-79,s=255,c=3,t=6,pt=0,l=1,sg=0:I
2630 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=11,pt=0,l=6,sg=0,ft=0,st=OK:sketch
2652 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.0
2674 TSF:MSG:SEND,79-79-0-0,s=1,c=0,t=36,pt=0,l=4,sg=0,ft=0,st=OK:echo
2681 MCO:REG:REQ
2698 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
3120 TSF:MSG:READ,0-0-79,s=255,c=3,t=27,pt=1,l=1,sg=0:1
3125 MCO:PIM:NODE REG=1
3127 MCO:BGN:INIT OK,TSP=1
Sending a message
3140 TSF:MSG:SEND,79-79-0-0,s=1,c=1,t=47,pt=0,l=3,sg=0,ft=0,st=OK:foo
sleep/delay for 30 seconds
3147 MCO:SLP:MS=30000,SMS=1,I1=255,M1=255,I2=255,M2=255
3172 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=32,pt=5,l=4,sg=0,ft=0,st=OK:500
3678 TSF:TDI:TSL
3679 MCO:SLP:WUP=-1
3681 TSF:TRI:TSB
3703 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=33,pt=5,l=4,sg=0,ft=0,st=OK:30000
done with loop
Sending a message
3726 TSF:MSG:SEND,79-79-0-0,s=1,c=1,t=47,pt=0,l=3,sg=0,ft=0,st=OK:foo
sleep/delay for 30 seconds
3733 MCO:SLP:MS=30000,SMS=1,I1=255,M1=255,I2=255,M2=255
3760 TSF:MSG:SEND,79-79-0-0,s=255,c=3,t=32,pt=5,l=4,sg=0,ft=0,st=OK:500
4267 TSF:TDI:TSL

When I set up the MySensors integration in Home Assistant, I set the version to 2.3.2 to match the version being used on the Arduino.

Am I doing something wrong? Should this work?

nschurando · October 12, 2022, 12:17pm

Hey Jeremy, I seem to be experiencing the same issue, did you ever find out more? Regards, Nicolas

FlyingSaucrDude · October 14, 2022, 12:49am

Nope, I never figured out a resolution. I ended up using smart sleep and just never communicating back from Home Assistant to the MySensors Arduino node.