NACK after Core initialized, transport status 1

Tico

Hi There,

I have setup a MQTT gateway with ESP8266 and RFM69HCW 868Mhz. Then I have setup a node with 328P pro mini, with RFM69HCW 868Mhz.

After the node is successfully initialized with all radio communications successfully done, I have a NACK. Please see logs from the node:

215 MCO:BGN:INIT REPEATER,CP=RPNRA---,FQ=8,REL=0,VER=2.4.0-alpha
350 MCO:BGN:BFR
366 NM:INIT:VER=1.9-dev
393 NM:INIT:INO=NodeManagerRelay v1.0
432 NM:INIT:LIB VER=2.4.0-alpha CP=RPNRA--- 
479 NM:BFR:INIT
495 TSM:INIT
509 TSF:WUR:MS=0
528 TSM:INIT:TSP OK
550 TSF:SID:OK,ID=1
571 TSM:FPAR
589 ?TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
1742 TSF:MSG:READ,0-0-1,s=255,c=3,t=8,pt=1,l=1,sg=0:0
1800 TSF:MSG:FPAR OK,ID=0,D=1
2664 TSM:FPAR:OK
2680 TSM:ID
2695 TSM:ID:OK
2709 TSM:UPL
2783 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
3586 TSF:MSG:READ,0-0-1,s=255,c=3,t=25,pt=1,l=1,sg=0:1
3643 TSF:MSG:PONG RECV,HP=1
3674 TSM:UPL:OK
3690 TSM:READY:ID=1,PAR=0,DIS=1
3782 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
4550 TSF:MSG:READ,0-0-1,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
4679 TSF:MSG:SEND,1-1-0-0,s=255,c=0,t=18,pt=0,l=11,sg=0,ft=0,st=OK:2.4.0-alpha
5320 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
6230 TSF:MSG:READ,0-0-1,s=255,c=3,t=6,pt=0,l=1,sg=0:M
6285 NM:BFR:OK
6363 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=11,pt=0,l=16,sg=0,ft=0,st=OK:NodeManagerRelay
7010 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.0
7081 NM:PRES:RELAY(1) p=3 t=2
7671 TSF:MSG:SEND,1-1-0-0,s=1,c=0,t=3,pt=0,l=5,sg=0,ft=0,st=OK:RELAY
7743 MCO:REG:REQ
8318 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
8591 TSF:MSG:READ,0-0-1,s=255,c=3,t=27,pt=1,l=1,sg=0:1
8648 MCO:PIM:NODE REG=1
8673 MCO:BGN:STP
8691 NM:STP:ID=1 M=1
8714 NM:LOOP:RELAY(1):SET t=2 v=0
8820 NM:STP:HW V=3319 F=8 M=1203
8855 MCO:BGN:INIT OK,TSP=1
19894 !TSF:MSG:SEND,1-1-0-0,s=1,c=1,t=2,pt=4,l=4,sg=0,ft=0,st=NACK:0

Please could someone drive me in sorting out this issue ?

thx and reg

Eric

mfalkvidd

@Tico what does the gateway log say?

The gteway log will show if the message did not reach the gateway, or the acknowledgement did not reach the node.

Tico

Thanks a lot @mfalkvidd for your support.
Please find following the logs from the node with MY_DEBUG_VERBOSE_RFM69 and timestamp:

18:06:02.305 -> 215 MCO:BGN:INIT REPEATER,CP=RPNRA---,FQ=8,REL=0,VER=2.4.0-alpha
18:06:02.366 -> 350 MCO:BGN:BFR
18:06:02.366 -> 366 NM:INIT:VER=1.9-dev
18:06:02.399 -> 393 NM:INIT:INO=NodeManagerRelay v1.0
18:06:02.432 -> 432 NM:INIT:LIB VER=2.4.0-alpha CP=RPNRA--- 
18:06:02.465 -> 479 NM:BFR:INIT
18:06:02.497 -> 495 TSM:INIT
18:06:02.497 -> 509 TSF:WUR:MS=0
18:06:02.529 -> 528 RFM69:INIT
18:06:02.529 -> 544 RFM69:INIT:PIN,CS=10,IQP=2,IQN=0
18:06:02.593 -> 583 RFM69:PTX:LEVEL=5 dBm
18:06:02.593 -> 610 TSM:INIT:TSP OK
18:06:02.625 -> 632 TSF:SID:OK,ID=1
18:06:02.657 -> 653 TSM:FPAR
18:06:02.657 -> 667 RFM69:SWR:SEND,TO=255,SEQ=0,RETRY=0
18:06:02.721 -> 710 RFM69:CSMA:RSSI=-107
18:06:02.721 -> 739 ?TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
18:06:03.466 -> 1452 RFM69:SAC:SEND ACK,TO=0,RSSI=-31
18:06:03.498 -> 1492 RFM69:CSMA:RSSI=-107
18:06:03.530 -> 1523 TSF:MSG:READ,0-0-1,s=255,c=3,t=8,pt=1,l=1,sg=0:0
18:06:03.595 -> 1579 TSF:MSG:FPAR OK,ID=0,D=1
18:06:04.827 -> 2816 TSM:FPAR:OK
18:06:04.827 -> 2832 TSM:ID
18:06:04.859 -> 2846 TSM:ID:OK
18:06:04.859 -> 2861 TSM:UPL
18:06:04.892 -> 2875 RFM69:SWR:SEND,TO=0,SEQ=2,RETRY=0
18:06:04.924 -> 2918 RFM69:CSMA:RSSI=-105
18:06:05.084 -> 3072 RFM69:SWR:ACK,FROM=0,SEQ=3,RSSI=-36
18:06:05.118 -> 3115 RFM69:ATC:ADJ TXL,cR=-36,tR=-78..-82,TXL=5
18:06:05.182 -> 3164 RFM69:PTX:LEVEL=4 dBm
18:06:05.215 -> 3192 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
18:06:05.538 -> 3534 RFM69:SAC:SEND ACK,TO=0,RSSI=-29
18:06:05.571 -> 3575 RFM69:CSMA:RSSI=-107
18:06:05.603 -> 3606 TSF:MSG:READ,0-0-1,s=255,c=3,t=25,pt=1,l=1,sg=0:1
18:06:05.667 -> 3663 TSF:MSG:PONG RECV,HP=1
18:06:05.699 -> 3692 TSM:UPL:OK
18:06:05.699 -> 3708 TSM:READY:ID=1,PAR=0,DIS=1
18:06:05.763 -> 3743 RFM69:SWR:SEND,TO=0,SEQ=4,RETRY=0
18:06:05.795 -> 3784 RFM69:CSMA:RSSI=-105
18:06:05.956 -> 3938 RFM69:SWR:ACK,FROM=0,SEQ=5,RSSI=-39
18:06:05.989 -> 3981 RFM69:ATC:ADJ TXL,cR=-39,tR=-78..-82,TXL=4
18:06:06.055 -> 4032 RFM69:PTX:LEVEL=3 dBm
18:06:06.055 -> 4061 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
18:06:06.377 -> 4366 RFM69:SAC:SEND ACK,TO=0,RSSI=-32
18:06:06.410 -> 4409 RFM69:CSMA:RSSI=-104
18:06:06.442 -> 4438 TSF:MSG:READ,0-0-1,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
18:06:06.507 -> 4499 RFM69:SWR:SEND,TO=0,SEQ=6,RETRY=0
18:06:06.540 -> 4540 RFM69:CSMA:RSSI=-103
18:06:06.701 -> 4696 RFM69:SWR:ACK,FROM=0,SEQ=7,RSSI=-39
18:06:06.765 -> 4739 RFM69:ATC:ADJ TXL,cR=-39,tR=-78..-82,TXL=3
18:06:06.797 -> 4790 RFM69:PTX:LEVEL=2 dBm
18:06:06.830 -> 4818 TSF:MSG:SEND,1-1-0-0,s=255,c=0,t=18,pt=0,l=11,sg=0,ft=0,st=OK:2.4.0-alpha
18:06:06.927 -> 4900 RFM69:SWR:SEND,TO=0,SEQ=7,RETRY=0
18:06:06.959 -> 4943 RFM69:CSMA:RSSI=-106
18:06:07.119 -> 5097 RFM69:SWR:ACK,FROM=0,SEQ=8,RSSI=-36
18:06:07.150 -> 5140 RFM69:ATC:ADJ TXL,cR=-36,tR=-78..-82,TXL=2
18:06:07.215 -> 5189 RFM69:PTX:LEVEL=1 dBm
18:06:07.247 -> 5218 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
18:06:09.281 -> 7288 NM:BFR:OK
18:06:09.313 -> 7303 RFM69:SWR:SEND,TO=0,SEQ=8,RETRY=0
18:06:09.346 -> 7346 RFM69:CSMA:RSSI=-110
18:06:09.507 -> 7501 RFM69:SWR:ACK,FROM=0,SEQ=9,RSSI=-36
18:06:09.573 -> 7544 RFM69:ATC:ADJ TXL,cR=-36,tR=-78..-82,TXL=1
18:06:09.605 -> 7596 RFM69:PTX:LEVEL=0 dBm
18:06:09.637 -> 7622 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=11,pt=0,l=16,sg=0,ft=0,st=OK:NodeManagerRelay
18:06:09.733 -> 7710 RFM69:SWR:SEND,TO=0,SEQ=9,RETRY=0
18:06:09.765 -> 7753 RFM69:CSMA:RSSI=-106
18:06:09.925 -> 7907 RFM69:SWR:ACK,FROM=0,SEQ=10,RSSI=-37
18:06:09.957 -> 7952 RFM69:ATC:ADJ TXL,cR=-37,tR=-78..-82,TXL=0
18:06:10.021 -> 8001 RFM69:PTX:LEVEL=-1 dBm
18:06:10.053 -> 8032 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.0
18:06:10.118 -> 8103 NM:PRES:RELAY(1) p=3 t=2
18:06:10.150 -> 8136 RFM69:SWR:SEND,TO=0,SEQ=10,RETRY=0
18:06:10.182 -> 8179 RFM69:CSMA:RSSI=-108
18:06:10.407 -> 8388 RFM69:SWR:ACK,FROM=0,SEQ=11,RSSI=-38
18:06:10.439 -> 8431 RFM69:ATC:ADJ TXL,cR=-38,tR=-78..-82,TXL=-1
18:06:10.503 -> 8482 RFM69:PTX:LEVEL=-2 dBm
18:06:10.536 -> 8513 TSF:MSG:SEND,1-1-0-0,s=1,c=0,t=3,pt=0,l=5,sg=0,ft=0,st=OK:RELAY
18:06:10.600 -> 8585 MCO:REG:REQ
18:06:10.632 -> 8603 RFM69:SWR:SEND,TO=0,SEQ=11,RETRY=0
18:06:10.664 -> 8646 RFM69:CSMA:RSSI=-108
18:06:10.890 -> 8855 RFM69:SWR:ACK,FROM=0,SEQ=12,RSSI=-39
18:06:10.922 -> 8900 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
18:06:11.308 -> 9287 RFM69:SAC:SEND ACK,TO=0,RSSI=-31
18:06:11.340 -> 9328 RFM69:CSMA:RSSI=-104
18:06:11.372 -> 9359 TSF:MSG:READ,0-0-1,s=255,c=3,t=27,pt=1,l=1,sg=0:1
18:06:11.436 -> 9416 MCO:PIM:NODE REG=1
18:06:11.468 -> 9443 MCO:BGN:STP
18:06:11.468 -> 9459 NM:STP:ID=1 M=1
18:06:11.501 -> 9482 NM:LOOP:RELAY(1):SET t=2 v=0
18:06:12.146 -> 9592 NM:STP:HW V=3319 F=8 M=1204
18:06:12.177 -> 9627 MCO:BGN:INIT OK,TSP=1
18:06:12.210 -> 9656 RFM69:SWR:SEND,TO=0,SEQ=13,RETRY=0
18:06:12.242 -> 9699 RFM69:CSMA:RSSI=-107
18:06:14.510 -> 11927 !RFM69:SWR:NACK
18:06:14.510 -> 11950 RFM69:SWR:SEND,TO=0,SEQ=14,RETRY=1
18:06:14.575 -> 11993 RFM69:CSMA:RSSI=-107
18:06:16.812 -> 14225 !RFM69:SWR:NACK
18:06:16.812 -> 14247 RFM69:SWR:SEND,TO=0,SEQ=14,RETRY=2
18:06:16.877 -> 14290 RFM69:CSMA:RSSI=-107
18:06:19.109 -> 16523 !RFM69:SWR:NACK
18:06:19.109 -> 16545 RFM69:SWR:SEND,TO=0,SEQ=14,RETRY=3
18:06:19.173 -> 16588 RFM69:CSMA:RSSI=-108
18:06:21.403 -> 18821 !RFM69:SWR:NACK
18:06:21.436 -> 18843 RFM69:SWR:SEND,TO=0,SEQ=14,RETRY=4
18:06:21.469 -> 18888 RFM69:CSMA:RSSI=-104
18:06:23.702 -> 21118 !RFM69:SWR:NACK
18:06:23.734 -> 21141 !TSF:MSG:SEND,1-1-0-0,s=1,c=1,t=2,pt=4,l=4,sg=0,ft=0,st=NACK:0

And from the gateway, with MY_DEBUG_VERBOSE_RFM69 and timestamp:

18:06:02.753 -> 46378 TSF:MSG:READ,1-1-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
18:06:02.818 -> 46436 TSF:MSG:BC
18:06:02.850 -> 46454 TSF:MSG:FPAR REQ,ID=1
18:06:02.883 -> 46483 TSF:PNG:SEND,TO=0
18:06:02.883 -> 46508 TSF:CKU:OK
18:06:02.916 -> 46526 TSF:MSG:GWL OK
18:06:03.401 -> 47016 RFM69:SWR:SEND,TO=1,SEQ=1,RETRY=0
18:06:03.433 -> 47059 RFM69:CSMA:RSSI=-103
18:06:03.562 -> 47162 RFM69:SWR:ACK,FROM=1,SEQ=2,RSSI=-31
18:06:03.594 -> 47206 TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0
18:06:05.020 -> 48640 RFM69:SAC:SEND ACK,TO=1,RSSI=-36
18:06:05.052 -> 48682 RFM69:CSMA:RSSI=-106
18:06:05.118 -> 48713 TSF:MSG:READ,1-1-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
18:06:05.150 -> 48772 TSF:MSG:PINGED,ID=1,HP=1
18:06:05.214 -> 48809 RFM69:SWR:SEND,TO=1,SEQ=3,RETRY=0
18:06:05.247 -> 48852 RFM69:CSMA:RSSI=-105
18:06:05.473 -> 49080 !RFM69:SWR:NACK
18:06:05.473 -> 49103 RFM69:SWR:SEND,TO=1,SEQ=4,RETRY=1
18:06:05.537 -> 49145 RFM69:CSMA:RSSI=-104
18:06:05.633 -> 49248 RFM69:SWR:ACK,FROM=1,SEQ=4,RSSI=-29
18:06:05.665 -> 49292 TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=OK:1
18:06:05.890 -> 49510 RFM69:SAC:SEND ACK,TO=1,RSSI=-39
18:06:05.954 -> 49552 RFM69:CSMA:RSSI=-106
18:06:05.986 -> 49582 TSF:MSG:READ,1-1-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
18:06:06.018 -> 49644 RFM69:SWR:SEND,TO=1,SEQ=5,RETRY=0
18:06:06.082 -> 49687 RFM69:CSMA:RSSI=-96
18:06:06.311 -> 49914 !RFM69:SWR:NACK
18:06:06.311 -> 49937 RFM69:SWR:SEND,TO=1,SEQ=6,RETRY=1
18:06:06.376 -> 49979 RFM69:CSMA:RSSI=-107
18:06:06.472 -> 50083 RFM69:SWR:ACK,FROM=1,SEQ=6,RSSI=-32
18:06:06.504 -> 50126 TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
18:06:06.665 -> 50268 RFM69:SAC:SEND ACK,TO=1,RSSI=-39
18:06:06.697 -> 50310 RFM69:CSMA:RSSI=-104
18:06:06.730 -> 50341 TSF:MSG:READ,1-1-0,s=255,c=0,t=18,pt=0,l=11,sg=0:2.4.0-alpha
18:06:06.794 -> 50413 GWT:TPS:TOPIC=esp8266-gw/out/1/255/0/0/18,MSG SENT
18:06:07.050 -> 50669 RFM69:SAC:SEND ACK,TO=1,RSSI=-36
18:06:07.082 -> 50711 RFM69:CSMA:RSSI=-106
18:06:07.145 -> 50742 TSF:MSG:READ,1-1-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
18:06:07.178 -> 50800 GWT:TPS:TOPIC=esp8266-gw/out/1/255/3/0/6,MSG SENT
18:06:09.475 -> 53079 RFM69:SAC:SEND ACK,TO=1,RSSI=-36
18:06:09.507 -> 53121 RFM69:CSMA:RSSI=-105
18:06:09.539 -> 53151 TSF:MSG:READ,1-1-0,s=255,c=3,t=11,pt=0,l=16,sg=0:NodeManagerRelay
18:06:09.604 -> 53226 GWT:TPS:TOPIC=esp8266-gw/out/1/255/3/0/11,MSG SENT
18:06:09.859 -> 53485 RFM69:SAC:SEND ACK,TO=1,RSSI=-37
18:06:09.925 -> 53527 RFM69:CSMA:RSSI=-105
18:06:09.957 -> 53558 TSF:MSG:READ,1-1-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.0
18:06:09.989 -> 53618 GWT:TPS:TOPIC=esp8266-gw/out/1/255/3/0/12,MSG SENT
18:06:10.311 -> 53912 RFM69:SAC:SEND ACK,TO=1,RSSI=-38
18:06:10.343 -> 53954 RFM69:CSMA:RSSI=-79
18:06:10.343 -> 53981 RFM69:CSMA:RSSI=-85
18:06:10.375 -> 54008 RFM69:CSMA:RSSI=-106
18:06:10.439 -> 54039 TSF:MSG:READ,1-1-0,s=1,c=0,t=3,pt=0,l=5,sg=0:RELAY
18:06:10.470 -> 54099 GWT:TPS:TOPIC=esp8266-gw/out/1/1/0/0/3,MSG SENT
18:06:10.761 -> 54379 RFM69:SAC:SEND ACK,TO=1,RSSI=-39
18:06:10.825 -> 54423 RFM69:CSMA:RSSI=-71
18:06:10.825 -> 54450 RFM69:CSMA:RSSI=-85
18:06:10.857 -> 54477 RFM69:CSMA:RSSI=-104
18:06:10.890 -> 54508 TSF:MSG:READ,1-1-0,s=255,c=3,t=26,pt=1,l=1,sg=0:2
18:06:10.954 -> 54572 RFM69:SWR:SEND,TO=1,SEQ=12,RETRY=0
18:06:11.018 -> 54615 RFM69:CSMA:RSSI=-105
18:06:11.244 -> 54844 !RFM69:SWR:NACK
18:06:11.244 -> 54867 RFM69:SWR:SEND,TO=1,SEQ=13,RETRY=1
18:06:11.308 -> 54910 RFM69:CSMA:RSSI=-98
18:06:11.404 -> 55013 RFM69:SWR:ACK,FROM=1,SEQ=13,RSSI=-31
18:06:11.436 -> 55058 TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=27,pt=1,l=1,sg=0,ft=0,st=OK:1
18:06:12.373 -> 55978 RFM69:SAC:SEND ACK,TO=1,RSSI=-44
18:06:12.404 -> 56020 RFM69:CSMA:RSSI=-42
18:06:12.404 -> 56047 RFM69:CSMA:RSSI=-42
18:06:12.437 -> 56074 RFM69:CSMA:RSSI=-42
18:06:12.469 -> 56101 RFM69:CSMA:RSSI=-42
18:06:12.500 -> 56128 RFM69:CSMA:RSSI=-42
18:06:12.533 -> 56155 RFM69:CSMA:RSSI=-42
18:06:12.533 -> 56182 RFM69:CSMA:RSSI=-42
18:06:12.565 -> 56210 RFM69:CSMA:RSSI=-42
18:06:12.598 -> 56237 RFM69:CSMA:RSSI=-42
18:06:12.630 -> 56264 RFM69:CSMA:RSSI=-42
18:06:12.662 -> 56291 RFM69:CSMA:RSSI=-42
18:06:12.662 -> 56318 RFM69:CSMA:RSSI=-42
18:06:12.695 -> 56345 RFM69:CSMA:RSSI=-42
18:06:12.761 -> 56372 RFM69:CSMA:RSSI=-42
18:06:12.793 -> 56400 RFM69:CSMA:RSSI=-42
18:06:12.825 -> 56427 RFM69:CSMA:RSSI=-42
18:06:12.857 -> 56454 RFM69:CSMA:RSSI=-42
18:06:12.857 -> 56481 RFM69:CSMA:RSSI=-42
18:06:12.890 -> 56508 RFM69:CSMA:RSSI=-42
18:06:12.922 -> 56538 TSF:MSG:READ,1-1-0,s=1,c=1,t=2,pt=4,l=4,sg=0:0
18:06:12.954 -> 56594 GWT:TPS:TOPIC=esp8266-gw/out/1/1/1/0/2,MSG SENT
18:06:14.671 -> 58278 RFM69:SAC:SEND ACK,TO=1,RSSI=-42
18:06:14.704 -> 58320 RFM69:CSMA:RSSI=-42
18:06:14.704 -> 58348 RFM69:CSMA:RSSI=-43
18:06:14.736 -> 58375 RFM69:CSMA:RSSI=-42
18:06:14.768 -> 58402 RFM69:CSMA:RSSI=-43
18:06:14.800 -> 58429 RFM69:CSMA:RSSI=-42
18:06:14.832 -> 58457 RFM69:CSMA:RSSI=-43
18:06:14.832 -> 58484 RFM69:CSMA:RSSI=-42
18:06:14.864 -> 58511 RFM69:CSMA:RSSI=-42
18:06:14.896 -> 58538 RFM69:CSMA:RSSI=-42
18:06:14.928 -> 58565 RFM69:CSMA:RSSI=-42
18:06:14.993 -> 58592 RFM69:CSMA:RSSI=-42
18:06:14.993 -> 58619 RFM69:CSMA:RSSI=-42
18:06:15.025 -> 58646 RFM69:CSMA:RSSI=-42
18:06:15.058 -> 58673 RFM69:CSMA:RSSI=-43
18:06:15.090 -> 58701 RFM69:CSMA:RSSI=-42
18:06:15.122 -> 58728 RFM69:CSMA:RSSI=-42
18:06:15.155 -> 58755 RFM69:CSMA:RSSI=-42
18:06:15.155 -> 58782 RFM69:CSMA:RSSI=-42
18:06:15.188 -> 58809 RFM69:CSMA:RSSI=-42
18:06:15.221 -> 58839 TSF:MSG:READ,1-1-0,s=1,c=1,t=2,pt=4,l=4,sg=0:0
18:06:15.253 -> 58894 GWT:TPS:TOPIC=esp8266-gw/out/1/1/1/0/2,MSG SENT
18:06:16.974 -> 60580 RFM69:SAC:SEND ACK,TO=1,RSSI=-42
18:06:17.006 -> 60622 RFM69:CSMA:RSSI=-42
18:06:17.006 -> 60649 RFM69:CSMA:RSSI=-42
18:06:17.039 -> 60677 RFM69:CSMA:RSSI=-42
18:06:17.071 -> 60704 RFM69:CSMA:RSSI=-42
18:06:17.103 -> 60731 RFM69:CSMA:RSSI=-42
18:06:17.135 -> 60758 RFM69:CSMA:RSSI=-42
18:06:17.135 -> 60785 RFM69:CSMA:RSSI=-42
18:06:17.167 -> 60813 RFM69:CSMA:RSSI=-42
18:06:17.198 -> 60840 RFM69:CSMA:RSSI=-42
18:06:17.231 -> 60867 RFM69:CSMA:RSSI=-43
18:06:17.297 -> 60894 RFM69:CSMA:RSSI=-42
18:06:17.297 -> 60921 RFM69:CSMA:RSSI=-43
18:06:17.329 -> 60948 RFM69:CSMA:RSSI=-42
18:06:17.361 -> 60975 RFM69:CSMA:RSSI=-42
18:06:17.393 -> 61002 RFM69:CSMA:RSSI=-42
18:06:17.425 -> 61030 RFM69:CSMA:RSSI=-42
18:06:17.457 -> 61057 RFM69:CSMA:RSSI=-43
18:06:17.457 -> 61084 RFM69:CSMA:RSSI=-42
18:06:17.489 -> 61111 RFM69:CSMA:RSSI=-42
18:06:17.521 -> 61141 TSF:MSG:READ,1-1-0,s=1,c=1,t=2,pt=4,l=4,sg=0:0
18:06:17.521 -> 61141 TSF:MSG:READ,1-1-0,s=1,c=1,t=2,pt=4,l=4,sg=0:0
18:06:17.554 -> 61197 GWT:TPS:TOPIC=esp8266-gw/out/1/1/1/0/2,MSG SENT
18:06:19.270 -> 62883 RFM69:SAC:SEND ACK,TO=1,RSSI=-42
18:06:19.302 -> 62925 RFM69:CSMA:RSSI=-42
18:06:19.302 -> 62952 RFM69:CSMA:RSSI=-42
18:06:19.333 -> 62979 RFM69:CSMA:RSSI=-42
18:06:19.398 -> 63006 RFM69:CSMA:RSSI=-42
18:06:19.430 -> 63034 RFM69:CSMA:RSSI=-42
18:06:19.462 -> 63061 RFM69:CSMA:RSSI=-42
18:06:19.462 -> 63088 RFM69:CSMA:RSSI=-42
18:06:19.494 -> 63115 RFM69:CSMA:RSSI=-42
18:06:19.526 -> 63142 RFM69:CSMA:RSSI=-42
18:06:19.559 -> 63169 RFM69:CSMA:RSSI=-42
18:06:19.591 -> 63196 RFM69:CSMA:RSSI=-42
18:06:19.591 -> 63223 RFM69:CSMA:RSSI=-42
18:06:19.624 -> 63251 RFM69:CSMA:RSSI=-42
18:06:19.657 -> 63278 RFM69:CSMA:RSSI=-42
18:06:19.689 -> 63305 RFM69:CSMA:RSSI=-42
18:06:19.722 -> 63332 RFM69:CSMA:RSSI=-42
18:06:19.754 -> 63359 RFM69:CSMA:RSSI=-42
18:06:19.754 -> 63386 RFM69:CSMA:RSSI=-42
18:06:19.787 -> 63413 RFM69:CSMA:RSSI=-42
18:06:19.818 -> 63443 TSF:MSG:READ,1-1-0,s=1,c=1,t=2,pt=4,l=4,sg=0:0
18:06:19.882 -> 63498 GWT:TPS:TOPIC=esp8266-gw/out/1/1/1/0/2,MSG SENT
18:06:21.565 -> 65184 RFM69:SAC:SEND ACK,TO=1,RSSI=-43
18:06:21.629 -> 65226 RFM69:CSMA:RSSI=-43
18:06:21.629 -> 65253 RFM69:CSMA:RSSI=-43
18:06:21.662 -> 65281 RFM69:CSMA:RSSI=-43
18:06:21.694 -> 65308 RFM69:CSMA:RSSI=-42
18:06:21.726 -> 65335 RFM69:CSMA:RSSI=-43
18:06:21.759 -> 65362 RFM69:CSMA:RSSI=-43
18:06:21.759 -> 65389 RFM69:CSMA:RSSI=-43
18:06:21.791 -> 65416 RFM69:CSMA:RSSI=-42
18:06:21.823 -> 65443 RFM69:CSMA:RSSI=-42
18:06:21.855 -> 65470 RFM69:CSMA:RSSI=-43
18:06:21.887 -> 65498 RFM69:CSMA:RSSI=-43
18:06:21.887 -> 65525 RFM69:CSMA:RSSI=-43
18:06:21.920 -> 65552 RFM69:CSMA:RSSI=-43
18:06:21.952 -> 65579 RFM69:CSMA:RSSI=-43
18:06:21.984 -> 65606 RFM69:CSMA:RSSI=-43
18:06:22.016 -> 65633 RFM69:CSMA:RSSI=-42
18:06:22.048 -> 65660 RFM69:CSMA:RSSI=-43
18:06:22.048 -> 65687 RFM69:CSMA:RSSI=-43
18:06:22.080 -> 65714 RFM69:CSMA:RSSI=-42
18:06:22.144 -> 65744 TSF:MSG:READ,1-1-0,s=1,c=1,t=2,pt=4,l=4,sg=0:0
18:06:22.176 -> 65800 GWT:TPS:TOPIC=esp8266-gw/out/1/1/1/0/2,MSG SENT

Thanks and regards,

Eric.

Tico

Hi There,

So, if I well understood the logs above, the node sent a msg to the GW 5 times without receiving the ACK, but the GW for each msg received, the GW sent the ACK, but it has never been received by the node. At the end, the GW received a status msg from the node.

I'm a bit stuck here, the ESP8266 has been used previously on another platform, both are Domoticz. Is it possible that some information stored in the GW's EEPROM from the previous platform interferes ? How could I erase this EEPROM ? I know how to do with 328P, but no clue for ESP.

In Domoticz, in the Hardware list, the MQTT gw doesn't list any node. I would expect to see mine here.

Thanks and regards,

Eric.

mfalkvidd

Nice work.

I think the cleareeprom sketch works for esp8266 as well. But I don't think old eeprom is the problem.

I don't have much experience with rfm radios so I don't know what could be wrong. Normal things to check is power supply to the radios and antennas for the radios. I think all the rssi lines in the log indicate that there is a lot of radio noise.

Tico

Thank you.

I cleared the eeprom from the node and the gw, now I can see the node in the MQTT gw in Domoticz. But still the same behavior. The GW and node were very closed during the test, but even with 5 meters in between, still buggy.

What I don't understand it received many times ACK from the GW before stopping:
18:06:05.084 -> 3072 RFM69:SWR:ACK,FROM=0,SEQ=3,RSSI=-36
18:06:05.956 -> 3938 RFM69:SWR:ACK,FROM=0,SEQ=5,RSSI=-39
18:06:06.701 -> 4696 RFM69:SWR:ACK,FROM=0,SEQ=7,RSSI=-39
18:06:07.119 -> 5097 RFM69:SWR:ACK,FROM=0,SEQ=8,RSSI=-36
18:06:09.507 -> 7501 RFM69:SWR:ACK,FROM=0,SEQ=9,RSSI=-36
18:06:09.925 -> 7907 RFM69:SWR:ACK,FROM=0,SEQ=10,RSSI=-37
18:06:10.407 -> 8388 RFM69:SWR:ACK,FROM=0,SEQ=11,RSSI=-38
18:06:10.890 -> 8855 RFM69:SWR:ACK,FROM=0,SEQ=12,RSSI=-39

It looks stopping reading radio once in loop. Could it be my nodemanager repo is outdated ? I'll try to update.

thx and regards

Eric.

Tico

Hi There,

I made a test with RelayActuator sample, and it worked like a charm at first compilation, after updated to RFM69.

Thus, the issue is coming from nodemanager, not from radio implementation.

My nodemanager repo looks in sync with github, nevertheless I'll refresh and give it a test.

Thx and reg

Eric.

Tico

Hi There,

Still investigating.... I refresh my nodemanager repo, but still same behavior. Thus I downgraded MySensors library from 2.4.0 Alpha to 2.3.2 for the nodemanager, still the same. Which is very strange to me as I have a nodemanager, SensorLatchingRelay2Pins, working perfectly over NRF24 with a serial gateway.

I introduced some Serial.println in receive(const MyMessage &message), but looks like never called.

Here is my code, maybe I wrote a mistake:

/*
* The MySensors Arduino library handles the wireless radio link and protocol
* between your home built sensors/actuators and HA controller of choice.
* The sensors forms a self healing radio network with optional repeaters. Each
* repeater and gateway builds a routing tables in EEPROM which keeps track of the
* network topology allowing messages to be routed to nodes.
*
* Created by Henrik Ekblad <henrik.ekblad@mysensors.org>
* Copyright (C) 2013-2017 Sensnology AB
* Full contributor list: https://github.com/mysensors/Arduino/graphs/contributors
*
* Documentation: http://www.mysensors.org
* Support Forum: http://forum.mysensors.org
*
* This program is free software; you can redistribute it and/or
* modify it under the terms of the GNU General Public License
* version 2 as published by the Free Software Foundation.
*/

/**************************
Template

This sketch can be used as a template since containing the most relevant MySensors library configuration settings,
NodeManager's settings, all its the supported sensors commented out and a sketch structure fully functional to operate with
NodeManager. Just uncomment the settings you need and the sensors you want to add and configure the sensors in before()
*/

/**********************************
 * MySensors node configuration
 */

// General settings
#define SKETCH_NAME "NodeManagerRelay"
#define SKETCH_VERSION "1.0"
#define MY_DEBUG
//#define MY_NODE_ID 99

// NRF24 radio settings
//#define MY_RADIO_RF24
//#define MY_RF24_ENABLE_ENCRYPTION
//#define MY_RF24_CHANNEL 125
//#define MY_RF24_PA_LEVEL RF24_PA_HIGH
//#define MY_DEBUG_VERBOSE_RF24
//#define MY_RF24_DATARATE RF24_250KBPS

// RFM69 radio settings
#define MY_RADIO_RFM69
#define MY_RFM69_FREQUENCY RFM69_868MHZ
#define MY_IS_RFM69HW
#define MY_RFM69_NEW_DRIVER
//#define MY_RFM69_ENABLE_ENCRYPTION
//#define MY_RFM69_NETWORKID 100
#define MY_DEBUG_VERBOSE_RFM69
#define MY_RFM69_IRQ_PIN 2
//#define MY_RFM69_IRQ_NUM MY_RFM69_IRQ_PIN
#define MY_RFM69_CS_PIN 10
//#define MY_RF69_SPI_CS D2
//#define MY_RFM69_ATC_MODE_DISABLED


// Advanced settings
#define MY_BAUD_RATE 9600
//#define MY_SMART_SLEEP_WAIT_DURATION_MS 500
//#define MY_SPLASH_SCREEN_DISABLED
//#define MY_DISABLE_RAM_ROUTING_TABLE_FEATURE
//#define MY_SIGNAL_REPORT_ENABLED

// Optimizations when running on 2032 Coin Cell. Also set nodeManager.setSleepBetweenSend(500) and run the board at 1Mhz
//#define MY_TRANSPORT_UPLINK_CHECK_DISABLED
//#define MY_TRANSPORT_WAIT_READY_MS  5000
//#define MY_SLEEP_TRANSPORT_RECONNECT_TIMEOUT_MS 2000
//#define MY_PARENT_NODE_ID 0
//#define MY_PARENT_NODE_IS_STATIC

/**********************************
 * MySensors gateway configuration
 */

// Common gateway settings
#define MY_REPEATER_FEATURE

/***********************************
 * NodeManager configuration
 */

#define NODEMANAGER_DEBUG ON
#define NODEMANAGER_INTERRUPTS ON
#define NODEMANAGER_SLEEP OFF
#define NODEMANAGER_RECEIVE ON
#define NODEMANAGER_DEBUG_VERBOSE ON
#define NODEMANAGER_POWER_MANAGER OFF
#define NODEMANAGER_CONDITIONAL_REPORT OFF
#define NODEMANAGER_EEPROM OFF
#define NODEMANAGER_TIME OFF
#define NODEMANAGER_RTC OFF
#define NODEMANAGER_SD OFF
#define NODEMANAGER_HOOKING OFF
#define NODEMANAGER_OTA_CONFIGURATION OFF
#define NODEMANAGER_SERIAL_INPUT OFF

// import NodeManager library (a nodeManager object will be then made available)
#include <MySensors_NodeManager.h>

/***********************************
 * Add your sensors
 */

#include <sensors/SensorRelay.h>
SensorRelay relay(6);


/***********************************
 * Main Sketch
 */

// before
void before() {

  /***********************************
   * Configure your sensors
   */


  // call NodeManager before routine
  nodeManager.before();
}

// presentation
void presentation() {
  // call NodeManager presentation routine
  nodeManager.presentation();
}

// setup
void setup() {
  // call NodeManager setup routine
  nodeManager.setup();
}

// loop
void loop() {
  // call NodeManager loop routine
  nodeManager.loop();
}

//#if NODEMANAGER_RECEIVE == ON
// receive
void receive(const MyMessage &message) {

  Serial.println("********* In receive ************");  
    if (message.isAck()) {
     Serial.println("************** This is an ack from gateway ******************");
  }

  // call NodeManager receive routine
  nodeManager.receive(message);
}
//#endif

#if NODEMANAGER_TIME == ON
// receiveTime
void receiveTime(unsigned long ts) {
  // call NodeManager receiveTime routine
  nodeManager.receiveTime(ts);
}
#endif

So the detailed issue would be:
A nodemanager doesn't receive ACK anymore after the INIT from the gateway (MQTT with TLS) over RFM69. Looks like receive(const MyMessage &message) is never called. An extract from the node logs to illustrate:

11:26:28.397 -> 7487 RFM69:SWR:ACK,FROM=0,SEQ=13,RSSI=-55
11:26:28.462 -> 7532 TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
11:26:28.850 -> 7933 RFM69:SAC:SEND ACK,TO=0,RSSI=-44
11:26:28.882 -> 7974 RFM69:CSMA:RSSI=-100
11:26:28.914 -> 8003 TSF:MSG:READ,0-0-2,s=255,c=3,t=27,pt=1,l=1,sg=0:1
11:26:28.978 -> 8060 MCO:PIM:NODE REG=1
11:26:29.010 -> 8087 MCO:BGN:STP
11:26:29.047 -> 8105 NM:STP:ID=2 M=1
11:26:29.047 -> 8128 NM:LOOP:RELAY(1):SET t=2 v=0
11:26:29.717 -> 8235 NM:STP:HW V=3329 F=8 M=1116
11:26:29.749 -> 8269 MCO:BGN:INIT OK,TSP=1
11:26:29.782 -> 8298 NM:MSG:SEND(1) t=2 p=0
11:26:29.815 -> 8327 RFM69:SWR:SEND,TO=0,SEQ=14,RETRY=0
11:26:29.847 -> 8370 RFM69:CSMA:RSSI=-105
11:26:32.071 -> 10600 !RFM69:SWR:NACK

I guess I can open an issue in the nodemanager github.

Reg

Eric.

NACK after Core initialized, transport status 1

19

11.7k

11.2k

113.1k