(Relay) node asks for parent. Gateway forwards (!)

[Erik Forsberg]

Hi!

I have a problem with one of my nodes, a sensor that is counting pulses on my power meter and also acts as relay. The relay functionality works fine from what I can see, but I'm not receiving any data from the power meter.

I don't have the output from the actual node available (it's in the garage..), but I see strange things happening on the gateway. Here's a typical message that reoccurs every 10s:

16-08-07 19:58:04 mysensors.mysensors: n:0 c:255 t:3 s:9 p:TSF:MSG:READ,4-4-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
16-08-07 19:58:04 mysensors.mysensors: n:0 c:255 t:3 s:9 p:TSF:MSG:BC
16-08-07 19:58:04 mysensors.mysensors: n:0 c:255 t:3 s:9 p:TSF:MSG:FPAR REQ,ID=4
16-08-07 19:58:04 mysensors.mysensors: n:0 c:255 t:3 s:9 p:TSF:CHKUPL:OK,FCTRL
16-08-07 19:58:04 mysensors.mysensors: n:0 c:255 t:3 s:9 p:TSF:MSG:GWL OK
16-08-07 19:58:05 mysensors.mysensors: n:0 c:255 t:3 s:9 p:TSF:MSG:SEND,0-0-4-4,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0

Now, I don't have the whole protocol understanding, and I just switched to 2.0.1-beta1 (directly off git) on the gateway to see if that was the problem, but if I read the above right the node (node id 4) is sending a request to get a parent, but the gateway forwards it instead of replying with a message that it is the parent.

Am I right? What could be the reason of this? Bad routing table in gateway?

Receiving messages from other nodes works w/o problems - even from nodes that pass through this troublesome node.

Gateway is running what's on development branch right now (d054c1c0c87d444c2e34e0e49f5e357e401ee209). The node is running a slightly earlier version.

Thanks!
\EF

For reference, here's my gateway code:

// Enable debug prints to serial monitor
#define MY_DEBUG 
// Enable and select radio type attached
#define MY_RADIO_NRF24

// Set LOW transmit power level as default, if you have an amplified NRF-module and
// power your radio separately with a good regulator you can turn up PA level. 
#define MY_RF24_PA_LEVEL RF24_PA_HIGH
#define MY_RF24_CHANNEL  42
// Enable serial gateway
#define MY_GATEWAY_SERIAL
// Flash leds on rx/tx/err
// #define MY_LEDS_BLINKING_FEATURE
// Set blinking period
#define MY_DEFAULT_LED_BLINK_PERIOD 300
// Set inclusion mode duration (in seconds)
#define MY_INCLUSION_MODE_DURATION 60 
// Digital pin used for inclusion mode button
#define MY_INCLUSION_MODE_BUTTON_PIN  3 

// Uncomment to override default HW configurations
//#define MY_DEFAULT_ERR_LED_PIN 4  // Error led pin
//#define MY_DEFAULT_RX_LED_PIN  6  // Receive led pin
//#define MY_DEFAULT_TX_LED_PIN  5  // the PCB, on board LED

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

void setup() { 
  // Setup locally attached sensors
}

void presentation() {
 // Present locally attached sensors 
}

void loop() { 
  // Send locally attached sensor data here 
}

[Erik Forsberg]

@Erik-Forsberg

So, replying to my own post, after looking a bit closer, it does send a reply telling the node that its parent is 0. So I guess the problem is on the other side some way. Hmm.. Need to investigate further.

[tekka]

@Erik-Forsberg The GW replies to a I_FIND_PARENT request from node 4 - nothing unusual here. I assume there is a radio/power issue with node 4 - can you get the debug log from that node?

Here is an explanation of the different GW messages

1. Node 4 sends I_FIND_PARENT request to broadcast address (=255)

TSF:MSG:READ,4-4-255,s=255,c=3,t=7,pt=0,l=0,sg=0:

2. GW receives broadcast message

TSF:MSG:BC

3. BC message is identified as I_FIND_PARENT request from node 4

TSF:MSG:FPAR REQ,ID=4

4. GW has also repeater functionality, meaning it checks the uplink (in that case to itself). Uplink is ok. FCTRL refers to "flood control", a mechanism that prevents flooding the GW with check uplink requests.

TSF:CHKUPL:OK,FCTRL
TSF:MSG:GWL OK

5. Send I_FIND_PARENT_RESPONSE to node 4

TSF:MSG:SEND,0-0-4-4,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0

Everything as expected from a GW/repeater perspective :)

[Erik Forsberg]

@tekka Thankyou! I will need to dig further another day. I will start by upgrading that troublesome node to the latest library version and see if the problem persists.

After enabling signing debug, it's now complaining a lot about the node not signing messages that should really be signed. So there could be some bug hidden in the combination of a node that makes both get and set requests, is a relay, and use soft signing.

I'll report back as soon as I find the time to make these experiments.

[tekka]

@Erik-Forsberg ok, certainly a good idea to update all nodes and GW to the most recent version - there are incompatibilities with singing and other features if used in a mixed setup.

[Erik Forsberg]

Hmm.. basically, this node works if signing is disabled. If it's enabled, all the nonce requests fail to transmit (with st=NACK). Disabling signing, it has greater success in transferring its data.

So I guess it's yet another problem with the radio. I suspected this.

This is an NRF24L01+PA+LNA module. I have:

• Tried multiple radio modules to rule out a faulty one.
• Put the radio module on a dedicated 3.3V power regulator.
• Tried both high and low PA level.
• Same thing on gateway - NRF24L01+PA+LNA, on dedicated 3.3V power regulator.

It seems to succeed in most cases, at least when it's sending just a set request. Presentations and others do not work. It's like it's having trouble transmitting longer messages. Odd.

The code in this sketch is using an interrupt handler to count pulsess on my energy meter. Could this be related?

Some debug output from the node, with signing disabled:

MCO:BGN:INIT REPEATER,CP=RNNRA--,VER=2.0.1-beta
TSM:INIT
TSM:INIT:TSP OK
TSF:ASID:OK,ID=4
TSM:FPAR
TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=bc:
TSF:MSG:READ,0-0-4,s=255,c=3,t=8,pt=1,l=1,sg=0:0
TSF:MSG:FPAR RES,ID=0,D=0
TSF:MSG:FPAR OK,ID=0,D=1
TSM:FPAR:OK
TSM:ID
TSM:ID:OK,ID=4
TSM:UPL
TSF:PING:SEND,TO=0
TSF:MSG:SEND,4-4-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
TSF:MSG:READ,0-0-4,s=255,c=3,t=25,pt=1,l=1,sg=0:1
TSF:MSG:PONG RECV,HP=1
TSF:CHKUPL:OK
TSM:UPL:OK
TSM:READY
TSF:MSG:SEND,4-4-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
!TSF:MSG:SEND,4-4-0-0,s=255,c=0,t=18,pt=0,l=10,sg=0,ft=0,st=NACK:2.0.1-beta
TSF:MSG:SEND,4-4-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=1,st=OK:0
TSF:MSG:READ,0-0-4,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
TSF:MSG:READ,0-0-4,s=255,c=3,t=6,pt=0,l=1,sg=0:M
!TSF:MSG:SEND,4-4-0-0,s=255,c=3,t=11,pt=0,l=12,sg=0,ft=0,st=NACK:Energy Meter
TSF:MSG:SEND,4-4-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=1,st=OK:1.1
TSF:MSG:SEND,4-4-0-0,s=4,c=0,t=13,pt=0,l=0,sg=0,ft=0,st=OK:
MCO:REG:REQ
TSF:MSG:SEND,4-4-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
TSF:MSG:READ,0-0-4,s=255,c=3,t=27,pt=1,l=1,sg=0:1
MCO:PIM:NODE REG=1
setup(). Radio Channel is 42
TSF:MSG:SEND,4-4-0-0,s=4,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
MCO:BGN:INIT OK,ID=4,PAR=0,DIS=1,REG=1
TSF:MSG:READ,0-0-4,s=4,c=1,t=24,pt=0,l=7,sg=0:7418044
Received last pulse count from gw:7418044
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=17,pt=5,l=4,sg=0,ft=0,st=OK:3169
Watt:3169
!TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=24,pt=5,l=4,sg=0,ft=0,st=NACK:7418088
!TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=18,pt=7,l=5,sg=0,ft=1,st=NACK:741.8089
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=17,pt=5,l=4,sg=0,ft=2,st=OK:3156
Watt:3156
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=24,pt=5,l=4,sg=0,ft=0,st=OK:7418132
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=18,pt=7,l=5,sg=0,ft=0,st=OK:741.8133
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=17,pt=5,l=4,sg=0,ft=0,st=OK:3169
Watt:3169
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=24,pt=5,l=4,sg=0,ft=0,st=OK:7418177
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=18,pt=7,l=5,sg=0,ft=0,st=OK:741.8177
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=17,pt=5,l=4,sg=0,ft=0,st=OK:7311
Watt:7241
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=24,pt=5,l=4,sg=0,ft=0,st=OK:7418249
TSF:MSG:SEND,4-4-0-0,s=4,c=1,t=18,pt=7,l=5,sg=0,ft=0,st=OK:741.8249```