Raspberry Pi 3 (RPI 3) + MQTT gateway NACK and triple messages

[Oumuamua]

Hi all,

Following a previous post on my transition to a RPI gateway + MQTT, I'm now experiencing two problems:

• Significant NACK ocurrencies, specially when connecting to gateway
• messages to MQTT gateway tripled

As per the logs below, node and gateway are able to connect (they are 4m away), RSSI seems to be very good (-30 to -40), but there number of connection attempts with NACK are not justified.

Also, for each message sent from node, there are three (sometimes 2, sometimes 4) messages sent by gateway to MQTT server.

I've already changed the antenna on the gateway radio. I haven't tried another radio as this one seems to be working well.

Both logs were taken in paralell (see timestamp)

Many thanks for any help!!

Node Log

08:02:11.829 ->  __  __       ____
08:02:11.829 -> |  \/  |_   _/ ___|  ___ _ __  ___  ___  _ __ ___
08:02:11.829 -> | |\/| | | | \___ \ / _ \ `_ \/ __|/ _ \| `__/ __|
08:02:11.829 -> | |  | | |_| |___| |  __/ | | \__ \  _  | |  \__ \
08:02:11.829 -> |_|  |_|\__, |____/ \___|_| |_|___/\___/|_|  |___/
08:02:11.863 ->         |___/                      2.3.2
08:02:11.863 -> 
08:02:11.863 -> 16 MCO:BGN:INIT NODE,CP=RPNNA---,FQ=16,REL=255,VER=2.3.2
08:02:11.863 -> 26 TSM:INIT
08:02:11.863 -> 28 TSF:WUR:MS=0
08:02:11.863 -> 29 TSM:INIT:TSP OK
08:02:11.863 -> 31 TSM:INIT:STATID=2
08:02:11.863 -> 33 TSF:SID:OK,ID=2
08:02:11.863 -> 35 TSM:FPAR
08:02:12.361 -> 540 ?TSF:MSG:SEND,2-2-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
08:02:14.355 -> 2511 TSF:MSG:READ,0-0-2,s=255,c=3,t=8,pt=1,l=1,sg=0:0
08:02:14.355 -> 2516 TSF:MSG:FPAR OK,ID=0,D=1
08:02:14.388 -> 2547 TSM:FPAR:OK
08:02:14.388 -> 2548 TSM:ID
08:02:14.388 -> 2549 TSM:ID:OK
08:02:14.388 -> 2551 TSM:UPL
08:02:17.909 -> 6069 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=NACK:1
08:02:19.204 -> 7389 TSF:MSG:READ,0-0-2,s=255,c=3,t=25,pt=1,l=1,sg=0:1
08:02:19.204 -> 7394 TSF:MSG:PONG RECV,HP=1
08:02:19.238 -> 7396 TSM:UPL:OK
08:02:19.238 -> 7398 TSM:READY:ID=2,PAR=0,DIS=1
08:02:22.560 -> 10728 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=NACK:0100
08:02:23.723 -> 11901 TSF:MSG:READ,0-0-2,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
08:02:27.246 -> 15421 !TSF:MSG:SEND,2-2-0-0,s=255,c=0,t=17,pt=0,l=5,sg=0,ft=1,st=NACK:2.3.2
08:02:30.768 -> 18941 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=2,st=NACK:0
08:02:36.318 -> 24473 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=11,pt=0,l=22,sg=0,ft=3,st=NACK:TemperatureAndHumidity
08:02:39.841 -> 27993 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=4,st=NACK:1.1
08:02:43.364 -> 31519 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=11,pt=0,l=13,sg=0,ft=5,st=NACK:Battery Meter
08:02:46.887 -> 35038 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=6,st=NACK:1.0
08:02:50.409 -> 38559 !TSF:MSG:SEND,2-2-0-0,s=0,c=0,t=7,pt=0,l=0,sg=0,ft=7,st=NACK:
08:02:53.898 -> 42077 !TSF:MSG:SEND,2-2-0-0,s=1,c=0,t=6,pt=0,l=0,sg=0,ft=8,st=NACK:
08:02:57.419 -> 45599 !TSF:MSG:SEND,2-2-0-0,s=2,c=0,t=23,pt=0,l=0,sg=0,ft=9,st=NACK:
08:02:57.453 -> 45605 MCO:REG:REQ
08:03:00.943 -> 49121 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=10,st=NACK:2
08:03:00.976 -> 49127 !TSM:READY:UPL FAIL,SNP
08:03:00.976 -> 49130 TSM:FPAR
08:03:01.474 -> 49635 ?TSF:MSG:SEND,2-2-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=11,st=OK:
08:03:02.869 -> 51050 TSF:MSG:READ,0-0-2,s=255,c=3,t=27,pt=1,l=1,sg=0:1
08:03:02.903 -> 51055 MCO:PIM:NODE REG=1
08:03:04.898 -> 53058 !TSM:FPAR:NO REPLY
08:03:04.898 -> 53060 TSM:FPAR
08:03:05.396 -> 53565 ?TSF:MSG:SEND,2-2-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
08:03:07.157 -> 55321 TSF:MSG:READ,0-0-2,s=255,c=3,t=8,pt=1,l=1,sg=0:0
08:03:07.157 -> 55326 TSF:MSG:FPAR OK,ID=0,D=1
08:03:07.423 -> 55572 TSM:FPAR:OK
08:03:07.423 -> 55573 TSM:ID
08:03:07.423 -> 55575 TSM:ID:OK
08:03:07.423 -> 55576 TSM:UPL
08:03:10.946 -> 59095 !TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=NACK:1
08:03:12.242 -> 60406 TSF:MSG:READ,0-0-2,s=255,c=3,t=25,pt=1,l=1,sg=0:1
08:03:12.242 -> 60411 TSF:MSG:PONG RECV,HP=1
08:03:12.242 -> 60414 TSM:UPL:OK
08:03:12.242 -> 60416 TSM:READY:ID=2,PAR=0,DIS=1
08:03:12.242 -> 60419 MCO:BGN:STP
08:03:12.242 -> 60422 MCO:SLP:MS=1000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:03:12.276 -> 60427 TSF:TDI:TSL
08:03:13.339 -> 60429 MCO:SLP:WUP=-1
08:03:13.339 -> 60431 TSF:TRI:TSB
08:03:13.372 -> 60433 MCO:BGN:INIT OK,TSP=1
08:03:16.894 -> 63969 !TSF:MSG:SEND,2-2-0-0,s=1,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=NACK:22.0
08:03:16.894 -> T: 22.00
08:03:20.450 -> 67511 !TSF:MSG:SEND,2-2-0-0,s=0,c=1,t=1,pt=7,l=5,sg=0,ft=1,st=NACK:95.0
08:03:20.450 -> H: 95.00
08:03:23.940 -> 71028 !TSF:MSG:SEND,2-2-0-0,s=2,c=1,t=28,pt=2,l=2,sg=0,ft=2,st=NACK:-32
08:03:23.973 -> RSSI: -32
08:03:23.973 -> 71034 MCO:SLP:MS=60000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:03:23.973 -> 71041 TSF:TDI:TSL
08:04:28.339 -> 71043 MCO:SLP:WUP=-1
08:04:28.339 -> 71045 TSF:TRI:TSB
08:04:31.893 -> 74582 !TSF:MSG:SEND,2-2-0-0,s=2,c=1,t=28,pt=2,l=2,sg=0,ft=3,st=NACK:-32
08:04:31.893 -> RSSI: -32
08:04:31.893 -> 74588 MCO:SLP:MS=60000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:04:31.893 -> 74594 TSF:TDI:TSL
08:05:36.231 -> 74596 MCO:SLP:WUP=-1
08:05:36.231 -> 74598 TSF:TRI:TSB
08:05:39.785 -> 78135 !TSF:MSG:SEND,2-2-0-0,s=2,c=1,t=28,pt=2,l=2,sg=0,ft=4,st=NACK:-32
08:05:39.785 -> RSSI: -32
08:05:39.785 -> 78141 MCO:SLP:MS=60000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:05:39.785 -> 78147 TSF:TDI:TSL
08:06:44.132 -> 78149 MCO:SLP:WUP=-1
08:06:44.132 -> 78151 TSF:TRI:TSB
08:06:47.683 -> 81691 !TSF:MSG:SEND,2-2-0-0,s=2,c=1,t=28,pt=2,l=2,sg=0,ft=5,st=NACK:-32
08:06:47.683 -> RSSI: -32
08:06:47.683 -> 81697 MCO:SLP:MS=60000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:06:47.683 -> 81703 TSF:TDI:TSL
08:07:52.039 -> 81705 MCO:SLP:WUP=-1
08:07:52.039 -> 81708 TSF:TRI:TSB
08:07:52.039 -> 81709 !TSM:READY:UPL FAIL,SNP
08:07:52.039 -> 81712 TSM:FPAR
08:07:52.537 -> 82219 ?TSF:MSG:SEND,2-2-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=6,st=OK:
08:07:52.570 -> 82247 !TSF:SND:TNR
08:07:52.570 -> RSSI: -32
08:07:52.570 -> 82249 MCO:SLP:MS=60000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:07:52.570 -> 82254 !MCO:SLP:TNR
08:07:53.700 -> 83374 TSF:MSG:READ,0-0-2,s=255,c=3,t=8,pt=1,l=1,sg=0:0
08:07:53.700 -> 83379 TSF:MSG:FPAR OK,ID=0,D=1
08:07:54.564 -> 84226 TSM:FPAR:OK
08:07:54.564 -> 84227 TSM:ID
08:07:54.564 -> 84229 TSM:ID:OK
08:07:54.564 -> 84230 TSM:UPL
08:07:57.188 -> 86844 TSF:MSG:SEND,2-2-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
08:07:58.882 -> 88552 TSF:MSG:READ,0-0-2,s=255,c=3,t=25,pt=1,l=1,sg=0:1
08:07:58.882 -> 88557 TSF:MSG:PONG RECV,HP=1
08:07:58.882 -> 88560 TSM:UPL:OK
08:07:58.882 -> 88561 TSM:READY:ID=2,PAR=0,DIS=1
08:07:58.882 -> 88564 MCO:SLP:MS=53692
08:07:58.882 -> 88566 TSF:TDI:TSL
08:08:56.465 -> 88568 MCO:SLP:WUP=-1
08:08:56.465 -> 88570 TSF:TRI:TSB
08:09:00.018 -> 92109 !TSF:MSG:SEND,2-2-0-0,s=0,c=1,t=1,pt=7,l=5,sg=0,ft=0,st=NACK:94.0
08:09:00.018 -> H: 94.00
08:09:01.946 -> 94031 TSF:MSG:SEND,2-2-0-0,s=2,c=1,t=28,pt=2,l=2,sg=0,ft=1,st=OK:-32
08:09:01.946 -> RSSI: -32
08:09:01.946 -> 94038 MCO:SLP:MS=60000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:09:01.946 -> 94044 TSF:TDI:TSL
08:10:06.293 -> 94046 MCO:SLP:WUP=-1
08:10:06.293 -> 94048 TSF:TRI:TSB
08:10:09.848 -> 97585 !TSF:MSG:SEND,2-2-0-0,s=1,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=NACK:23.0
08:10:09.848 -> T: 23.00
08:10:13.370 -> 101126 !TSF:MSG:SEND,2-2-0-0,s=0,c=1,t=1,pt=7,l=5,sg=0,ft=1,st=NACK:95.0
08:10:13.370 -> H: 95.00
08:10:16.890 -> 104649 !TSF:MSG:SEND,2-2-0-0,s=2,c=1,t=28,pt=2,l=2,sg=0,ft=2,st=NACK:-33
08:10:16.924 -> RSSI: -33
08:10:16.924 -> 104655 MCO:SLP:MS=60000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:10:16.924 -> 104662 TSF:TDI:TSL
08:11:21.281 -> 104664 MCO:SLP:WUP=-1
08:11:21.281 -> 104666 TSF:TRI:TSB
08:11:24.800 -> 108204 !TSF:MSG:SEND,2-2-0-0,s=1,c=1,t=0,pt=7,l=5,sg=0,ft=3,st=NACK:22.0
08:11:24.800 -> T: 22.00
08:11:28.355 -> 111744 !TSF:MSG:SEND,2-2-0-0,s=2,c=1,t=28,pt=2,l=2,sg=0,ft=4,st=NACK:-33
08:11:28.355 -> RSSI: -33
08:11:28.355 -> 111750 MCO:SLP:MS=60000,SMS=0,I1=255,M1=255,I2=255,M2=255
08:11:28.355 -> 111756 TSF:TDI:TSL
08:12:32.710 -> 111758 MCO:SLP:WUP=-1
08:12:32.710 -> 111760 TSF:TRI:TSB

Gateway Log

Sep 03 08:01:53 INFO  Starting gateway...
Sep 03 08:01:53 INFO  Protocol version - 2.3.2
Sep 03 08:01:53 DEBUG MCO:BGN:INIT GW,CP=RPNGL---,FQ=NA,REL=255,VER=2.3.2
Sep 03 08:01:53 DEBUG TSF:LRT:OK
Sep 03 08:01:53 DEBUG TSM:INIT
Sep 03 08:01:53 DEBUG TSF:WUR:MS=0
Sep 03 08:01:53 DEBUG TSM:INIT:TSP OK
Sep 03 08:01:53 DEBUG TSM:INIT:GW MODE
Sep 03 08:01:53 DEBUG TSM:READY:ID=0,PAR=0,DIS=0
Sep 03 08:01:53 DEBUG MCO:REG:NOT NEEDED
Sep 03 08:01:53 DEBUG MCO:BGN:STP
Sep 03 08:01:53 DEBUG MCO:BGN:INIT OK,TSP=1
Sep 03 08:01:53 DEBUG GWT:RMQ:CONNECTING...
Sep 03 08:01:53 DEBUG connected to 127.0.0.1
Sep 03 08:01:53 DEBUG GWT:RMQ:OK
Sep 03 08:01:53 DEBUG GWT:TPS:TOPIC=mygateway1-out/0/255/0/0/18,MSG SENT
Sep 03 08:01:53 DEBUG TSM:READY:NWD REQ
Sep 03 08:01:54 DEBUG ?TSF:MSG:SEND,0-0-255-255,s=255,c=3,t=20,pt=0,l=0,sg=0,ft=0,st=OK:
Sep 03 08:02:12 DEBUG TSF:MSG:READ,2-2-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
Sep 03 08:02:12 DEBUG TSF:MSG:BC
Sep 03 08:02:12 DEBUG TSF:MSG:FPAR REQ,ID=2
Sep 03 08:02:12 DEBUG TSF:PNG:SEND,TO=0
Sep 03 08:02:12 DEBUG TSF:CKU:OK
Sep 03 08:02:12 DEBUG TSF:MSG:GWL OK
Sep 03 08:02:16 DEBUG !TSF:MSG:SEND,0-0-2-2,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=NACK:0
Sep 03 08:02:17 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
Sep 03 08:02:17 DEBUG TSF:MSG:PINGED,ID=2,HP=1
Sep 03 08:02:21 DEBUG !TSF:MSG:SEND,0-0-2-2,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=NACK:1
Sep 03 08:02:21 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
Sep 03 08:02:24 DEBUG !TSF:MSG:SEND,0-0-2-2,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=NACK:0100
Sep 03 08:02:25 DEBUG TSF:MSG:READ,2-2-0,s=255,c=0,t=17,pt=0,l=5,sg=0:2.3.2
Sep 03 08:02:25 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/0/0/17,MSG SENT
Sep 03 08:02:26 DEBUG TSF:MSG:READ,2-2-0,s=255,c=0,t=17,pt=0,l=5,sg=0:2.3.2
Sep 03 08:02:26 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/0/0/17,MSG SENT
Sep 03 08:02:28 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
Sep 03 08:02:28 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/6,MSG SENT
Sep 03 08:02:29 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
Sep 03 08:02:29 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/6,MSG SENT
Sep 03 08:02:31 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
Sep 03 08:02:31 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/6,MSG SENT
Sep 03 08:02:33 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=11,pt=0,l=22,sg=0:TemperatureAndHumidity
Sep 03 08:02:33 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/11,MSG SENT
Sep 03 08:02:35 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=11,pt=0,l=22,sg=0:TemperatureAndHumidity
Sep 03 08:02:35 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/11,MSG SENT
Sep 03 08:02:36 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=11,pt=0,l=22,sg=0:TemperatureAndHumidity
Sep 03 08:02:36 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/11,MSG SENT
Sep 03 08:02:38 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.1
Sep 03 08:02:38 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/12,MSG SENT
Sep 03 08:02:39 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.1
Sep 03 08:02:39 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/12,MSG SENT
Sep 03 08:02:40 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=11,pt=0,l=13,sg=0:Battery Meter
Sep 03 08:02:40 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/11,MSG SENT
Sep 03 08:02:42 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=11,pt=0,l=13,sg=0:Battery Meter
Sep 03 08:02:42 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/11,MSG SENT
Sep 03 08:02:43 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=11,pt=0,l=13,sg=0:Battery Meter
Sep 03 08:02:43 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/11,MSG SENT
Sep 03 08:02:45 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.0
Sep 03 08:02:45 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/12,MSG SENT
Sep 03 08:02:46 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.0
Sep 03 08:02:46 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/255/3/0/12,MSG SENT
Sep 03 08:02:47 DEBUG TSF:MSG:READ,2-2-0,s=0,c=0,t=7,pt=0,l=0,sg=0:
Sep 03 08:02:47 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/0/0/7,MSG SENT
Sep 03 08:02:49 DEBUG TSF:MSG:READ,2-2-0,s=0,c=0,t=7,pt=0,l=0,sg=0:
Sep 03 08:02:49 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/0/0/7,MSG SENT
Sep 03 08:02:50 DEBUG TSF:MSG:READ,2-2-0,s=0,c=0,t=7,pt=0,l=0,sg=0:
Sep 03 08:02:50 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/0/0/7,MSG SENT
Sep 03 08:02:52 DEBUG TSF:MSG:READ,2-2-0,s=1,c=0,t=6,pt=0,l=0,sg=0:
Sep 03 08:02:52 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/0/0/6,MSG SENT
Sep 03 08:02:53 DEBUG TSF:MSG:READ,2-2-0,s=1,c=0,t=6,pt=0,l=0,sg=0:
Sep 03 08:02:53 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/0/0/6,MSG SENT
Sep 03 08:02:54 DEBUG TSF:MSG:READ,2-2-0,s=2,c=0,t=23,pt=0,l=0,sg=0:
Sep 03 08:02:54 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/0/0/23,MSG SENT
Sep 03 08:02:56 DEBUG TSF:MSG:READ,2-2-0,s=2,c=0,t=23,pt=0,l=0,sg=0:
Sep 03 08:02:56 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/0/0/23,MSG SENT
Sep 03 08:02:57 DEBUG TSF:MSG:READ,2-2-0,s=2,c=0,t=23,pt=0,l=0,sg=0:
Sep 03 08:02:57 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/0/0/23,MSG SENT
Sep 03 08:02:59 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=26,pt=1,l=1,sg=0:2
Sep 03 08:03:02 DEBUG !TSF:MSG:SEND,0-0-2-2,s=255,c=3,t=27,pt=1,l=1,sg=0,ft=0,st=NACK:1
Sep 03 08:03:05 DEBUG TSF:MSG:READ,2-2-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
Sep 03 08:03:05 DEBUG TSF:MSG:BC
Sep 03 08:03:05 DEBUG TSF:MSG:FPAR REQ,ID=2
Sep 03 08:03:05 DEBUG TSF:PNG:SEND,TO=0
Sep 03 08:03:05 DEBUG TSF:CKU:OK
Sep 03 08:03:05 DEBUG TSF:MSG:GWL OK
Sep 03 08:03:09 DEBUG !TSF:MSG:SEND,0-0-2-2,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=NACK:0
Sep 03 08:03:10 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
Sep 03 08:03:10 DEBUG TSF:MSG:PINGED,ID=2,HP=1
Sep 03 08:03:14 DEBUG !TSF:MSG:SEND,0-0-2-2,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=NACK:1
Sep 03 08:03:15 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:22.0
Sep 03 08:03:15 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:03:16 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:22.0
Sep 03 08:03:16 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:03:17 DEBUG TSF:MSG:READ,2-2-0,s=0,c=1,t=1,pt=7,l=5,sg=0:95.0
Sep 03 08:03:17 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/1/0/1,MSG SENT
Sep 03 08:03:19 DEBUG TSF:MSG:READ,2-2-0,s=0,c=1,t=1,pt=7,l=5,sg=0:95.0
Sep 03 08:03:19 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/1/0/1,MSG SENT
Sep 03 08:03:20 DEBUG TSF:MSG:READ,2-2-0,s=0,c=1,t=1,pt=7,l=5,sg=0:95.0
Sep 03 08:03:20 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/1/0/1,MSG SENT
Sep 03 08:03:22 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:03:22 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:03:23 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:03:23 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:04:29 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:04:29 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:04:30 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:04:30 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:04:32 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:04:32 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:05:37 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:05:37 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:05:38 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:05:38 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:05:40 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:05:40 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:06:45 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:06:45 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:06:46 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:06:46 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:06:47 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:06:47 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:07:52 DEBUG TSF:MSG:READ,2-2-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
Sep 03 08:07:52 DEBUG TSF:MSG:BC
Sep 03 08:07:52 DEBUG TSF:MSG:FPAR REQ,ID=2
Sep 03 08:07:52 DEBUG TSF:PNG:SEND,TO=0
Sep 03 08:07:52 DEBUG TSF:CKU:OK
Sep 03 08:07:52 DEBUG TSF:MSG:GWL OK
Sep 03 08:07:56 DEBUG !TSF:MSG:SEND,0-0-2-2,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=NACK:0
Sep 03 08:07:57 DEBUG TSF:MSG:READ,2-2-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
Sep 03 08:07:57 DEBUG TSF:MSG:PINGED,ID=2,HP=1
Sep 03 08:08:00 DEBUG !TSF:MSG:SEND,0-0-2-2,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=NACK:1
Sep 03 08:08:58 DEBUG TSF:MSG:READ,2-2-0,s=0,c=1,t=1,pt=7,l=5,sg=0:94.0
Sep 03 08:08:58 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/1/0/1,MSG SENT
Sep 03 08:08:59 DEBUG TSF:MSG:READ,2-2-0,s=0,c=1,t=1,pt=7,l=5,sg=0:94.0
Sep 03 08:08:59 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/1/0/1,MSG SENT
Sep 03 08:09:01 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:09:01 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:09:01 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-32
Sep 03 08:09:01 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:10:07 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:23.0
Sep 03 08:10:07 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:10:08 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:23.0
Sep 03 08:10:08 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:10:10 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:23.0
Sep 03 08:10:10 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:10:11 DEBUG TSF:MSG:READ,2-2-0,s=0,c=1,t=1,pt=7,l=5,sg=0:95.0
Sep 03 08:10:11 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/1/0/1,MSG SENT
Sep 03 08:10:12 DEBUG TSF:MSG:READ,2-2-0,s=0,c=1,t=1,pt=7,l=5,sg=0:95.0
Sep 03 08:10:12 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/0/1/0/1,MSG SENT
Sep 03 08:10:14 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-33
Sep 03 08:10:14 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:10:15 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-33
Sep 03 08:10:15 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:10:17 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-33
Sep 03 08:10:17 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:11:22 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:22.0
Sep 03 08:11:22 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:11:23 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:22.0
Sep 03 08:11:23 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:11:25 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:22.0
Sep 03 08:11:25 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:11:26 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-33
Sep 03 08:11:26 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:11:27 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-33
Sep 03 08:11:27 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:12:33 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:23.0
Sep 03 08:12:33 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:12:35 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:23.0
Sep 03 08:12:35 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:12:36 DEBUG TSF:MSG:READ,2-2-0,s=1,c=1,t=0,pt=7,l=5,sg=0:23.0
Sep 03 08:12:36 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/1/1/0/0,MSG SENT
Sep 03 08:12:37 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-33
Sep 03 08:12:37 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT
Sep 03 08:12:39 DEBUG TSF:MSG:READ,2-2-0,s=2,c=1,t=28,pt=2,l=2,sg=0:-33
Sep 03 08:12:39 DEBUG GWT:TPS:TOPIC=mygateway1-out/2/2/1/0/28,MSG SENT

Gateway config

./configure --my-gateway=mqtt --my-controller-ip-address=127.0.0.1 --my-mqtt-user=user --my-mqtt-password=pswd --my-mqtt-publish-topic-prefix=mygateway1-out --my-mqtt-subscribe-topic-prefix=mygateway1-in --my-mqtt-client-id=gw_02 --my-transport=rfm69 --my-rfm69-frequency=433 --my-is-rfm69hw --extra-cxxflags="-DMY_DEBUG_VERBOSE_GATEWAY"

Node config

/**
 * 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-2015 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.
 *
 *******************************
 *
 * REVISION HISTORY
 * Version 1.0: Henrik EKblad
 * Version 1.1 - 2016-07-20: Converted to MySensors v2.0 and added various improvements - Torben Woltjen (mozzbozz)
 * 
 * DESCRIPTION
 * This sketch provides an example of how to implement a humidity/temperature
 * sensor using a DHT11/DHT-22.
 *  
 * For more information, please visit:
 * http://www.mysensors.org/build/humidity
 * 
 */

// Enable debug prints
#define MY_DEBUG

// Atualizar para nó esperado
#define MY_NODE_ID 2

// Novo driver para gateway RPI
#define MY_RFM69_NEW_DRIVER

// Enable and select radio type attached 
//#define MY_RADIO_RF24
#define MY_RADIO_RFM69
//#define MY_RS485

#define MY_RFM69_FREQUENCY RFM69_433MHZ  // Define for frequency setting. Needed if you're radio module isn't 868Mhz (868Mhz is default in lib)
#define MY_IS_RFM69HW  // Mandatory if you radio module is the high power version (RFM69HW and RFM69HCW), Comment it if it's not the case


#include <SPI.h>
#include <MySensors.h>  
#include <DHT.h>

// Set this to the pin you connected the DHT's data pin to
#define DHT_DATA_PIN 3

// select the input pin for the battery sense point
int BATTERY_SENSE_PIN = A0;
int oldBatteryPcnt = 0;

// Set this offset if the sensor has a permanent small offset to the real temperatures.
// In Celsius degrees (as measured by the device)
#define SENSOR_TEMP_OFFSET 0

// Sleep time between sensor updates (in milliseconds)
// Must be >1000ms for DHT22 and >2000ms for DHT11
static const uint64_t UPDATE_INTERVAL = 60000;

// Force sending an update of the temperature after n sensor reads, so a controller showing the
// timestamp of the last update doesn't show something like 3 hours in the unlikely case, that
// the value didn't change since;
// i.e. the sensor would force sending an update every UPDATE_INTERVAL*FORCE_UPDATE_N_READS [ms]
static const uint8_t FORCE_UPDATE_N_READS = 5;

#define CHILD_ID_HUM 0
#define CHILD_ID_TEMP 1
#define CHILD_ID_RSSI 2               //RSSI
#define CHILD_ID_BAT 3               //BATTERY


float lastTemp;
float lastHum;
uint8_t nNoUpdatesTemp;
uint8_t nNoUpdatesHum;
bool metric = true;
int16_t rssiVal;               //RSSI
char rssiStr[10];             //RSSI



MyMessage msgHum(CHILD_ID_HUM, V_HUM);
MyMessage msgTemp(CHILD_ID_TEMP, V_TEMP);
MyMessage msgRSSI(CHILD_ID_RSSI,V_VAR5);
DHT dht;





void presentation()  
{ 
  // Send the sketch version information to the gateway
  sendSketchInfo("TemperatureAndHumidity", "1.1");
  sendSketchInfo("Battery Meter", "1.0");
///  sendSketchInfo("DHT11-v05");

  // Register all sensors to gw (they will be created as child devices)
  present(CHILD_ID_HUM, S_HUM);
  present(CHILD_ID_TEMP, S_TEMP);
  present(CHILD_ID_RSSI, S_CUSTOM);


  metric = getControllerConfig().isMetric;
}


void setup()
{
  // Battery
  // use the 1.1 V internal reference
  #if defined(__AVR_ATmega2560__)
    analogReference(INTERNAL1V1);
  #else
    analogReference(INTERNAL);
  #endif
  
  dht.setup(DHT_DATA_PIN); // set data pin of DHT sensor
  if (UPDATE_INTERVAL <= dht.getMinimumSamplingPeriod()) {
    Serial.println("Warning: UPDATE_INTERVAL is smaller than supported by the sensor!");
  }
  // Sleep for the time of the minimum sampling period to give the sensor time to power up
  // (otherwise, timeout errors might occure for the first reading)
  sleep(dht.getMinimumSamplingPeriod());
}


void loop()      
{  
  // Force reading sensor, so it works also after sleep()
  dht.readSensor(true);

  // Get temperature from DHT library
  float temperature = dht.getTemperature();
  if (isnan(temperature)) {
    Serial.println("Failed reading temperature from DHT!");
  } else if (temperature != lastTemp || nNoUpdatesTemp == FORCE_UPDATE_N_READS) {
    // Only send temperature if it changed since the last measurement or if we didn't send an update for n times
    lastTemp = temperature;

    // apply the offset before converting to something different than Celsius degrees
    temperature += SENSOR_TEMP_OFFSET;

    if (!metric) {
      temperature = dht.toFahrenheit(temperature);
    }
    // Reset no updates counter
    nNoUpdatesTemp = 0;
    send(msgTemp.set(temperature, 1));

    #ifdef MY_DEBUG
    Serial.print("T: ");
    Serial.println(temperature);
    #endif
  } else {
    // Increase no update counter if the temperature stayed the same
    nNoUpdatesTemp++;
  }

  // Get humidity from DHT library
  float humidity = dht.getHumidity();
  if (isnan(humidity)) {
    Serial.println("Failed reading humidity from DHT");
  } else if (humidity != lastHum || nNoUpdatesHum == FORCE_UPDATE_N_READS) {
    // Only send humidity if it changed since the last measurement or if we didn't send an update for n times
    lastHum = humidity;
    // Reset no updates counter
    nNoUpdatesHum = 0;
    send(msgHum.set(humidity, 1));

    #ifdef MY_DEBUG
    Serial.print("H: ");
    Serial.println(humidity);
    #endif
  } else {
    // Increase no update counter if the humidity stayed the same
    nNoUpdatesHum++;
  }

//  rssiVal = _radio.readRSSI();  // Old Driver
  rssiVal = RFM69_getReceivingRSSI();  // New Driver
  send(msgRSSI.set(rssiVal));
  #ifdef MY_DEBUG
  Serial.print("RSSI: ");
  Serial.println(rssiVal);
  #endif

  // Sleep for a while to save energy
  sleep(UPDATE_INTERVAL); 
}

[mfalkvidd]

Nice work on the troubleshooting @Oumuamua

The reason the node sends multiple times (which causes the gateway to publish multiple times to mqtt) is that the node does not receive ack from the gateway, and therefore assumes that the message got lost and retransmits.

So the question is why the node has trouble hearing the ack. Maybe the power supply to the gateway's radio isn't sufficiently stable. Imagine trying to hear a podcast while twiddling the volume knob up and down all the time. Are you using a capacitor near the radio? The rfm radios usually don't need one though.

Maybe the signal is too strong. The rssi values are pretty high. Imagine standing next to a megaphone blasting in your ear. See if omitting --my-is-rfm69hw and re-running make and make install helps (iirc, this will result in lower output power). You could also try moving the node further away from the gateway.

Maybe the antennas are bad. Could you post photos of the antennas? Maybe there is a solder bridge somewhere?

[OldSurferDude]

@Oumuamua I have a non-MySensors nRF24 network and I discovered that a significant number of ACKs don't get received and is more so on child and child-of-child nodes. It is my understanding that ACKs are a programable part of the nRF24 and not part of your code nor of the MySensors code.

More often than not, the message has been received, even though the ACK didn't make it back. Thus, I added an acknowledge to my code.

For a reason I don't understand, the MySensors code is more robust when it comes to ACKs

Perhaps the MySensor code employ a messageID strategy to avoid duplicate messages?

I concur with @mfalkvidd that noise and/or overdriving the antenna and/or bad connections are a source of many problems.

[Oumuamua]

Thanks @mfalkvidd @OldSurferDude !

The problem really was the antenna. I was using the helical antenna below and I welded in the "wrong" part of it the first time. The second I welded it on the "right" place and it work. The RSSI is still below that the old and good wire... am I welding it on the really right place?

Are helical antennas good?

Thanks again for the great support you provide.