Error: too many failed ADR requests

Hi all,
i’m currently testing the ADR of my new node, but it seems not working as i expected. After 10 packages it seems that the ADR process is started, but not responded or recognized from the LMIC library. After a few packages i become the “error: too many failed ADR requests”. See the screenshot from my gateway:

Here is the code for init the LMIC:

void setup()
{
uint8_t mcusr = MCUSR;
MCUSR = 0;

Serial.begin(115200);
debugPrintLn(F("Boot")); 

showBootStatus(mcusr);

// LMIC init
os_init();
// Reset the MAC state. Session and pending data transfers will be discarded.
LMIC_reset();

LMIC_setClockError(MAX_CLOCK_ERROR * 1 / 100);

LMIC_setupChannel(0, 868100000, DR_RANGE_MAP(DR_SF12, DR_SF7),  BAND_CENTI);      // g-band
LMIC_setupChannel(1, 868300000, DR_RANGE_MAP(DR_SF12, DR_SF7B), BAND_CENTI);      // g-band
LMIC_setupChannel(2, 868500000, DR_RANGE_MAP(DR_SF12, DR_SF7),  BAND_CENTI);      // g-band
LMIC_setupChannel(3, 867100000, DR_RANGE_MAP(DR_SF12, DR_SF7),  BAND_CENTI);      // g-band
LMIC_setupChannel(4, 867300000, DR_RANGE_MAP(DR_SF12, DR_SF7),  BAND_CENTI);      // g-band
LMIC_setupChannel(5, 867500000, DR_RANGE_MAP(DR_SF12, DR_SF7),  BAND_CENTI);      // g-band
LMIC_setupChannel(6, 867700000, DR_RANGE_MAP(DR_SF12, DR_SF7),  BAND_CENTI);      // g-band
LMIC_setupChannel(7, 867900000, DR_RANGE_MAP(DR_SF12, DR_SF7),  BAND_CENTI);      // g-band
LMIC_setupChannel(8, 868800000, DR_RANGE_MAP(DR_FSK,  DR_FSK),  BAND_MILLI);      // g2-band

LMIC_setLinkCheckMode(1);
LMIC_setAdrMode(1);
LMIC.dn2Dr = DR_SF9;
debugPrintLn(F("S")); // Setup complete!"
debugFlush();   

}

This is my onEvent method:

void onEvent (ev_t ev)
{
debugPrint(os_getTime());
debugPrint(": ");
debugPrintLn(ev);
switch(ev)
{
case EV_SCAN_TIMEOUT:
//debugPrintLn(F(“EV_SCAN_TIMEOUT”));
break;
case EV_BEACON_FOUND:
//debugPrintLn(F(“EV_BEACON_FOUND”));
break;
case EV_BEACON_MISSED:
//debugPrintLn(F(“EV_BEACON_MISSED”));
break;
case EV_BEACON_TRACKED:
//debugPrintLn(F(“EV_BEACON_TRACKED”));
break;
case EV_JOINING:
//debugPrintLn(F(“EV_JOINING”));
break;
case EV_JOINED:
//debugPrintLn(F(“EV_JOINED”));
break;
case EV_RFU1:
//debugPrintLn(F(“EV_RFU1”));
break;
case EV_JOIN_FAILED:
//debugPrintLn(F(“EV_JOIN_FAILED”));
break;
case EV_REJOIN_FAILED:
//debugPrintLn(F(“EV_REJOIN_FAILED”));
break;
case EV_TXCOMPLETE:
debugPrintLn(F(“EV_TXC”));
if (LMIC.txrxFlags & TXRX_ACK)
debugPrintLn(F(“R ACK”)); // Received ack
if (LMIC.dataLen)
{
debugPrintLn(F(“R “));
debugPrintLn(LMIC.dataLen);
debugPrintLn(F(” bytes”)); // of payload
}
LMIC_transmitted = 1;
break;
case EV_LOST_TSYNC:
//debugPrintLn(F(“EV_LOST_TSYNC”));
break;
case EV_RESET:
//debugPrintLn(F(“EV_RESET”));
break;
case EV_RXCOMPLETE:
// data received in ping slot
//debugPrintLn(F(“EV_RXCOMPLETE”));
break;
case EV_LINK_DEAD:
//debugPrintLn(F(“EV_LINK_DEAD”));
break;
case EV_LINK_ALIVE:
//debugPrintLn(F(“EV_LINK_ALIVE”));
break;
default:
//debugPrintLn(F(“Unknown event”));
break;
}
}

Where is the problem? Do i need to set some other flag or use another event. The serial monitor of the Arduino IDE shows only that a “EV_TXCOMPLETE” is received by the LMIC.

Kind regards
Stefan

Here some debug statements from the LMiC, setting debug level to 2.

9329234: engineUpdate, opmode=0x908
9329311: Uplink data pending
9329373: Considering band 0, which is available at 10930440
9329610: Considering band 1, which is available at 9482879
9329941: Considering band 2, which is available at 4950416
9330273: Considering band 3, which is available at 0
9330584: No channel found in band 3
9330774: Considering band 0, which is available at 10930440
9331111: Considering band 1, which is available at 9482879
9331443: Considering band 2, which is available at 4950416
9331788: No channel found in band 2
9331978: Considering band 0, which is available at 10930440
9332315: Considering band 1, which is available at 9482879
9332648: Airtime available at 9482879 (channel duty limit)
9332979: Airtime available at 9576587 (global duty limit)
9333305: Uplink delayed until 9576587
9333524: Scheduled job 0x449, cb 0x2007 at 9576462

9576572: Running job 0x449, cb 0x2007, deadline 9576462
9576691: engineUpdate, opmode=0x108
9576768: Uplink data pending
9576903: Airtime available at 9482879 (previously determined)
9577252: Airtime available at 9576587 (global duty limit)
9577578: Ready for uplink
9578410: Updating info for TX at 9576767, airtime will be 2896. Setting available time for band 1 to 2357133312
9578769: TXMODE, freq=868300000, len=14, SF=7, BW=125, CR=4/5, IH=0
9581294: irq: dio: 0x0 flags: 0x8
9581386: Scheduled job 0x449, cb 0xef3 ASAP
9582107: Running job 0x449, cb 0xef3, deadline 0
9582223: Scheduled job 0x449, cb 0xc45 at 9643155
9643485: Running job 0x449, cb 0xc45, deadline 9643155
9643669: RXMODE_SINGLE, freq=868300000, SF=7, BW=125, CR=4/5, IH=0
9646830: irq: dio: 0x0 flags: 0x40
9646951: Scheduled job 0x449, cb 0x20cd ASAP
9647675: Running job 0x449, cb 0x20cd, deadline 0
9648280: Received downlink, window=RX1, port=-1, ack=1
9648387: 10

9648469: engineUpdate, opmode=0x800

9650217: engineUpdate, opmode=0x808
9650293: Uplink data pending
9650356: Considering band 0, which is available at 10930440
9650593: Considering band 1, which is available at 9866367
9650925: Considering band 2, which is available at 4950416
9651257: Considering band 3, which is available at 0
9651567: No channel found in band 3
9651757: Considering band 0, which is available at 10930440
9652095: Considering band 1, which is available at 9866367
9652427: Considering band 2, which is available at 4950416
9652771: No channel found in band 2
9652961: Considering band 0, which is available at 10930440
9653298: Considering band 1, which is available at 9866367
9653632: Airtime available at 9866367 (channel duty limit)
9653962: Uplink delayed until 9866367
9654180: Scheduled job 0x449, cb 0x2007 at 9866242

9866336: Running job 0x449, cb 0x2007, deadline 9866242
9866454: engineUpdate, opmode=0x8
9866527: Uplink data pending
9866655: Airtime available at 9866367 (previously determined)
9867003: Ready for uplink
9867835: Updating info for TX at 9866526, airtime will be 3216. Setting available time for band 1 to 1969094656
9868194: TXMODE, freq=868500000, len=16, SF=7, BW=125, CR=4/5, IH=0
9871348: irq: dio: 0x0 flags: 0x8
9871440: Scheduled job 0x449, cb 0xef3 ASAP
9872161: Running job 0x449, cb 0xef3, deadline 0
9872277: Scheduled job 0x449, cb 0xc45 at 9933209
9933544: Running job 0x449, cb 0xc45, deadline 9933209
9933727: RXMODE_SINGLE, freq=868500000, SF=7, BW=125, CR=4/5, IH=0
9935632: irq: dio: 0x1 flags: 0x80
9935725: Scheduled job 0x449, cb 0x20cd ASAP
9936448: Running job 0x449, cb 0x20cd, deadline 0
9936565: Scheduled job 0x449, cb 0xc71 at 9995453
9995936: Running job 0x449, cb 0xc71, deadline 9995453
9996120: RXMODE_SINGLE, freq=869525000, SF=9, BW=125, CR=4/5, IH=0
10000040: irq: dio: 0x1 flags: 0x80
10000136: Scheduled job 0x449, cb 0x20e4 ASAP
10000861: Running job 0x449, cb 0x20e4, deadline 0
10000969: 10

10001058: engineUpdate, opmode=0x900

10002793: engineUpdate, opmode=0x908
10002873: Uplink data pending
10002938: Considering band 0, which is available at 10930440
10003186: Considering band 1, which is available at 10188126
10003529: Considering band 2, which is available at 4950416
10003867: Considering band 3, which is available at 0
10004182: No channel found in band 3
10004379: Considering band 0, which is available at 10930440
10004722: Considering band 1, which is available at 10188126
10005065: Considering band 2, which is available at 4950416
10005415: No channel found in band 2
10005610: Considering band 0, which is available at 10930440
10005953: Considering band 1, which is available at 10188126
10006308: Airtime available at 10188126 (channel duty limit)
10006639: Airtime available at 10264935 (global duty limit)
10006977: Uplink delayed until 10264935
10007207: Scheduled job 0x449, cb 0x2007 at 10264810

10265398: Running job 0x449, cb 0x2007, deadline 10264810
10265523: engineUpdate, opmode=0x108
10265602: Uplink data pending
10265752: Airtime available at 10188126 (previously determined)
10266113: Airtime available at 10264935 (global duty limit)
10266450: Ready for uplink
10267288: Updating info for TX at 10265601, airtime will be 2896. Setting available time for band 1 to 255918080
10267653: TXMODE, freq=868100000, len=14, SF=7, BW=125, CR=4/5, IH=0
10270184: irq: dio: 0x0 flags: 0x8
10270278: Scheduled job 0x449, cb 0xef3 ASAP
10271003: Running job 0x449, cb 0xef3, deadline 0
10271121: Scheduled job 0x449, cb 0xc45 at 10332045
10332390: Running job 0x449, cb 0xc45, deadline 10332045
10332579: RXMODE_SINGLE, freq=868100000, SF=7, BW=125, CR=4/5, IH=0
10335118: irq: dio: 0x0 flags: 0x40
10335239: Scheduled job 0x449, cb 0x20cd ASAP
10335965: Running job 0x449, cb 0x20cd, deadline 0
10336562: Received downlink, window=RX1, port=-1, ack=1
10336673: 10

10336761: engineUpdate, opmode=0x800

It seems that the message is received in RX1 window but not interpreted or used.

@biermi

Looks like TTN gave up on your node and refuses to send any more ADR requests. However, from your log it appears to be that your node is already running failry efficiently (SF7 TX and RX),

Here is what you can do to debug the thing:

  1. Set ACKREQ on each uplink (this will cause adr optimize on a first uplink after join). You can keep ACKREQ bit set on every uplink.
  2. Clear log on TTN console and restart the device.
  3. You should see that first ACK following your first uplink will contain ADR data if that was needed.
  4. If 3 is not the case you’ll have to wait for 20+ uplinks.

Repeat 1 to 3 and post snapshot of TTN console log for first ACK,

The above will reveal if TTN ever sends ADR data or not.

If it sends it then we need to look at LMIC mac processing.

1 Like

How can i set the ACKREQ on each uplink with LMIC? There is no operation for that, i can only activate:

LMIC_setLinkCheckMode(1);
LMIC_setAdrMode(1);

as operation for the lib, that i have done. I can later post the join and first uplink messages from the TTN console of my gateway.

LMIC_setLinCheckMode(1) is the right way to do so.

As per processing of the state after join it’ll set LMIC.adrAckReq to some value.
Here is code snippet from lmic.c

static void stateJustJoined (void) {
    LMIC.seqnoDn     = LMIC.seqnoUp = 0;
    LMIC.rejoinCnt   = 0;
    LMIC.dnConf      = LMIC.adrChanged = LMIC.ladrAns = LMIC.devsAns = 0;
    LMIC.moreData    = LMIC.dn2Ans = LMIC.snchAns = LMIC.dutyCapAns = 0;
    LMIC.pingSetAns  = 0;
    LMIC.upRepeat    = 0;
    LMIC.adrAckReq   = LINK_CHECK_INIT;
    LMIC.dn2Dr       = DR_DNW2;
    LMIC.dn2Freq     = FREQ_DNW2;
    LMIC.bcnChnl     = CHNL_BCN;
    LMIC.ping.freq   = FREQ_PING;
    LMIC.ping.dr     = DR_PING;
}

Ok, post the screenshots of the first results later here.

When I said that ADR should work on LMIC I actually know that there is a code there. I haven’t tried it but based on what I am seeing in “decodeFrame” function of lmic.c processing of ADR response is there:

            if( (LMIC.ladrAns & 0x7F) == (MCMD_LADR_ANS_POWACK | MCMD_LADR_ANS_CHACK | MCMD_LADR_ANS_DRACK) ) {
                // Nothing went wrong - use settings
                LMIC.upRepeat = uprpt;
                setDrTxpow(DRCHG_NWKCMD, dr, pow2dBm(p1));
            }

Add some debug print and you should be able to resolve it no time.
First thing that you need to find out is if ADR portion of the lora mac message is there.

It seems it is working now, without any code changes on the node. The only change, so far i know, is that the backend software is changed as here described ADR Not Working on AU915 (Device stuck on SF12). Maybe it was the same problem or similar which is now fixed by @htdvisser.
image
On the screen shot is shown that the ADR requests starts after 12 uplink packages and ends after 3.

@biermi

How do you know that any of the messages sent to device between 16:58:45 and 17:00:38 contain ADR data ?

Have you actually seen ADR sent from message arriving to device and being processed there in decodeFrame() function ?

The reason I am asking is the fact that device was on SF7 and it stayed there so device was reasonably optimized already. However that brings another question into focus and this is at what SF it joined the network and how it did get to SF7 for start.

I have looked in the console at the packages which are send to the node, they showing, similar to the first screenshot in this thread, mac commands, which will be send to the node. In the serial monitor of the node was shown that packages are received but no additional logging within the decodeFrame() function. And there are only 3 packages send to the node, in the tests before every uplink package followed by a downlink package starting after 12 uplink packages received by the gateway.

The node was joining with SF7 at the beginning, the console of the gateway shows the joining request was received with SF7. I have not set any SF in the code, it must be came from the LMiC lib himself. My assumption was similar to yours, i thought it will start with SF12 for joining and lowers than the SF to the optimal value. But it starts with SF7. I’m using the LMiC from @matthijskooijman https://github.com/matthijskooijman/arduino-lmic.