Problem with ID_REQUEST

[Tang]

Hi

I have some trouble with new id request.
I uploaded fresh repeater or dallas temperature sketch to arduino nano and the sensor always request me its id.

Here is the output of my controller

RECEIVING: 0/0;INTERNAL;0;I_LOG_MESSAGE;read: 255-255-0 s=255,c=3,t=3,pt=0,l=0,sg=0:
RECEIVING: 255/255;INTERNAL;0;I_ID_REQUEST;
SENDING: 255;255;3;1;4;150
...

And the output of sensor:

sensor started, id=255, parent=0, distance=1
req id
send: 255-255-0-0 s=255,c=3,t=3,pt=0,l=0,sg=0,st=ok:
req id
send: 255-255-0-0 s=255,c=3,t=3,pt=0,l=0,sg=0,st=ok:
req id
send: 255-255-0-0 s=255,c=3,t=3,pt=0,l=0,sg=0,st=ok:
req id
send: 255-255-0-0 s=255,c=3,t=3,pt=0,l=0,sg=0,st=ok:

I tested it on 3 differents sensors with different hardwares (nano for both and mini 5v with 3 differents NRF with 47µF and 4.7µF). My controller is near the tested sensors and have a 4.7µF cap too.
I also tested with NRF of working sensor. And i tryed differents power supplies (computer USB, external power supply (5v 2A))
All other 3 sensors are working perfectly at the same time.

I don't know how to investigate more. Is something changed on 1.5 about ID_REQUEST ?

Thank you for your help

[Tang]

By the way, i have no problem if i force the sensor id using gw.begin(NULL, XXX) at startup.
I'm really lost about this issue :S

[sundberg84]

Did you clear the eeprom before reuploading the scetch?

[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