Problem with ID_REQUEST

tedstriker

Hi there,
I've got exactly the same issue. Same log output, same behavior. I checked the nodes eeprom content at address 0 (node id) and it seems not to get updated. It's value is still 255, but controller address and distance have been updated in the eeprom.
I already erased the flash memory, but it's still not working. As radio I use RFM69HW. I took into account it's highpower and added the flag in its constructor:

MyTransportRFM69 radio (RFM69_FREQUENCY, RFM69_NETWORKID, RF69_SPI_CS, RF69_IRQ_PIN, true, RF69_IRQ_NUM);

Using Tangs workaround with a fixed ID gw.begin(NULL, ###) made it run for the first time! Thanks for that @Tang ;)
I really have no clue why it's not working and any hint is appreciated.

Tang

@sundberg84 said:

Did you clear the eeprom before reuploading the scetch?

Yep it's the first thing i did.

hek

How does the gateway log look like when id request comes in and being sent?

Tang

@hek said:

How does the gateway log look like when id request comes in and being sent?

It looks like that

0;0;3;0;9;read: 255-255-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;0;3;0;9;send: 0-0-255-255 s=255,c=3,t=8,pt=1,l=1,sg=0,st=bc:0
0;0;3;0;9;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
255;255;3;0;3;
0;0;3;0;9;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
255;255;3;0;3;
0;0;3;0;9;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
255;255;3;0;3;
0;0;3;0;9;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
255;255;3;0;3;
0;0;3;0;9;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
255;255;3;0;3;

After sensor sends its ID_REQUEST command i send (within 2 seconds) this message 255;255;3;0;4;150 but no response from sensor.
I'm not familiar with cutecom, i suppose when i write something in input field and press enter, message is sent properly?

hek

Looks like gateway is receiving id-request (t=4) but does not send any id-resonse (t=4).
Even though the controller log says ("SENDING: 255;255;3;1;4;150"). So somehow the messages get lost on the serial line?

The only strange thing I can see is that it sends this with ack (forth argument=1) enabled.

Tang

The ack set to 1 was just a test. I tryed first with 0
So no idea of my problem ... :S

Tang

I just tryed with new gateway and development branch and same result...

I reverted back to 1.4.2 without problem. The sensor sends its ID_REQUEST, my controller sends the reply and startup is complete.
I suppose there is something new in 1.5 that is not correct.

Sparkman

@Tang Which controller are you using? I've added new nodes under 1.5 and it worked fine for me with the controller I have (HomeSeer).

Cheers
Al

Tang

@Sparkman I'm using agocontrol. I'm developping mysensors module.
The problem is my controller seems to have the good behaviour but the gateway does nothing.
Like Hek said it's like the frame is lost during serial transfer, but I have doubt about it.
A downgrade of my gateway to 1.4.2 version fixes the problem. My controller sends exactly the same frame (SENDING: 255;255;3;0;4;2)

015-Aug-19 11:22:48.806905 [DEBUG]  => 09:22:48 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0:
2015-Aug-19 11:22:48.808057 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:48.808084 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:48.808113 [DEBUG]  => 09:22:48 2015/08/19 RECEIVING: 255/255;INTERNAL;0;I_ID_REQUEST;
2015-Aug-19 11:22:48.808276 [DEBUG] Free id found: 2
2015-Aug-19 11:22:48.808354 [DEBUG]  => SENDING: 255;255;3;0;4;2
2015-Aug-19 11:22:48.853276 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:48.853309 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:48.853338 [DEBUG]  => 09:22:48 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;send: 0-0-255-255 s=255,c=3,t=4,pt=0,l=1,st=fail:2
2015-Aug-19 11:22:48.857694 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:48.857715 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:48.857745 [DEBUG]  => 09:22:48 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 2-2-0 s=255,c=0,t=17,pt=0,l=5:1.4.2
2015-Aug-19 11:22:48.859906 [TRACE] Use protocol version found in current message
2015-Aug-19 11:22:48.859925 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:48.859952 [DEBUG]  => 09:22:48 2015/08/19 RECEIVING: 2/255;PRESENTATION;0;S_ARDUINO_NODE;1.4.2
2015-Aug-19 11:22:48.859976 [WARNING] PRESENTATION subtype '17' not supported (protocol v1.4)
2015-Aug-19 11:22:48.864316 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:48.864316 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:48.864336 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:48.864363 [DEBUG]  => 09:22:48 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 2-2-0 s=255,c=3,t=6,pt=1,l=1:0
2015-Aug-19 11:22:48.864452 [TRACE] protocol found: 
2015-Aug-19 11:22:48.864480 [DEBUG]  => 09:22:48 2015/08/19 RECEIVING: 2/255;INTERNAL;0;I_CONFIG;0
2015-Aug-19 11:22:48.864499 [WARNING] Error: no protocol version found for this message, drop it
2015-Aug-19 11:22:50.814719 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:50.814794 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:50.814827 [DEBUG]  => 09:22:50 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 2-2-0 s=255,c=0,t=17,pt=0,l=5:1.4.2
2015-Aug-19 11:22:50.816996 [TRACE] Use protocol version found in current message
2015-Aug-19 11:22:50.817017 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:50.817044 [DEBUG]  => 09:22:50 2015/08/19 RECEIVING: 2/255;PRESENTATION;0;S_ARDUINO_NODE;1.4.2
2015-Aug-19 11:22:50.817067 [WARNING] PRESENTATION subtype '17' not supported (protocol v1.4)
2015-Aug-19 11:22:50.821411 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:50.821432 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:50.821460 [DEBUG]  => 09:22:50 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 2-2-0 s=255,c=3,t=6,pt=1,l=1:0
2015-Aug-19 11:22:50.822611 [TRACE] protocol found: 
2015-Aug-19 11:22:50.822640 [DEBUG]  => 09:22:50 2015/08/19 RECEIVING: 2/255;INTERNAL;0;I_CONFIG;0
2015-Aug-19 11:22:50.822660 [WARNING] Error: no protocol version found for this message, drop it
2015-Aug-19 11:22:52.827945 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:52.828028 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:52.828060 [DEBUG]  => 09:22:52 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 2-2-0 s=255,c=3,t=11,pt=0,l=18:Temperature Sensor
2015-Aug-19 11:22:52.830376 [TRACE] protocol found: 
2015-Aug-19 11:22:52.830412 [DEBUG]  => 09:22:52 2015/08/19 RECEIVING: 2/255;INTERNAL;0;I_SKETCH_NAME;Temperature Sensor
2015-Aug-19 11:22:52.830433 [WARNING] Error: no protocol version found for this message, drop it
2015-Aug-19 11:22:52.834780 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:52.834802 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:52.834830 [DEBUG]  => 09:22:52 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 2-2-0 s=255,c=3,t=12,pt=0,l=3:1.0
2015-Aug-19 11:22:52.837054 [TRACE] protocol found: 
2015-Aug-19 11:22:52.837086 [DEBUG]  => 09:22:52 2015/08/19 RECEIVING: 2/255;INTERNAL;0;I_SKETCH_VERSION;1.0
2015-Aug-19 11:22:52.837115 [WARNING] Error: no protocol version found for this message, drop it
2015-Aug-19 11:22:52.840755 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:52.840783 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:52.840811 [DEBUG]  => 09:22:52 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 2-2-0 s=0,c=0,t=6,pt=0,l=0:
2015-Aug-19 11:22:52.841915 [TRACE] protocol found: 
2015-Aug-19 11:22:52.841945 [DEBUG]  => 09:22:52 2015/08/19 RECEIVING: 2/0;PRESENTATION;0;S_TEMP;
2015-Aug-19 11:22:52.841965 [WARNING] Error: no protocol version found for this message, drop it
2015-Aug-19 11:22:53.729763 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:22:53.729837 [TRACE] protocol found: 1.4.2
2015-Aug-19 11:22:53.729869 [DEBUG]  => 09:22:53 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 2-2-0 s=0,c=1,t=0,pt=7,l=5:26.9
2015-Aug-19 11:22:53.731027 [TRACE] protocol found: 
2015-Aug-19 11:22:53.731058 [DEBUG]  => 09:22:53 2015/08/19 RECEIVING: 2/0;SET;0;V_TEMP;26.9

While I have it on 1.5

2015-Aug-19 11:17:24.437051 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:17:24.437124 [TRACE] protocol found: 1.5
2015-Aug-19 11:17:24.437157 [DEBUG]  => 09:17:24 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
2015-Aug-19 11:17:24.437250 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:17:24.437269 [TRACE] protocol found: 1.5
2015-Aug-19 11:17:24.437298 [DEBUG]  => 09:17:24 2015/08/19 RECEIVING: 255/255;INTERNAL;0;I_ID_REQUEST;
2015-Aug-19 11:17:24.437464 [DEBUG] Free id found: 2
2015-Aug-19 11:17:24.437540 [DEBUG]  => SENDING: 255;255;3;0;4;2
2015-Aug-19 11:17:26.448202 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:17:26.448284 [TRACE] protocol found: 1.5
2015-Aug-19 11:17:26.448316 [DEBUG]  => 09:17:26 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
2015-Aug-19 11:17:26.449473 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:17:26.449494 [TRACE] protocol found: 1.5
2015-Aug-19 11:17:26.449524 [DEBUG]  => 09:17:26 2015/08/19 RECEIVING: 255/255;INTERNAL;0;I_ID_REQUEST;
2015-Aug-19 11:17:26.449689 [DEBUG] Free id found: 2
2015-Aug-19 11:17:26.449765 [DEBUG]  => SENDING: 255;255;3;0;4;2
2015-Aug-19 11:17:28.455924 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:17:28.456006 [TRACE] protocol found: 1.5
2015-Aug-19 11:17:28.456039 [DEBUG]  => 09:17:28 2015/08/19 RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
2015-Aug-19 11:17:28.457196 [TRACE] Use protocol version of gateway (gateway or broadcast message)
2015-Aug-19 11:17:28.457217 [TRACE] protocol found: 1.5
2015-Aug-19 11:17:28.457245 [DEBUG]  => 09:17:28 2015/08/19 RECEIVING: 255/255;INTERNAL;0;I_ID_REQUEST;
2015-Aug-19 11:17:28.457409 [DEBUG] Free id found: 2
2015-Aug-19 11:17:28.457485 [DEBUG]  => SENDING: 255;255;3;0;4;2

As you can see on sample above, on 1.4.2 the id is requested only once ("Free id found...")and all other mysensors stuff is normal while on 1.5 the sensor always requesting an id.
The code is quite the same between 1.4.X and 1.5 protocol handling and there is absolutely no difference between ID_REQUEST on 1.4.X and 1.5. Both of functions are using the same code to send data to gateway.

In view of those outputs, I don't know how to investigate more on my controller side... but good to know it works on other controller ;)
Maybe somebody has a manual procedure using an external tool and tell me how to test it :p

hek

Weird, sure that id-response adds a newline?

Does it work if you just hook up your gateway to the Arduino IDE Serial Monitor? And reply to the id-request over there (remember to turn on newline/carriage return).

Tang

I tryed with arduino IDE with "Both NL & CR" activated and the sensors received a new ID.

Here is full output of gateway:

0;0;3;0;9;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0:
255;255;3;0;3;
0;0;3;0;9;send: 0-0-255-255 s=255,c=3,t=4,pt=0,l=1,st=fail:2
0;0;3;0;9;read: 2-2-0 s=255,c=0,t=17,pt=0,l=3:1.5
2;255;0;0;17;1.5
0;0;3;0;9;read: 2-2-0 s=255,c=3,t=6,pt=1,l=1:0
2;255;3;0;6;0
0;0;3;0;9;read: 2-2-0 s=255,c=0,t=17,pt=0,l=3:1.5
2;255;0;0;17;1.5
0;0;3;0;9;read: 2-2-0 s=255,c=3,t=6,pt=1,l=1:0
2;255;3;0;6;0
0;0;3;0;9;read: 2-2-0 s=255,c=3,t=11,pt=0,l=18:Temperature Sensor
2;255;3;0;11;Temperature Sensor
0;0;3;0;9;read: 2-2-0 s=255,c=3,t=12,pt=0,l=3:1.1
2;255;3;0;12;1.1
0;0;3;0;9;read: 2-2-0 s=0,c=0,t=6,pt=0,l=0:
2;0;0;0;6;
0;0;3;0;9;read: 2-2-0 s=0,c=1,t=0,pt=7,l=5:26.2
2;0;1;0;0;26.2

I will try tomorrow to update my controller sending \n\r at end of command.
Until now it seems my controller doesn't send it. Is it something new in 1.5 protocol to handle \n\r as end of command or it is a lack of my controller since the beginning?

hek

I cannot recall changing anything about how this is handled between 1.4->1.5.

Tang

Adding NL+CR to sent command fixed my problem.
Weird everything worked before 1.5. Anyway no problem now :D

Thank you for your help guys ;-)

bjacobse

@Tang Does this means that you will update some code in Agocontrol?
I also uses Agocontrol and have upgraded mysensors to ver 1.5, and I'm not able to add new sensors

Tang

@bjacobse yes i'm working on it
I just need to fix some stuff on actuator and it should be good

bjacobse

@Tang Perfect,
Let me know if I can do some testing/verification for you

Tang

@bjacobse said:

@Tang Perfect,
Let me know if I can do some testing/verification for you

I commited my stuff. You can make a try and tell me all bugs you found ;-)
Please use irc now. Thx

bjacobse

Thank you Tang, works perfekt now

Problem with ID_REQUEST

18

11.7k

11.2k

113.1k