Increasingly long time between acks when using sendWithRetry [SOLVED]

[englund]

Hi, I'm having problems with the sendWithRetry method, it seems to take longer and longer before it gets an ACK until it fails completely (although the data is received just fine). Detailed description follows.

I'm running the WirelessProgramming examples on two Moteino R3:s sitting 1m apart on the same desk.
The gateway (https://github.com/LowPowerLab/RFM69/blob/master/Examples/WirelessProgramming_gateway/WirelessProgramming_gateway.ino) is almost unmodified, I only changed TARGET_ID to 11, FREQUENCY to 868 and ACK_TIME to 500.
The node (https://github.com/LowPowerLab/RFM69/blob/master/Examples/WirelessProgramming_node/WirelessProgramming_node.ino) has the same modifications as the gateway plus the addition of sending data periodically:

Code Select Expand

////////////////////////////////////////////////////////////////////////////////////////////
  // Real sketch code here, let's blink the onboard LED every 0.5sec
  if ((int)(millis()/3000) > lastPeriod)
  {
    lastPeriod++;
    pinMode(9, OUTPUT);
    digitalWrite(9, lastPeriod%2);

    byte temperature =  radio.readTemperature(-1);
    sprintf(payload, "radio %d %lu\n", temperature, millis());
    sendSize = strlen(payload);
    Serial.print("Sending[");
    Serial.print(sendSize);
    Serial.print("]: ");
    for(byte i = 0; i < sendSize; i++){
      Serial.print((char)payload[i]);
    }
    Serial.println();

    if (radio.sendWithRetry(GATEWAYID, payload, sendSize, 5, ACK_TIME)){
    	Serial.print(" ok!");
    }
    else {
    	Serial.print(" nothing...");
    }
    Serial.println();
  }
  ////////////////////////////////////////////////////////////////////////////////////////////

The serial output on the node (with the debug prints in sendWithRetry enabled) is:

Code Select Expand

****Sending[16]: radio 29 117000

 ~ms:
4 ok!
****Sending[16]: radio 29 120000

 ~ms:
22 ok!
****Sending[16]: radio 29 123000

 ~ms:
38 ok!
****Sending[16]: radio 29 126000

 ~ms:
55 ok!
****Sending[16]: radio 29 129000

 ~ms:
72 ok!
****Sending[16]: radio 29 132000

 ~ms:
89 ok!
****Sending[16]: radio 29 135000

 ~ms:
105 ok!
****Sending[16]: radio 29 138000

 ~ms:
123 ok!
****Sending[16]: radio 29 141000

 ~ms:
140 ok!
****Sending[16]: radio 29 144000

 ~ms:
157 ok!
****Sending[16]: radio 29 147000

 ~ms:
173 ok!
****Sending[16]: radio 29 150000

 ~ms:
191 ok!
****Sending[16]: radio 29 153000

 ~ms:
206 ok!
****Sending[16]: radio 29 156000

 ~ms:
224 ok!
****Sending[16]: radio 29 159000

 ~ms:
242 ok!
****Sending[16]: radio 29 162000

 RETRY#
1
 RETRY#
2
 RETRY#
3
 RETRY#
4
 RETRY#
5
 RETRY#
6
 nothing...
****Sending[16]: radio 29 165000

 RETRY#
1
 ~ms:
84 ok!
****Sending[16]: radio 29 168000

 RETRY#
1
 ~ms:
99 ok!
****Sending[16]: radio 29 171000

 RETRY#
1
 ~ms:
117 ok!
****Sending[16]: radio 29 174000

 RETRY#
1
 ~ms:
133 ok!
****Sending[16]: radio 29 177000

 RETRY#
1
 ~ms:
151 ok!
****Sending[16]: radio 29 180000

 RETRY#
1
 ~ms:
167 ok!
****Sending[16]: radio 29 183000

 RETRY#
1
 ~ms:
184 ok!
****Sending[16]: radio 29 186000

 RETRY#
1
 ~ms:
202 ok!
****Sending[16]: radio 29 189000

 RETRY#
1
 ~ms:
218 ok!
****Sending[16]: radio 29 192000

 RETRY#
1
 ~ms:
235 ok!
****Sending[16]: radio 29 195000

 RETRY#
1
 RETRY#
2
 ~ms:
3 ok!
****Sending[16]: radio 29 198000

 RETRY#
1
 RETRY#
2
 ~ms:
20 ok!
****Sending[16]: radio 29 201000

 RETRY#
1
 RETRY#
2
 ~ms:
36 ok!
****Sending[16]: radio 29 204000

 RETRY#
1
 RETRY#
2
 ~ms:
54 ok!

And the output on the gateway is:

Code Select Expand

radio 29 117000
                - ACK sent
radio 29 120000
                - ACK sent
radio 29 123000
                - ACK sent
radio 29 126000
                - ACK sent
radio 29 129000
                - ACK sent
radio 29 132000
                - ACK sent
radio 29 135000
                - ACK sent
radio 29 138000
                - ACK sent
radio 29 141000
                - ACK sent
radio 29 144000
                - ACK sent
radio 29 147000
                - ACK sent
radio 29 150000
                - ACK sent
radio 29 153000
                - ACK sent
radio 29 156000
                - ACK sent
radio 29 159000
                - ACK sent
radio 29 162000
                - ACK sent
radio 29 165000
                - ACK sent
radio 29 168000
                - ACK sent
radio 29 171000
                - ACK sent
radio 29 174000
                - ACK sent
radio 29 177000
                - ACK sent
radio 29 180000
                - ACK sent
radio 29 183000
                - ACK sent
radio 29 186000
                - ACK sent
radio 29 189000
                - ACK sent
radio 29 192000
                - ACK sent
radio 29 195000
                - ACK sent
radio 29 198000
                - ACK sent
radio 29 201000
                - ACK sent
radio 29 204000
                - ACK sent

So everything seems to be received and acked if you look at the gateway output but the node is just adding up the time it takes for the ack, in the end of the example above it's at 500 + 500 + 54 ms (2 retries).
And when it sends "radio 29 162000" it never gets an ack but the gateway receives it and sends an ack.
What is going on here??

Cheers,
Lars

[englund]

Also, although not important, where do the "****" that get printed before "Sending" come from in the node serial output?

[joao_ladeira]

Hi,

The ***** comes when you call the read temperature if im not mistaken    :

RFM69.cpp
byte RFM69::readTemperature(byte calFactor) //returns centigrade
{
  setMode(RF69_MODE_STANDBY);
  writeReg(REG_TEMP1, RF_TEMP1_MEAS_START);
  while ((readReg(REG_TEMP1) & RF_TEMP1_MEAS_RUNNING)) Serial.print('*');
  return ~readReg(REG_TEMP2) + COURSE_TEMP_COEF + calFactor; //'complement'corrects the slope, rising temp = rising val
}

Best regards,
João Ladeira

[englund]

Ah, there it was, thanks!

Now I'm hoping Felix will work his usual magic and solve the ACK-problem!

[joao_ladeira]

Np .

Im at work now, but if for some reason i get into that problem i will let you know, but since i got mine to work (since last friday ) i dint encounter that problem you are reporting.
If you try the node and gateway examples (not the wireless programing ones) do you get that effect as well?

Best regards,
JL.

[Felix]

I'd have to try the code myself to see for sure what's going on, can't do it right now, but hopefully later today.
However at first glance, it seems you might be using an older version of the library, which was printing the "~ms ..." in the sendWithRetry() function. That was only there for early lib development debugging and was left in as an artifact. Or maybe you went in and uncommented that yourself .. ?

[englund]

I went in and uncommented that myself to try and figure out what was going on but to no awail
I hope you find something.. I'll try the regular node and gateway in an hour as JL suggested.

[englund]

So the regular gateway and node example works just fine.. super weird. I can't see any functional difference in the code.

[englund]

Ok, I think I found the problem. This line:

Code Select Expand

byte inputLen = readSerialLine(input);

in WirelessProgramming_gateway blocks for 1000ms every time and thus makes the client wait for an ACK until it's done. Since I was sending every 3000ms I got a slowly increasing ACK-delay due to other things in the code on the node and gateway taking slightly different time.

It says in the feature list that the RFM69 library is interrupt driven but I can't find any information on how to use the interrupt driven approach instead of the radio.receiveDone polling. Is it possible to call an interrupt function when a packet has been received to immediately send the ACK?

[john k2ox]

the radio sets an output when it receives a packet. Felix's lib sets the AtMega to interupt when that pin changes. He grabs the data and gives it to you. Part of his receive routine.

[Felix]

It's interrupt driven, but the lib makes it easy for you since it grabs the data as soon as it's available and then allows you to collect it whenever you ask for it. Hence the receiveDone() call which abstracts all those details. I think that's more preferable than you dealing with interrupt routines.

The gateway example blocks for 1000ms, which can be reduced to 100ms or even less. So yes that can easily explain the behavior you're seeing. It's because the gateway example is not focused on receiving data, but rather listening for a wireless-programming command from the host.
I do realize all the code I provide does not fit all the scenarios and has shortcomings ... but it's there to give a decent head start

[englund]

I made a fork & topic branch (https://github.com/larsenglund/RFM69/compare/radiocallback) that adds callback functionality to the RFM69 library. It seems to be working fine here. If you want to merge it into the master I can create a pull request?

[Felix]

Thanks for the effort. However I'm trying to think who will use a callback call from an interrupt routine. It's so easy to screw it up it's going to create more problems than solve. People won't know how to properly use it. People barely know how to use the library as easy as it is to use now. Let alone using interrupts and function pointers properly...

Also you cannot use timing functions in an interrupt, they rely on interrupts.
And starting other transmissions from the interrupt is another problem. You will generate interrupts from within the interrupt. Big no no there.
Interrupts have to be as short as possible and not generate other interrupts, especially the same interrupt.
Hope this makes sense...

[englund]

Ah, I see, I did think it was too easy
But when using the polled approach, what happens if we during the 100ms delay in the gateway receive 2 transmissions? Or even worse, if we during each 100ms delay receive 2 transmissions. Either the gateway or nodes packet queues (if there are any queues) will fill up since we only read one packet between every 100ms delay. I guess we will start losing packets?

Was I just lucky that my callback approach works for me? Will it break down if I spend to much time in the callback or if I send anything other than the ACK and ping? Is there a safe (and not overly complex) way to implement a callback approach?

[Felix]

You have to let the interrupt finish as soon as possible if you want to avoid losing packets, and perhaps implement a queue if you want to avoid loosing packets. But even so you still have to poll at some point.
That's why I never implemented a queue in the library because it didn't make sense. It's up to the user to make sure they are picking up all the packets that are received.