Requesting variables reliably - how?

[mfalkvidd]

I am writing some code that fetches a variable from Domoticz. The sensor is battery powered so I want to minimize wake time and radio usage.

My tests show that if a gw.request is successfully sent, the response comes 3-4 seconds later. If the gw.request fails, a response might still come but not always.

code:

void setup()
{
  Serial.begin(BAUD_RATE);
  gw.begin(incomingMessage);

  gw.sendSketchInfo("Plant moisture w bat", "1.6");
  Serial.println("Present battery");
  gw.present(CHILD_ID_BATTERY, S_CUSTOM);
  gw.wait(RADIO_DELAY);
  Serial.println("Present moisture");
  gw.present(CHILD_ID_MOISTURE, S_HUM);
  gw.wait(RADIO_DELAY);
  for (int i = 0; i < N_ELEMENTS(SENSOR_ANALOG_PINS); i++) {
    pinMode(SENSOR_ANALOG_PINS[i], OUTPUT);
    digitalWrite(SENSOR_ANALOG_PINS[i], LOW);
  }
  Serial.println("Present sleep time");
  gw.present(CHILD_ID_SLEEP_TIME, S_INFO);
  gw.wait(RADIO_DELAY);
  fetchConfig();
}

void fetchConfig() {
  // Request latest sleep time
  Serial.print("Ask for sleep time, time is ");
  Serial.println(millis());
  // Usually takes approximately 3 seconds to get a response from Domoticz so let's wait 5 seconds.
  // We want to go to sleep as soon as we've gotten an incoming message, but if the controller doesn't responss
  // we need a timeout.
  byte t = 0;
  while (!gotMessage && t < 200) { // sleep in intervals of 100ms until we get a response or we have tried for 20 seconds
    gw.request(CHILD_ID_SLEEP_TIME, V_TEXT); // incomingMessage will set getMessage to true when an incoming message is detected
    gw.wait(100);
    t++;
  }
  gotMessage = false;
  // If we didn't get any sleeptime, sleeptime will be 0.
  // Ask the controller to create the variable by sending the default value
  Serial.println("Done waiting for sleep time");
  if (sleeptime_ms == 0) {
    sleeptime_ms = DEFAULT_SLEEP_TIME_MINUTES * 60L * 1000;
    Serial.println("Send default sleep time");
    gw.send(sleeptimeMsg.set(DEFAULT_SLEEP_TIME_MINUTES));
  }
  lastConfigCheckTime = millis();
}

void incomingMessage(const MyMessage &message) {
  gotMessage = true;
  Serial.print("Incoming message, time is ");
  Serial.println(millis());
  Serial.println(message.sensor);
  Serial.println(message.type);
  Serial.println(message.getLong());
  if (message.sensor == CHILD_ID_SLEEP_TIME) {
    if (message.type == V_TEXT) {
      long newSleeptime_ms = message.getLong() * 60L * 1000;
      Serial.println(newSleeptime_ms);
      if (newSleeptime_ms >= MIN_SLEEP_TIME_MINUTES * 60L * 1000 && newSleeptime_ms <= MAX_SLEEP_TIME_MINUTES * 60L * 1000) {
        sleeptime_ms = newSleeptime_ms;
      }
    }
  }
}

This is what output might look like:

send: 10-10-0-0 s=255,c=0,t=17,pt=0,l=3,sg=0,st=ok:1.5
send: 10-10-0-0 s=255,c=3,t=6,pt=1,l=1,sg=0,st=ok:0
sensor started, id=10, parent=0, distance=1
send: 10-10-0-0 s=255,c=3,t=11,pt=0,l=20,sg=0,st=ok:Plant moisture w bat
send: 10-10-0-0 s=255,c=3,t=12,pt=0,l=3,sg=0,st=ok:1.6
Present battery
send: 10-10-0-0 s=1,c=0,t=23,pt=0,l=0,sg=0,st=ok:
Present moisture
send: 10-10-0-0 s=0,c=0,t=7,pt=0,l=0,sg=0,st=ok:
Present sleep time
send: 10-10-0-0 s=2,c=0,t=36,pt=0,l=0,sg=0,st=fail:
Ask for sleep time, time is 3651
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=ok:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=ok:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=ok:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=ok:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=ok:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
find parent
send: 10-10-255-255 s=255,c=3,t=7,pt=0,l=0,sg=0,st=bc:
read: 0-0-10 s=2,c=2,t=47,pt=0,l=3,sg=0:30

Incoming message, time is 7424
2
47
30
1800000
read: 0-0-10 s=2,c=2,t=47,pt=0,l=3,sg=0:30

Incoming message, time is 7432
2
47
30
1800000
read: 0-0-10 s=2,c=2,t=47,pt=0,l=3,sg=0:30

Incoming message, time is 8429
2
47
30
1800000
read: 0-0-10 s=2,c=2,t=47,pt=0,l=3,sg=0:30

Incoming message, time is 8437
2
47
30
1800000
Done waiting for sleep time
send: 10-10-0-0 s=0,c=1,t=1,pt=7,l=5,sg=0,st=ok:0.0
send: 10-10-0-0 s=1,c=1,t=38,pt=7,l=5,sg=0,st=ok:3.441
send: 10-10-0-0 s=255,c=3,t=0,pt=1,l=1,sg=0,st=ok:137

As can be seen, gw.request often fails. The Arduino is a 3.3V Pro Mini. I have a 4.7uF cap on the radio. The nrf and the Arduino is powered on Vcc from the FTDI adapter.

I think the best solution would be to only resend if gw.request fails, similar to what can be done with gw.send. However, gw.request does not support the ack flag. I'll post a proposed solution soon.

[mfalkvidd]

I am using MySensors 1.5, so this change would need some refactoring to suit the development branch but the same principle should work.

Changes to MySensors:

diff --git a/libraries/MySensors/MySensor.cpp b/libraries/MySensors/MySensor.cpp
index 6c3a348..33fc516 100644
--- a/libraries/MySensors/MySensor.cpp
+++ b/libraries/MySensors/MySensor.cpp
@@ -504,8 +504,8 @@ void MySensor::sendSketchInfo(const char *name, const char *version, bool enable
     }
 }

-void MySensor::request(uint8_t childSensorId, uint8_t variableType, uint8_t destination) {
-   sendRoute(build(msg, nc.nodeId, destination, childSensorId, C_REQ, variableType, false).set(""));
+bool MySensor::request(uint8_t childSensorId, uint8_t variableType, uint8_t destination, bool enableAck) {
+ return sendRoute(build(msg, nc.nodeId, destination, childSensorId, C_REQ, variableType, enableAck).set(""));
 }

 void MySensor::requestTime(void (* _timeCallback)(unsigned long)) {
diff --git a/libraries/MySensors/MySensor.h b/libraries/MySensors/MySensor.h
index 18f4cb7..9e9ad8d 100644
--- a/libraries/MySensors/MySensor.h
+++ b/libraries/MySensors/MySensor.h
@@ -232,7 +232,7 @@ class MySensor
        * @param variableType The variableType to fetch
        * @param destination The nodeId of other node in radio network. Default is gateway
        */
-   void request(uint8_t childSensorId, uint8_t variableType, uint8_t destination=GATEWAY_ADDRESS);
+ bool request(uint8_t childSensorId, uint8_t variableType, uint8_t destination=GATEWAY_ADDRESS, bool ack=false);

        /**
         * Requests time from controller. Answer will be delivered to callback.

My new code:

#define re_request(id,type,retries) {byte t = 0; while(!gw.request(id,type,0, true) && t<retries){Serial.println(millis());gw.wait(pow(2,t)*100);t++;}}
void fetchConfig() {
  // Request latest sleep time
  Serial.print("Ask for sleep time, time is ");
  Serial.println(millis());
  // Usually takes approximately 3 seconds to get a response from Domoticz
  // We want to go to sleep as soon as we've gotten an incoming message, but if the controller doesn't respond
  // we need a timeout.
  byte t = 0;
  re_request(CHILD_ID_SLEEP_TIME, V_TEXT, 5);
  while (!gotMessage && t < 200) { // sleep in intervals of 100ms until we get a response or we have tried for 20 seconds
  // incomingMessage() will set gotMessage to true when an incoming message is detected
    gw.wait(100);
    t++;
  }
  gotMessage = false;
  // If we didn't get any sleeptime, sleeptime will be 0.
  // Ask the controller to create the variable by sending the default value
  Serial.println("Done waiting for sleep time");
  if (sleeptime_ms == 0) {
    sleeptime_ms = DEFAULT_SLEEP_TIME_MINUTES * 60L * 1000;
    Serial.println("Send default sleep time");
    gw.send(sleeptimeMsg.set(DEFAULT_SLEEP_TIME_MINUTES));
  }
  lastConfigCheckTime = millis();
}

Output:

send: 10-10-0-0 s=255,c=0,t=17,pt=0,l=3,sg=0,st=ok:1.5
send: 10-10-0-0 s=255,c=3,t=6,pt=1,l=1,sg=0,st=ok:0
sensor started, id=10, parent=0, distance=1
send: 10-10-0-0 s=255,c=3,t=11,pt=0,l=20,sg=0,st=ok:Plant moisture w bat
send: 10-10-0-0 s=255,c=3,t=12,pt=0,l=3,sg=0,st=ok:1.6
Present battery
send: 10-10-0-0 s=1,c=0,t=23,pt=0,l=0,sg=0,st=ok:
Present moisture
send: 10-10-0-0 s=0,c=0,t=7,pt=0,l=0,sg=0,st=fail:
read: 0-0-10 s=255,c=3,t=6,pt=0,l=2,sg=0:M

Present sleep time
send: 10-10-0-0 s=2,c=0,t=36,pt=0,l=0,sg=0,st=ok:
Ask for sleep time, time is 3651
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=ok:
read: 0-0-10 s=2,c=2,t=47,pt=0,l=0,sg=0:
Incoming message, time is 6799
2
47
0
0
read: 0-0-10 s=2,c=2,t=47,pt=0,l=3,sg=0:30

Incoming message, time is 6807
2
47
30
1800000
Done waiting for sleep time
send: 10-10-0-0 s=0,c=1,t=1,pt=7,l=5,sg=0,st=ok:0.0
send: 10-10-0-0 s=1,c=1,t=38,pt=7,l=5,sg=0,st=ok:3.441
send: 10-10-0-0 s=255,c=3,t=0,pt=1,l=1,sg=0,st=ok:137

I know re-sending has been discussed several times. So far, re-sending seems to be the "least bad" solution. Is there a better solution to this problem? (To recap, my problem is that I want to fetch a value from Domoticz reliably and I want the node to sleep as much as possible).

Perhaps I should read up on how other communication protocols handle reliable delivery. Any good examples besides TCP?
Edit: https://en.wikipedia.org/wiki/Automatic_repeat_request seems like a good place to start.

[hek]

This solution does not account for messages routed through repeaters. As gw.request only returns send result from the first hop.

[martinhjelmare]

@mfalkvidd

Why does it take 3-4 secs to get a response from Domoticz? That sounds very slow to me.

A timeout for reading from the serial port shouldn't need to be longer than 1 second, in my opinion.

[hek]

I'll do some reading and see if I can come up with something

[mfalkvidd]

@martinhjelmare said:

Why does it take 3-4 secs to get a response from Domoticz? That sounds very slow to me.

A timeout for reading from the serial port shouldn't need to be longer than 1 second, in my opinion.

I have no idea. The Domoticz log file does not log variable requests and responses. The PiSerialGateway does not log time stamps. So troubleshooting is a bit hard. But the delay is quite consistent, 3-4 seconds. Once it took 7 seconds.

[mfalkvidd]

@mfalkvidd said:

@martinhjelmare said:

Why does it take 3-4 secs to get a response from Domoticz? That sounds very slow to me.

A timeout for reading from the serial port shouldn't need to be longer than 1 second, in my opinion.

I have no idea. The Domoticz log file does not log variable requests and responses. The PiSerialGateway does not log time stamps. So troubleshooting is a bit hard. But the delay is quite consistent, 3-4 seconds. Once it took 7 seconds.

I managed to get timestamps from the gateway:

22:03:53.597931 read: 10-10-0 s=255,c=0,t=17,pt=0,l=3:1.5
22:03:54.099184 read: 10-10-0 s=255,c=3,t=6,pt=1,l=1:0
22:03:54.636821 send: 0-0-10-10 s=255,c=3,t=6,pt=0,l=2,st=fail:M
22:03:54.637514
22:03:54.638318 read: 10-10-0 s=255,c=3,t=11,pt=0,l=20:Plant moisture w bat
22:03:55.141040 read: 10-10-0 s=255,c=3,t=12,pt=0,l=3:1.6
22:03:55.643784 read: 10-10-0 s=1,c=0,t=23,pt=0,l=0:
22:03:56.145626 read: 10-10-0 s=2,c=0,t=36,pt=0,l=0:
22:03:56.648191 read: 10-10-0 s=2,c=2,t=47,pt=0,l=0:
22:03:56.651149 send: 0-0-10-10 s=2,c=2,t=47,pt=0,l=0,st=ok:
22:03:56.655084 send: 0-0-10-10 s=2,c=2,t=47,pt=0,l=3,st=ok:30
22:03:56.655757
22:03:56.656460 read: 10-10-0 s=2,c=1,t=47,pt=2,l=2:30
22:03:58.159151 read: 10-10-0 s=0,c=1,t=1,pt=7,l=5:0.1
22:03:58.668016 read: 10-10-0 s=1,c=1,t=38,pt=7,l=5:3.441
22:03:59.169774 read: 10-10-0 s=255,c=3,t=0,pt=1,l=1:137

Serial log:

sensor started, id=10, parent=0, distance=1
send: 10-10-0-0 s=255,c=3,t=11,pt=0,l=20,sg=0,st=ok:Plant moisture w bat
send: 10-10-0-0 s=255,c=3,t=12,pt=0,l=3,sg=0,st=ok:1.6
Present battery
send: 10-10-0-0 s=1,c=0,t=23,pt=0,l=0,sg=0,st=ok:
Present moisture
send: 10-10-0-0 s=0,c=0,t=7,pt=0,l=0,sg=0,st=fail:
read: 0-0-10 s=255,c=3,t=6,pt=0,l=2,sg=0:M


Present sleep time
send: 10-10-0-0 s=2,c=0,t=36,pt=0,l=0,sg=0,st=ok:
Ask for sleep time, time is 3651
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
3727
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
3905
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=ok:
read: 0-0-10 s=2,c=2,t=47,pt=0,l=0,sg=0:
Incoming message, time is 7024
2
47
0
Done waiting for sleep time, time is 7026
Send default sleep time
send: 10-10-0-0 s=2,c=1,t=47,pt=2,l=2,sg=0,st=ok:30
send: 10-10-0-0 s=0,c=1,t=1,pt=7,l=5,sg=0,st=ok:0.1
send: 10-10-0-0 s=1,c=1,t=38,pt=7,l=5,sg=0,st=ok:3.441
send: 10-10-0-0 s=255,c=3,t=0,pt=1,l=1,sg=0,st=ok:137

[mfalkvidd]

I forked the general discussion about reliable delivery, so we can use that thread to continue the discussion. Sorry for the inconvenience.

[mfalkvidd]

I have analyzed the log posted above and two things stand out:

1. When I request an ack, incomingMessage is called with a message length of 0. That seems strange to me. @hek do you have any insight to why this happens? Do all sketches need to handle empty messages due to ACKs as a special case in the implementation of incomingMessage? Sorry if this has already been changed in the development branch, I haven't been able to set up a working environment for that branch yet.
2. As can be seen in the serial log

Ask for sleep time, time is 3651
Incoming message, time is 7024

it takes 7.026-3.651=3.375 seconds from the request is sent until incomingMessage is called. But as can be seen in the gateway log

22:03:56.648191 read: 10-10-0 s=2,c=2,t=47,pt=0,l=0:                 # This is the request from the sensor
22:03:56.651149 send: 0-0-10-10 s=2,c=2,t=47,pt=0,l=0,st=ok:         # This is the ACK being sent to the sensor
22:03:56.655084 send: 0-0-10-10 s=2,c=2,t=47,pt=0,l=3,st=ok:30       # This is the reply being sent to the sensor - Domoticz must be blazingly fast!

both the ack and the reply are sent from the gateway almost immediately when the request is received (within 7 milliseconds). Does anyone have ideas why it takes more than three seconds before incomingMessage is called? My sketch does gw.wait almost all the time so the delay between the sensor's radio receives the message and the call to incomingMessage should be small.

[hek]

It was you, who added ack-flag to the request function. Not sure I see the point in that. But generally the ack payload is identical to the message being send. And in this case, REQuest always sends an empty payload.

3 seconds sounds live an awful long time. I have no immediate explanation. I mean, it's directly communicating with the sensor.

[mfalkvidd]

@hek True Of course things become strange when I make random changes to the library. In a way I guess it makes sense to wait for the reply to the request instead of requesting an ack on the request. If I don't get a reply within some timeout, I should send the request again. No need for ack. Then that's sorted out at least, thanks!

[Yveaux]

@mfalkvidd try sniffing the network. It might reveal things you didn't expect...

[mfalkvidd]

@Yveaux yes, this is a perfect excuse to try your sniffer. (adding the link if someone else reads this and doesn't know how to find it). I read your blog post with great interest a few months ago but haven't gotten around to trying it yet.

[martinhjelmare]

Shouldn't the controller respond with a set message to the req message? Now it's responding with a req, first with empty payload then with a payload. I don't think that makes sense.

Edit: The first response must be the ack right?