Radio FAIL after ~3 weeks [SOLVED]

Reza

0 MCO:BGN:INIT REPEATER,CP=RNNRA--,VER=2.0.1-beta
4 TSM:INIT
11 TSM:INIT:TSP OK
12 TSM:INIT:STATID=4
14 TSF:SID:OK,ID=4
16 TSM:FPAR
52 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2059 !TSM:FPAR:NO REPLY
2061 TSM:FPAR
2097 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2830 TSF:MSG:READ,2-2-4,s=255,c=3,t=8,pt=1,l=1,sg=0:1
2835 TSF:MSG:FPAR OK,ID=2,D=2
4105 TSM:FPAR:OK
4106 TSM:ID
4107 TSM:ID:OK
4109 TSM:UPL
4146 !TSF:MSG:SEND,4-4-2-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=NACK:1
6153 TSM:UPL
6190 !TSF:MSG:SEND,4-4-2-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=1,st=NACK:1
8197 TSM:UPL
8233 !TSF:MSG:SEND,4-4-2-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=2,st=NACK:1
10241 TSM:UPL
10277 !TSF:MSG:SEND,4-4-2-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=3,st=NACK:1
12285 !TSM:UPL:FAIL
12286 TSM:FPAR
12323 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=4,st=OK:
14332 !TSM:FPAR:NO REPLY
14334 TSM:FPAR
14371 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
16378 !TSM:FPAR:NO REPLY
16380 TSM:FPAR
16417 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
18424 !TSM:FPAR:NO REPLY
18426 TSM:FPAR
18463 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
20470 !TSM:FPAR:FAIL
20471 TSM:FAIL:CNT=1
20473 TSM:FAIL:PDT
30476 TSM:FAIL:RE-INIT
30478 TSM:INIT
30485 TSM:INIT:TSP OK
30487 TSM:INIT:STATID=4
30489 TSF:SID:OK,ID=4
30491 TSM:FPAR
30528 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
32535 !TSM:FPAR:NO REPLY
32537 TSM:FPAR
32574 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
34581 !TSM:FPAR:NO REPLY
34583 TSM:FPAR
34620 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
36627 !TSM:FPAR:NO REPLY
36629 TSM:FPAR
36666 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:

tboha

@Reza I got your nodes behavior mostly reproduced (see protocol below).
Only difference:

2097 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2830 TSF:MSG:READ,2-2-4,s=255,c=3,t=8,pt=1,l=1,sg=0:1
2835 TSF:MSG:FPAR OK,ID=2,D=2
4105 TSM:FPAR:OK
4106 TSM:ID

In my network I got direct connections to my gateway.
so most messages in your logs document all nodes broadcasting all the time searching for your gateway and getting no response.
If there is no connection - there can be no ACK.

Would you please check your gateway sketch for the RF-channel in use?

Protocol with non matching RF-channel (#define MY_RF24_CHANNEL 0)

0 MCO:BGN:INIT REPEATER,CP=RNNRA--,VER=2.1.0
3 TSM:INIT
4 TSF:WUR:MS=0
11 TSM:INIT:TSP OK
13 TSM:INIT:STATID=5
15 TSF:SID:OK,ID=5
17 TSM:FPAR
53 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2060 !TSM:FPAR:NO REPLY
2062 TSM:FPAR
2098 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
4105 !TSM:FPAR:NO REPLY
4107 TSM:FPAR
4143 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
6150 !TSM:FPAR:NO REPLY
6152 TSM:FPAR
6188 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
8195 !TSM:FPAR:FAIL
8196 TSM:FAIL:CNT=1
8198 TSM:FAIL:PDT
18201 TSM:FAIL:RE-INIT
18203 TSM:INIT
18210 TSM:INIT:TSP OK
18212 TSM:INIT:STATID=5
18214 TSF:SID:OK,ID=5
18216 TSM:FPAR
18253 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
20260 !TSM:FPAR:NO REPLY
20262 TSM:FPAR
20298 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
22306 !TSM:FPAR:NO REPLY
22308 TSM:FPAR
22344 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
24352 !TSM:FPAR:NO REPLY
24354 TSM:FPAR
24390 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
26398 !TSM:FPAR:FAIL
26399 TSM:FAIL:CNT=2
26401 TSM:FAIL:PDT

Protocol with matching RF-Channel (without #define MY_RF24_CHANNEL 0,i.e. using default channel)

0 MCO:BGN:INIT REPEATER,CP=RNNRA--,VER=2.1.0
3 TSM:INIT
4 TSF:WUR:MS=0
11 TSM:INIT:TSP OK
13 TSM:INIT:STATID=5
15 TSF:SID:OK,ID=5
17 TSM:FPAR
53 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2060 !TSM:FPAR:NO REPLY
2062 TSM:FPAR
2098 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2377 TSF:MSG:READ,14-14-5,s=255,c=3,t=8,pt=1,l=1,sg=0:1
2382 TSF:MSG:FPAR OK,ID=14,D=2
2811 TSF:MSG:READ,0-0-5,s=255,c=3,t=8,pt=1,l=1,sg=0:0
2817 TSF:MSG:FPAR OK,ID=0,D=1
3289 TSF:MSG:READ,7-7-5,s=255,c=3,t=8,pt=1,l=1,sg=0:2
3734 TSF:MSG:READ,4-4-5,s=255,c=3,t=8,pt=1,l=1,sg=0:1
4105 TSM:FPAR:OK
4106 TSM:ID
4107 TSM:ID:OK
4109 TSM:UPL
4112 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
4118 TSF:MSG:READ,0-0-5,s=255,c=3,t=25,pt=1,l=1,sg=0:1
4123 TSF:MSG:PONG RECV,HP=1
4126 TSM:UPL:OK
4127 TSM:READY:ID=5,PAR=0,DIS=1
4132 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
4139 TSF:MSG:READ,0-0-5,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
4146 TSF:MSG:SEND,5-5-0-0,s=255,c=0,t=18,pt=0,l=5,sg=0,ft=0,st=OK:2.1.0
4155 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
4584 TSF:MSG:READ,0-0-5,s=255,c=3,t=6,pt=0,l=6,sg=0:Metric
4590 TSF:MSG:ACK REQ
4594 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=6,pt=0,l=6,sg=0,ft=0,st=OK:Metric
4602 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=11,pt=0,l=6,sg=0,ft=0,st=OK:RELAY6
4611 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:0.1
4620 TSF:MSG:SEND,5-5-0-0,s=1,c=0,t=3,pt=0,l=8,sg=0,ft=0,st=OK:Relais A
4628 TSF:MSG:SEND,5-5-0-0,s=2,c=0,t=3,pt=0,l=8,sg=0,ft=0,st=OK:Relais B
4637 TSF:MSG:SEND,5-5-0-0,s=3,c=0,t=3,pt=0,l=8,sg=0,ft=0,st=OK:Relais C
4645 TSF:MSG:SEND,5-5-0-0,s=4,c=0,t=3,pt=0,l=8,sg=0,ft=0,st=OK:Relais D
4655 TSF:MSG:SEND,5-5-0-0,s=5,c=0,t=3,pt=0,l=8,sg=0,ft=0,st=OK:Relais E
4663 TSF:MSG:SEND,5-5-0-0,s=6,c=0,t=3,pt=0,l=8,sg=0,ft=0,st=OK:Relais F
4670 MCO:REG:REQ
4673 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
4679 TSF:MSG:READ,0-0-5,s=255,c=3,t=27,pt=1,l=1,sg=0:1
4684 MCO:PIM:NODE REG=1
4686 MCO:BGN:STP
4714 TSF:MSG:READ,0-0-5,s=255,c=3,t=6,pt=0,l=6,sg=0:Metric
5688 MCO:BGN:INIT OK,TSP=1
7503 TSF:MSG:READ,8-8-5,s=255,c=3,t=8,pt=1,l=1,sg=0:1
7508 !TSF:MSG:FPAR INACTIVE
loop_count: 36610
loop_count: 85099
loop_count: 85091
31153 TSF:MSG:SEND,5-5-0-0,s=1,c=1,t=2,pt=7,l=5,sg=0,ft=0,st=OK:0.0
Switch A pressed
34217 TSF:MSG:SEND,5-5-0-0,s=1,c=1,t=2,pt=7,l=5,sg=0,ft=0,st=OK:1.0
Switch A pressed
36277 TSF:MSG:SEND,5-5-0-0,s=1,c=1,t=2,pt=7,l=5,sg=0,ft=0,st=OK:0.0
Switch A pressed
loop_count: 84876

Which kind of Gateway are you using?

Reza

@tboha
i use #define MY_RF24_CHANNEL 0 and all of node are #define MY_RF24_CHANNEL 0

tboha

@Reza
Based on your answer I have to confess I didn´t read your log carefully enough - being fixed to missing ACKs I didn´t pay attention to successful transmissions.

Difference between Node 160 log and Node 4 log is the complete absence of any messages from Node 0 (GW) in Node 160 log, whereas in Node 4 log there are answers from GW.

So my next question would be: are these failures consistent?

If you are not feed up already, would you please log some boot sequences from Node 4? And some button-presses too?

I think it would be interesting if failures are the exact identical or just almost identical.
(exact identical favors software problem, almost identical favors hardware problem).

A parallel log from the GW would be nice too. Maybe there is a problem in the ACK system.

If you don´t trust your OrangePi hardware - would a temporarily switch to Laptop/Windows/Linux make much effort? Just to prove integrity of GW-Arduino and radio.

tboha

@Reza
I forgot - you are completely right. Why is there any need for a repeater node in between at 1m distance?

To get a clean solution you could isolate your GW and Node 4 by changing RF-channels and have a look at their private conversation without being disturbed by other (healthy) nodes.

Jan Gatzke

Coul it be you are using modules with different chips? See https://forum.mysensors.org/topic/1153/we-are-mostly-using-fake-nrf24l01-s-but-worse-fakes-are-emerging

Reza

@tboha
sorry for english
generally , my problem is connection.
i have a controller (domoticz on orangepi) and one serial gateway with usb cable to controller. and some sensors in all of house (Sporadic) and some relay for test just in my room. id 4 or 160 is choose random for test. i am near controller and test some sketch, some relay , radio and etc...
so my problem is just connection between relays and gateway. sensors is good and work well and report all of states. but relays. first can not connection and show error :
(4143 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
6150 !TSM:FPAR:NO REPLY
6152 TSM:FPAR
6188 TSF:MSG:SEND,5-5-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
8195 !TSM:FPAR:FAIL
8196 TSM:FAIL:CNT=1
8198 TSM:FAIL:PDT)
but after some time (with some power off/on) relay can connect to gateway . but after connect this is very unstable and some command send and some command dont send and show error ( NACK...)
i test and i change hardware and sketch but dont resolve :(

A parallel log from the GW would be nice too. Maybe there is a problem in the ACK system.

this is a solution ?please explain more . what am i do ?
use a repeater near gateway and use this for connect all of relays to gateway?

Reza

@Jan-Gatzke
my radios is not fake. i use 3 type of radio nrf+ but i have problem

Jan Gatzke

@Reza

Can you try to add the following line to your sketch?

#define MY_RF24_PA_LEVEL RF24_PA_LOW

Right at the top, along with the other defines. I had similar problems with a LED Dimmer node. This solved the problem.

tboha

@Reza No, an additional repeater was not intended (though it may be a solution).
From your "Node 4" log I conclude:

you got at least 3 fully functional nodes (node 2,3,4). These nodes talk to each other in the environment of MySensors in an expected way.
so hardware (radio and power) is ok. Software is ok too.
GW functionality is partially ok - maybe hard- or software issues.

Now there is a decision to make: go on testing potentially defective hardware or start over with known intact hardware.

Go on testing means: are this failures reproducible? So I asked for logs of repeated boot sequences.
Until now we don´t know the exact failure. The parallel log from Gateway would show if there are really missing transmissions (and the extent of missing messages) or only missing ACKs.
I used ACKs last time in MySensors 1.4 and those days it made more trouble than profit. At last is showed up transmissions were ok (enough) the ACK system was not ok.
For my purposes MySensors keeps up with transmission difficulties so I have not to care about (15m Distance, in house, reinforced concrete). So I decided not to use ACKs anymore and this did not reduce performance.

If there are not to many missing transmissions (compare node messages vs. GW messages) I would skip the whole ACK thing.

I would test potentially defective hardware first because it is easy to get some logs an costs not much time.
Jan Gatzkes proposal is done quickly too.

An additional repeater would only obscure severe GW-problems. For the GW is the heart of MySensors system - you should not tolerate any problems (hard- or software) because it will come on top again in the very near future.

Starting over with known hardware takes more effort but should be doable in a manageable amount of time.

Reza

@Jan-Gatzke

use this just for nrf +pa+lna? now i use just usual nrf+

Reza

@tboha
i test my hardware, change these and test again with some radio and wire and arduino ....
now about parallel log .what am i do ? this is means i build 2 gateway?

tboha

@Reza No.
Parallel may not be the exact description, I meant simultaneous recording of GW and node.

I don`t know about Domoticz - maybe there is a raw log function - then you are done.

Or if you installed arduino ide on your OrangePi just use the serial monitor.

Otherwise just hook up a terminal to your gateway.
I.e. on your OrangePi look for the device GW is bound to and start some terminal program linked hereto (e.g. putty, minicom, kermit).

Reza

@tboha
i understand . ok thank you . i will test it

tboha

@Reza
Sometimes it is better to step back and have a look from the distance.

A receipe for a clean restart.

you need:

2 working Arduinos with radio (node 4 and node 3 from your log)

1 working Computer/Laptop with 2 free USB interfaces

preferably Windows with Arduino IDE installed. (Linux might work too.)
connect both arduinos to your USB ports.
if Arduinos are different - write down which Arduino is on which port (eg. com34: or similar)

start Arduino IDE
from examples/Mysensors load "Gateway serial"
2a. choose one USB/COM-port.
don´t change anything and load it to the Arduino No.1
from examples/Mysensors load "MockMySensors"
4a. choose the other USB/COM-Port
don`t change anything and load it to Arduino No.2

You are done. Watch Arduinos communicating via serial monitor.

Ok- you are right - it is not truely simultaneaus - but close enough.

If this is ok you should try to upload the relay-sketch and watch what is happening.

This should not take to long, and as a result you will hopefully know:

my hardware is ok or not
my software (MySensors) is ok or not
my sketch is ok or not.

Reza

@tboha
hi friend , i test it and when i have NACK serial monitor is :
0_1483382377534_.....jpg

Reza

@tboha
i think found problem . i was careless about parent, relay is bad working when use a parent device for connect to gateway.but when connect directly , work better . more better . but now there is 2 questions ! first i am near gateway (1meter) and relay for test is near gateway.but after start or reset , some time relay choose a node (10 m far) for parent, while gateway is near that ! why ?
i know that i can use static parent for nodes but i want know why node choose a node 10m far for parent while gateway is in near (1m)

and second question. why with a parent relay work very bad and more command dont send and there is error!? this is related to power of radio of parent ?
thank you

tboha

@Reza this is weird - i have to think about.
Just for clarification:

it seems you issued a command at your controller which results in sending

60;2;1;0;2;1

dissected:
60; = to node 60,
2; = sensor 2
1; = set value
0; = unacknowledged message (?)
2; = subtype is V_LIGHT
1; = payload is "1"

I think you hit button "Relais 2 ON" .

The weird thing is - you haven`t asked for acknowledge - but system is trying to get acknowledge ---- strange.

I just got your next question, I have to think about this too.

tboha

@Reza I think we are getting close to solution.

but after start or reset , some time relay choose a node (10 m far) for parent, while gateway is near that ! why ?

This seems to be the crucial question.
I never dived into the core functions how MySensors decides about choosing parent.
Maybe it depends upon speed of answer?

a little excerpt from an earlier log (which i didn´t read close enough, I told you).

16 TSM:FPAR
52 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2059 !TSM:FPAR:NO REPLY
2061 TSM:FPAR
2097 TSF:MSG:SEND,4-4-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2165 TSF:MSG:READ,2-2-4,s=255,c=3,t=8,pt=1,l=1,sg=0:1
2170 TSF:MSG:FPAR OK,ID=2,D=2
2340 TSF:MSG:READ,3-3-4,s=255,c=3,t=8,pt=1,l=1,sg=0:3
4105 TSM:FPAR:OK
4106 TSM:ID

at 2097 Node 4 broadcasts for parent and gets accepted for parenting from Node 2.
at 2340 Node 3 offers parenting too - upon which request?

and why doesn`t GW offer parenting ?? GW shows up at 8240 with response to PING, so it is alive and connection was ok.

at least at the moment - unexpected behavior.

So reading logs give us some hints.
Could you provide a little more from the simultaneous logs? And don´t stick to the NACK logs - the other messages are interesting as well.

tekka

@tboha
Thanks for your time and effort, you're doing an excellent analysis. Please find below some answers to your questions:

at 2097 Node 4 broadcasts for parent and gets accepted for parenting from Node 2.
at 2340 Node 3 offers parenting too - upon which request?

and why doesn`t GW offer parenting ?? GW shows up at 8240 with response to PING, so it is alive and connection was ok.

The find parent step is initiated by a local I_FIND_PARENT_REQUEST broadcast, i.e. all repeaters/GW will reply with I_FIND_PARENT_RESPONSE if their uplink connections are operational (this prevents circular referencing). Node 3 (@2340) is replying to the same request, but ignored due to a greater distance to the GW (D=3+1=4 vs D=1+1=2 from node 4). The GW does not offer parenting, because it's either too close (radio interference) or too far from the requesting node. After a timeout (default 2000ms) the node uses the closest repeater/GW that replied to the request unless a static/preferred parent is defined.

Radio FAIL after ~3 weeks [SOLVED]

23

11.7k

11.2k

113.0k