[solved] RFM69 based nodes unable to report Lib Version

korttoma

Maybe it is just me but it seems like RFM69 based nodes are unable to report MySensors Lib Version. I noticed that none of my nodes has reported Lib version.

Debug output from a Sensebender RFM69 based node:

MCO:BGN:INIT NODE,CP=RRNNA--,VER=2.0.1-beta
TSM:INIT
TSM:INIT:TSP OK
TSM:INIT:STATID,ID=101
TSF:ASID:OK,ID=101
TSM:FPAR
TSF:MSG:SEND,101-101-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=bc:
TSF:MSG:READ,0-0-101,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=101
TSM:UPL
TSF:PING:SEND,TO=0
TSF:MSG:SEND,101-101-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
TSF:MSG:READ,0-0-101,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,101-101-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
!TSF:MSG:SEND,101-101-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=NACK:2.0.1-beta
TSF:MSG:SEND,101-101-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=1,st=OK:0
TSF:MSG:READ,0-0-101,s=255,c=3,t=6,pt=0,l=1,sg=0:M
TSF:MSG:SEND,101-101-0-0,s=255,c=3,t=11,pt=0,l=19,sg=0,ft=0,st=OK:SBenderDoorLockRF69
TSF:MSG:SEND,101-101-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.4
TSF:MSG:SEND,101-101-0-0,s=1,c=0,t=6,pt=0,l=0,sg=0,ft=0,st=OK:
TSF:MSG:SEND,101-101-0-0,s=2,c=0,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
TSF:MSG:SEND,101-101-0-0,s=3,c=0,t=0,pt=0,l=0,sg=0,ft=0,st=OK:
MCO:REG:REQ
TSF:MSG:SEND,101-101-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
TSF:MSG:READ,0-0-101,s=255,c=3,t=27,pt=1,l=1,sg=0:1
MCO:PIM:NODE REG=1
MCO:BGN:STP
Sensebender Micro FW 1.4 - Online!
isMetric: 1
TempDiff :126.18
HumDiff  :131.00
T: 26.18
H: 31
TSF:MSG:SEND,101-101-0-0,s=1,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=OK:26.2
TSF:MSG:SEND,101-101-0-0,s=2,c=1,t=1,pt=2,l=2,sg=0,ft=0,st=OK:31
TSF:MSG:SEND,101-101-0-0,s=255,c=3,t=0,pt=1,l=1,sg=0,ft=0,st=OK:91
MCO:BGN:INIT OK,ID=101,PAR=0,DIS=1,REG=1
TempDiff :0.01
HumDiff  :0.00
TSF:MSG:SEND,101-101-0-0,s=3,c=1,t=16,pt=2,l=2,sg=0,ft=0,st=OK:1
MCO:SLP:MS=60000,SMS=0,I1=1,M1=1,I2=255,M2=255
MCO:SLP:TPD
MCO:SLP:WUP=-1
TempDiff :0.21
HumDiff  :1.00
T: 25.97
H: 29
TSF:MSG:SEND,101-101-0-0,s=1,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=OK:26.0
TSF:MSG:SEND,101-101-0-0,s=2,c=1,t=1,pt=2,l=2,sg=0,ft=0,st=OK:29
MCO:SLP:MS=60000,SMS=0,I1=1,M1=1,I2=255,M2=255
MCO:SLP:TPD

Some logging from MYSController 1.0.0 Beta:

17.10.2016 9:12:02	RX	0;255;3;0;9;TSF:MSG:READ,101-101-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
17.10.2016 9:12:02	RX	0;255;3;0;9;TSF:MSG:BC
17.10.2016 9:12:02	RX	0;255;3;0;9;TSF:MSG:FPAR REQ,ID=101
17.10.2016 9:12:02	RX	0;255;3;0;9;TSF:CHKUPL:OK
17.10.2016 9:12:02	RX	0;255;3;0;9;TSF:MSG:GWL OK
17.10.2016 9:12:02	RX	0;255;3;0;9;TSF:MSG:SEND,0-0-101-101,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:PINGED,ID=101,HP=1
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:SEND,0-0-101-101,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=OK:1
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
17.10.2016 9:12:04	RX	0;255;3;0;9;!TSF:MSG:SEND,0-0-101-101,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=NACK:0100
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
17.10.2016 9:12:04	RX	101;255;3;0;6;0
17.10.2016 9:12:04	TX	101;255;3;0;6;M
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:SEND,0-0-101-101,s=255,c=3,t=6,pt=0,l=1,sg=0,ft=0,st=OK:M
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=255,c=3,t=11,pt=0,l=19,sg=0:SBenderDoorLockRF69
17.10.2016 9:12:04	RX	101;255;3;0;11;SBenderDoorLockRF69
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.4
17.10.2016 9:12:04	RX	101;255;3;0;12;1.4
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=1,c=0,t=6,pt=0,l=0,sg=0:
17.10.2016 9:12:04	RX	101;1;0;0;6;
17.10.2016 9:12:04	DEBUG	Update child id=1, type=S_TEMP
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=2,c=0,t=7,pt=0,l=0,sg=0:
17.10.2016 9:12:04	RX	101;2;0;0;7;
17.10.2016 9:12:04	DEBUG	Update child id=2, type=S_HUM
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=3,c=0,t=0,pt=0,l=0,sg=0:
17.10.2016 9:12:04	RX	101;3;0;0;0;
17.10.2016 9:12:04	DEBUG	Update child id=3, type=S_DOOR
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=255,c=3,t=26,pt=1,l=1,sg=0:2
17.10.2016 9:12:04	RX	0;255;3;0;9;TSF:MSG:SEND,0-0-101-101,s=255,c=3,t=27,pt=1,l=1,sg=0,ft=0,st=OK:1
17.10.2016 9:12:05	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=1,c=1,t=0,pt=7,l=5,sg=0:26.2
17.10.2016 9:12:05	RX	101;1;1;0;0;26.2
17.10.2016 9:12:05	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=2,c=1,t=1,pt=2,l=2,sg=0:31
17.10.2016 9:12:05	RX	101;2;1;0;1;31
17.10.2016 9:12:05	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=255,c=3,t=0,pt=1,l=1,sg=0:91
17.10.2016 9:12:05	RX	101;255;3;0;0;91
17.10.2016 9:12:05	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=3,c=1,t=16,pt=2,l=2,sg=0:1
17.10.2016 9:12:05	RX	101;3;1;0;16;1
17.10.2016 9:12:37	RX	0;255;3;0;9;TSF:SANCHK:OK
17.10.2016 9:13:09	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=1,c=1,t=0,pt=7,l=5,sg=0:26.0
17.10.2016 9:13:09	RX	101;1;1;0;0;26.0
17.10.2016 9:13:09	RX	0;255;3;0;9;TSF:MSG:READ,101-101-0,s=2,c=1,t=1,pt=2,l=2,sg=0:29
17.10.2016 9:13:09	RX	101;2;1;0;1;29
17.10.2016 9:13:37	RX	0;255;3;0;9;TSF:SANCHK:OK
17.10.2016 9:14:37	RX	0;255;3;0;9;TSF:SANCHK:OK

I'm running MySensors Lib Version 2.0.1-beta (build from a few weeks back).

EDIT: Updated to the current MySensors Lib Development build and it is stil the same.
EDIT2: I just noticed that "Parent node:" information is also empty for RFM69 nodes in my Vera Controller.

scalz

@korttoma
i'm working on rfm69 so i put this on my list ;)

korttoma

@scalz said:

@korttoma
i'm working on rfm69 so i put this on my list ;)

If you get to the point where you have something that could be tested please feel free to let me know.
I have a small setup that I use for testing so I could possibly help with testing even if I have limited hardware.

scalz

@korttoma

I have not looked at your msg version problem yet.

Well if you want to try something it's possible...so here it is:

List of changes, some notes, and current status : https://docs.google.com/spreadsheets/d/191NpTBogLPijYxS2V_oHZnVlcW4B65J1kXAqYrr4qeE/edit#gid=884074439
https://github.com/scalz/Mysensors

Don't try the listenmode for the moment plz :)
I'm not sure yet, but i think i will remove conditional define on ATC as it does not use lot of mem. etc..

Do you use softspi, w5100. I have all hardware but no time to test this part. This should work now.

Sidenote:
I'm ok to help one or two betatester only for the moment. Lucky!
Be a little bit more patient, PR should go soon now as you can see from the current status ;)

Enjoy :smiley:

TimO

I've tinkered a little w5100-RFM69-gateway lateley wich works with the softspi implementation I've tried to push the other day. I'll give your implementation a try at the weekend.

scalz

@TimO

ah okay! welcome betatester :)

hek

@korttoma

The node seems to send parent info here:

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

And myscontroller logs this:

17.10.2016 9:12:04 RX 101;255;3;0;6;0

chrille

@scalz said:

List of changes, some notes, and current status : https://docs.google.com/spreadsheets/d/191NpTBogLPijYxS2V_oHZnVlcW4B65J1kXAqYrr4qeE/edit#gid=884074439

https://github.com/scalz/Mysensors

Be a little bit more patient, PR should go soon now as you can see from the current status ;)

It's great to see work being put into the RFM69 driver. I have tried to install your code and updated my gateway and a sensor node

On the sensor node I added

sendSignalStrength(1);
sendRadioTxLevel(1);

and in the debug window I see

6899 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=29,pt=1,l=1,sg=0,ft=0,st=OK:51
7035 !TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=30,pt=1,l=1,sg=0,ft=0,st=NACK:0

Message type 30 always fails (st=NACK) - is this expected?

Gateway is ESP8266 and node is Anarduino (328p+RFM69CW)

jpaulin

@korttoma

I get exactly the same bug. I found a way to solve it, but not sure if it's the root cause.
I use RFM69W and the latest release from the Development Branch.

From your message dump:

TSF:MSG:SEND,101-101-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
!TSF:MSG:SEND,101-101-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=NACK:2.0.1-beta
TSF:MSG:SEND,101-101-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=1,st=OK:0

The Internal Presentation Message with Lib Version as payload always fails. (!TSF: c=0, t=17, st=NACK:2.0.1-beta)

The message is sent immediately after the previously sent internal message (TSF: c=3, t=15, st=OK:0100) (t=15 => I_REQUEST_SIGNING).
The Gateway responds the Signing Preference Message to the node exactly at the same time the node tries to send the Lib Version Presentation Message to the Gateway. Seems that won't work. There's no buffering?
I added a 1s delay for test purpose in MySensorsCore.cpp to give time to finish the response from the gateway before sending the Lib Version Presentation Message.

New message dump from my test-node after changes:

TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
TSF:MSG:READ,0-0-3,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
TSF:MSG:SEND,3-3-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.0.1-beta
TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0

Now a new message appears in the node, the response message from the Gateway to the Signing Preference Message, and the presentation of the Lib Version works as expected.

TSF:MSG:READ,0-0-3,s=255,c=3,t=15,pt=6,l=2,sg=0:0100 
TSF:MSG:SEND,3-3-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.0.1-beta

In MySensorsCore.cpp at line 216 I added a wait(1000); to mitigate the issue.

	// Send signing preferences for this node to the GW
	signerPresentation(_msgTmp, GATEWAY_ADDRESS);

wait(1000);

		// Send presentation for this radio node
	#if defined(MY_REPEATER_FEATURE)
		(void)present(NODE_SENSOR_ID, S_ARDUINO_REPEATER_NODE);
	#else
		(void)present(NODE_SENSOR_ID, S_ARDUINO_NODE);
	#endif

I guess the final patch would look different and would need to be looked into by @Anticimex or @hek. :smiley:

Anticimex

@jpaulin the signing backend is already waiting for the GW to send a message. So if it is not waiting long enough I believe the existing delay should be increased instead: https://github.com/mysensors/MySensors/blob/development/core/MySigning.cpp#L158

tekka

@Anticimex This is a conditional wait(), i.e. only when signing is enabled: https://github.com/mysensors/MySensors/blob/development/core/MySigning.cpp#L154-L160

Since the GW always replies to signing preferences, but the node only waits if signing is enabled - this message will eventually collide with the following lib version message, as seen above.

I suggest removing the surrounding #ifdef.

Anticimex

@tekka true. Moving the existing delay outside the preprocessor condition should help.

Anticimex

@jpaulin could you please file a pull request with the delay moved outside the preprocessor condition (as you have the rig to verify the change works)?

jpaulin

@Anticimex
I don't know how to file a pull request, so I put the test results here.

Modified as follows to remove the preprocessor condition at: https://github.com/mysensors/MySensors/blob/development/core/MySigning.cpp#L154-L160

// #if defined(MY_SIGNING_FEATURE)
    // If we do support signing, wait for the gateway to tell us how it prefer us to transmit our messages
    if (destination == GATEWAY_ADDRESS) {
	    SIGN_DEBUG(PSTR("Waiting for GW to send signing preferences...\n"));
	    wait(2000, C_INTERNAL, I_SIGNING_PRESENTATION);
}
// #endif

solves the issue.

At the same time the internal message received from the gateway seems to be erroneously transferred to the receive() function in a sketch. Adding to the sketch

void receive(const MyMessage &message) {
    Serial.println("something came in");
}

gets the message dump:

2310 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
2332 TSF:MSG:READ,0-0-3,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
something came in
2409 TSF:MSG:SEND,3-3-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.0.1-beta
2496 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0

To solve this I made the following change to _processInternalMessages(void) in MySensorsCore.cpp.
Line https://github.com/mysensors/MySensors/blob/development/core/MySensorsCore.cpp#L407 is replaced with:

	else if (type == I_SIGNING_PRESENTATION) {
	}
	else return false;

The message dump now looks like this:

2250 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
2269 TSF:MSG:READ,0-0-3,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
2331 TSF:MSG:SEND,3-3-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.0.1-beta
2441 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0

At the API description page https://www.mysensors.org/download/serial_api_20 seems to be another error.
For the internal message t=15 the name description

I_REQUEST_SIGNING 	15 	Used between sensors when initialting signing.

should be changed to

I_SIGNING_PRESENTATION 	15 	Provides signing related preferences.

This I think is relevant both for the master and the development branch.

Anticimex

@jpaulin thanks for the updates. I will have a look at making a pr when I get opportunity. @hek does the documentation issue sound familiar? ;)

Anticimex

@jpaulin I have made a pull request. My solution differs slightly from your as the I_SIGNING_PRESENTATION should never reach the _processInternalMessages function. I do however not have the ability to test so I would appreciate if you could test the PR for me?
Thanks for finding and pointing out the flaws! :D

jpaulin

@Anticimex
I updated my node and GW with your pull request and made some basic tests and it seems to work ok with my sketch. I added MY_DEBUG_VERBOSE_SIGNING and got the following messages.

From the node:

2205 TSM:READY
2220 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
2226 Waiting for GW to send signing preferences...
2280 TSF:MSG:READ,0-0-3,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
2285 Received signing presentation, but signing is not supported (message ignored)
2349 TSF:MSG:SEND,3-3-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.0.1-beta
2450 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0

From the GW:

0;255;3;0;9;TSF:MSG:PINGED,ID=3,HP=1
0;255;3;0;9;TSF:MSG:SEND,0-0-3-3,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=OK:1
0;255;3;0;9;TSF:MSG:READ,3-3-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
0;255;3;0;9;Informing node 3 that we do not require signatures because we do not support it
0;255;3;0;9;TSF:MSG:SEND,0-0-3-3,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
0;255;3;0;9;TSF:MSG:READ,3-3-0,s=255,c=0,t=17,pt=0,l=10,sg=0:2.0.1-beta
0;255;3;0;9;Sending message on topic: my_RFM69_gw1-out/3/255/0/0/17
0;255;3;0;9;TSF:MSG:READ,3-3-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0

Do you need some more testing?

Anticimex

@jpaulin thanks for testing. The change should have little effect for people using signing. The issue is for people who does not use it as the node did not wait for a gw response in that case.

korttoma

tried the latest development branch on my test system and the results are good so far. Now I just need to update my "real" system also. Thanks to everyone that participated in solving this!!

korttoma

Updated now also 2 nodes in my "real" system and both now successfully reported Lib version. I did not update the GW. Maybe it is safe to say that the Lib reporting problem is solved now.

Now I will try to look in to the sofSerial RFM69 solution that @scalz is working on, do you have any eta on when you will try to include our solution in the official MySensors development branch?
Any recommendations for the wiring of an W5100/RFM69 Gateway?

[solved] RFM69 based nodes unable to report Lib Version

9

11.7k

11.2k

113.0k