RFM69 RPI3 gateway

[rozpruwacz]

Hi,

I'm trying to switch from nrf24 to rfm69 so I bought some nrf2rfm69 boards and begin testing. I have a working node and sarial gateway on arduingo uno. Now I want to run a gateway on my rpi3 and have some problems. I'm pretty sure about the wiring, i just replaced the nrf24 module with nrf2rfm69 and I connected the DI0 pin to gpio25 - this is the only difference in wiring between nrf24 and rfm69 (for nrf24 the gpio25 pin is the ce pin). Now the gateway seems to run ok, and my node is comunicating with the gateway. Next I wrote a python script to ping the node with heartbeat messages and the result is very poor, less that 10% messages have replies. If I connect the arduino gateway to the same rpi and launch the same python script I have 100% replies. Oh, and I'm using the latest developement branch on node and on gateway. This can't be the problem with the node, because it works without any problems with arduino gateway. I tried two rfm69 modules on rpi, one normal and one high gain - same result. The radio module is powered from the separate LM1117 ldo so it should not be the power issue. I don't know what else I can check to find the issue. Any ideas ?

[gohan]

What do you see in gateway debug and node debug?

[rozpruwacz]

this is from the gateway:

mysgw: Starting gateway...
mysgw: Protocol version - 2.2.0-rc.2
mysgw: Serial port /dev/ttyMySensorsGateway (115200 baud) created
mysgw: MCO:BGN:INIT GW,CP=RPNGL---,VER=2.2.0-rc.2
mysgw: TSF:LRT:OK
mysgw: TSM:INIT
mysgw: TSF:WUR:MS=0
mysgw: TSM:INIT:TSP OK
mysgw: TSM:INIT:GW MODE
mysgw: TSM:READY:ID=0,PAR=0,DIS=0
mysgw: MCO:REG:NOT NEEDED
mysgw: MCO:BGN:STP
mysgw: MCO:BGN:INIT OK,TSP=1
mysgw: !TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=NACK:0
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:1876502
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:1910901
mysgw: TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=OK:0
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:1911910
mysgw: !TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=NACK:0
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:1912932
mysgw: !TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=NACK:0
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:1914521
mysgw: !TSF:MSG:SEND,0-0-11-11,s=255,c=3,t=18,pt=0,l=1,sg=0,ft=0,st=NACK:0
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:1916842
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:1975572
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2035573
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2095573
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2155573
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2215573
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2275572
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2335572
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2395572
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2455572
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2515573
mysgw: TSF:MSG:READ,11-11-0,s=255,c=3,t=22,pt=5,l=4,sg=0:2575573

don't have debug logs from the node, I'll check them tomorrow. For me the gateway log looks like the replies from the node are delayed.

[gohan]

You need to compare both log side to side and see what happens in the node if it is actually replying or just receiving the message late

[rozpruwacz]

OK, I get very weird results. So I enabled logging in my node and at first it was hard to tell what was going on. I would say that rather every message from the gateway was received in the node and I had some nacks for messages sent to the gateway. Gateway and node has some retry policy so after first failure in the gateway i get mess in the logs. The node is retrying to send back the heartbeat and gateway sends again previous heartbeat and it gets choked. So I compiled the node with MY_PASSIVE_NODE and I changed in the RFM69_RETRIES in the RFM69_new.h to 0. And now I get around 95% success ! It seems that the first failure causes the domino effect.

[rozpruwacz]

So RFM69_TX_LIMIT_MS is 200ms and if I revert the RFM69_RETRIES to 5 then it is around 1s maximum time for sending one message in the gateway. Taking this into account if I run my test with 2 seconds interval between heartbeats I should not have the domino effect if some heartbeat does not get back to gateway. And indeed it is much better. So to sum up - it seems like the gateway running on rpi gets choked if there are communication errors and there is a lot of messages to send. I the send interval is more than 2 seconds it seems to work ok. The Arduino gateway handles this much better.

[gohan]

@tekka do you have any idea about this timing issue?

[tekka]

@gohan Maybe: RFM69 and RFM95 have a software-based packet engine responsible for the ACK handling, i.e. with extreme clock differences between node and GW, TX from (fast) GW may occur before the radio of the (slow) node is in RX, that's why we introduced additional delays for faster CPUs. I had no issues running the code on RPI1 (0.7GHz) and RPI2 (0.9GHz), but I do not have a RPI3(1.2GHz) where additional timing optimizations may be needed.