Uplink Channel stays the same after ~80 to ~90 minutes

[JSchimmelpfennig]

Hi guys, thank you for this amazing project. I am currently writing my master thesis at PHYSEC as part of the master's degree in IT-Security at the Ruhr-University Bochum.

For my thesis, I am using MCCI LoRaWAN LMIC library in version 5.0.1 and I found out, that the uplink channel stays after approximately 80 - 90 minutes the same and does not change again (EU868 band).

I could reproduce this behaviour on all Nucleos, as I have multiple of them here for testing, so this is not a hardware bug caused by one faulty device.

I use the most recent versions of VSCode with PlatformIO for the development on the Nucleo L476RG with an Adafruit RFM9X LoRa radio transceiver module.

I am using a local ChirpStack (version 4.15.0) instance and I use the InfluxDB integration and visualize it with Grafana.

The FLUX query for this dashboard

startTime   = v.timeRangeStart
stopTime    = v.timeRangeStop
bucket_name = "measurement_bucket"

from(bucket: bucket_name)
  |> range(start: startTime, stop: stopTime)
  |> filter(fn: (r) => 
      r._measurement == "device_uplink" and
      r._field == "value" and          // 1 row per uplink
      exists r.device_name and
      r.device_name =~ /^LR-NuB/ and
      exists r.frequency               // ensure frequency tag exists
  )
  // Map frequency tag directly into _value (Hz)
  |> map(fn: (r) => ({
        r with _value: float(v: r.frequency) / 1000000.0
  }))
  |> keep(columns: ["_time", "_value", "device_name"])
  |> group(columns: ["device_name"])
  |> sort(columns: ["_time"])
  |> yield(name: "frequency_by_device")

For testing, I used the provided ttn-otaa example with some minor changes to make it able to compile.

main.cpp

/*******************************************************************************
 * Copyright (c) 2015 Thomas Telkamp and Matthijs Kooijman
 * Copyright (c) 2018 Terry Moore, MCCI
 *
 * Permission is hereby granted, free of charge, to anyone
 * obtaining a copy of this document and accompanying files,
 * to do whatever they want with them without any restriction,
 * including, but not limited to, copying, modification and redistribution.
 * NO WARRANTY OF ANY KIND IS PROVIDED.
 *
 * This example sends a valid LoRaWAN packet with payload "Hello,
 * world!", using frequency and encryption settings matching those of
 * the The Things Network.
 *
 * This uses OTAA (Over-the-air activation), where where a DevEUI and
 * application key is configured, which are used in an over-the-air
 * activation procedure where a DevAddr and session keys are
 * assigned/generated for use with all further communication.
 *
 * Note: LoRaWAN per sub-band duty-cycle limitation is enforced (1% in
 * g1, 0.1% in g2), but not the TTN fair usage policy (which is probably
 * violated by this sketch when left running for longer)!

 * To use this sketch, first register your application and device with
 * the things network, to set or generate an AppEUI, DevEUI and AppKey.
 * Multiple devices can use the same AppEUI, but each device has its own
 * DevEUI and AppKey.
 *
 * Do not forget to define the radio type correctly in
 * arduino-lmic/project_config/lmic_project_config.h or from your BOARDS.txt.
 *
 *******************************************************************************/

#include <lmic.h>
#include <hal/hal.h>
#include <SPI.h>

//
// For normal use, we require that you edit the sketch to replace FILLMEIN
// with values assigned by the TTN console. However, for regression tests,
// we want to be able to compile these scripts. The regression tests define
// COMPILE_REGRESSION_TEST, and in that case we define FILLMEIN to a non-
// working but innocuous value.
//
#ifdef COMPILE_REGRESSION_TEST
# define FILLMEIN 0
#else
# warning "You must replace the values marked FILLMEIN with real values from the TTN control panel!"
# define FILLMEIN (#dont edit this, edit the lines that use FILLMEIN)
#endif

// This EUI must be in little-endian format, so least-significant-byte
// first. When copying an EUI from ttnctl output, this means to reverse
// the bytes. For TTN issued EUIs the last bytes should be 0xD5, 0xB3,
// 0x70.
static const u1_t PROGMEM APPEUI[8]={ 0x00 };
void os_getArtEui (u1_t* buf) { memcpy_P(buf, APPEUI, 8);}

// This should also be in little endian format, see above.
static const u1_t PROGMEM DEVEUI[8]={ HIDDEN };
void os_getDevEui (u1_t* buf) { memcpy_P(buf, DEVEUI, 8);}

// This key should be in big endian format (or, since it is not really a
// number but a block of memory, endianness does not really apply). In
// practice, a key taken from ttnctl can be copied as-is.
static const u1_t PROGMEM APPKEY[16] = { HIDDEN };
void os_getDevKey (u1_t* buf) {  memcpy_P(buf, APPKEY, 16);}

void do_send(osjob_t* j); // Declaration to prevent error "'do_send' was not declared in this scope"

static uint8_t mydata[] = "Hello, world!";
static osjob_t sendjob;

// Schedule TX every this many seconds (might become longer due to duty
// cycle limitations).
const unsigned TX_INTERVAL = 6;

// Pin mapping
const lmic_pinmap lmic_pins = {
    .nss = D10,           // RFM95 Chip Select pin Pin CS is connected to pin CN10,19(D9) on STM32 Nucleo
    .rxtx = LMIC_UNUSED_PIN,
    .rst = PA0,          // RFM95 Reset Pin RST is connected to pin CN7,28(PC0/A0) on STM32 Nucleo
    .dio = {D2, D3, D4},  // RFM95 GPIO Pin G0,G1,G2 are DIO0,DIO1,DIO2 and are connected to pins CN10,33(D2), CN10,31(D3), CN10,29(D4) on STM32 Nucleo

    // the following are need to prevent compiler warning "missing initializer for member"
    .rxtx_rx_active = 0,
    .rssi_cal = 10,           // default RSSI calibration
    .spi_freq = 8000000,      // 8 MHz SPI
    .pConfig = nullptr        // no special config
};

void printHex2(unsigned v) {
    v &= 0xff;
    if (v < 16)
        Serial.print('0');
    Serial.print(v, HEX);
}

void onEvent (ev_t ev) {
    Serial.print(os_getTime());
    Serial.print(": ");
    switch(ev) {
        case EV_SCAN_TIMEOUT:
            Serial.println(F("EV_SCAN_TIMEOUT"));
            break;
        case EV_BEACON_FOUND:
            Serial.println(F("EV_BEACON_FOUND"));
            break;
        case EV_BEACON_MISSED:
            Serial.println(F("EV_BEACON_MISSED"));
            break;
        case EV_BEACON_TRACKED:
            Serial.println(F("EV_BEACON_TRACKED"));
            break;
        case EV_JOINING:
            Serial.println(F("EV_JOINING"));
            break;
        case EV_JOINED:
            Serial.println(F("EV_JOINED"));
            {
              u4_t netid = 0;
              devaddr_t devaddr = 0;
              u1_t nwkKey[16];
              u1_t artKey[16];
              LMIC_getSessionKeys(&netid, &devaddr, nwkKey, artKey);
              Serial.print("netid: ");
              Serial.println(netid, DEC);
              Serial.print("devaddr: ");
              Serial.println(devaddr, HEX);
              Serial.print("AppSKey: ");
              for (size_t i=0; i<sizeof(artKey); ++i) {
                if (i != 0)
                  Serial.print("-");
                printHex2(artKey[i]);
              }
              Serial.println("");
              Serial.print("NwkSKey: ");
              for (size_t i=0; i<sizeof(nwkKey); ++i) {
                      if (i != 0)
                              Serial.print("-");
                      printHex2(nwkKey[i]);
              }
              Serial.println();
            }
            // Disable link check validation (automatically enabled
            // during join, but because slow data rates change max TX
	    // size, we don't use it in this example.
            LMIC_setLinkCheckMode(0);
            break;
        /*
        || This event is defined but not used in the code. No
        || point in wasting codespace on it.
        ||
        || case EV_RFU1:
        ||     Serial.println(F("EV_RFU1"));
        ||     break;
        */
        case EV_JOIN_FAILED:
            Serial.println(F("EV_JOIN_FAILED"));
            break;
        case EV_REJOIN_FAILED:
            Serial.println(F("EV_REJOIN_FAILED"));
            break;
        case EV_TXCOMPLETE:
            Serial.println(F("EV_TXCOMPLETE (includes waiting for RX windows)"));
            if (LMIC.txrxFlags & TXRX_ACK)
              Serial.println(F("Received ack"));
            if (LMIC.dataLen) {
              Serial.print(F("Received "));
              Serial.print(LMIC.dataLen);
              Serial.println(F(" bytes of payload"));
            }
            // Schedule next transmission
            os_setTimedCallback(&sendjob, os_getTime()+sec2osticks(TX_INTERVAL), do_send);
            break;
        case EV_LOST_TSYNC:
            Serial.println(F("EV_LOST_TSYNC"));
            break;
        case EV_RESET:
            Serial.println(F("EV_RESET"));
            break;
        case EV_RXCOMPLETE:
            // data received in ping slot
            Serial.println(F("EV_RXCOMPLETE"));
            break;
        case EV_LINK_DEAD:
            Serial.println(F("EV_LINK_DEAD"));
            break;
        case EV_LINK_ALIVE:
            Serial.println(F("EV_LINK_ALIVE"));
            break;
        /*
        || This event is defined but not used in the code. No
        || point in wasting codespace on it.
        ||
        || case EV_SCAN_FOUND:
        ||    Serial.println(F("EV_SCAN_FOUND"));
        ||    break;
        */
        case EV_TXSTART:
            Serial.println(F("EV_TXSTART"));
            break;
        case EV_TXCANCELED:
            Serial.println(F("EV_TXCANCELED"));
            break;
        case EV_RXSTART:
            /* do not print anything -- it wrecks timing */
            break;
        case EV_JOIN_TXCOMPLETE:
            Serial.println(F("EV_JOIN_TXCOMPLETE: no JoinAccept"));
            break;

        default:
            Serial.print(F("Unknown event: "));
            Serial.println((unsigned) ev);
            break;
    }
}

void do_send(osjob_t* j){
    // Check if there is not a current TX/RX job running
    if (LMIC.opmode & OP_TXRXPEND) {
        Serial.println(F("OP_TXRXPEND, not sending"));
    } else {
        // Prepare upstream data transmission at the next possible time.
        LMIC_setTxData2(1, mydata, sizeof(mydata)-1, 0);
        Serial.println(F("Packet queued"));
    }
    // Next TX is scheduled after TX_COMPLETE event.
}

void setup() {
    Serial.begin(115200);
    Serial.println(F("Starting"));

    #ifdef VCC_ENABLE
    // For Pinoccio Scout boards
    pinMode(VCC_ENABLE, OUTPUT);
    digitalWrite(VCC_ENABLE, HIGH);
    delay(1000);
    #endif

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

    LMIC_setClockError(MAX_CLOCK_ERROR * 20 / 100); // start/keep downlink windows x percent earlier

    // Start job (sending automatically starts OTAA too)
    do_send(&sendjob);
}

void loop() {
    os_runloop_once();
}

platformio.ini

[env:nucleo_l476rg]
platform = ststm32
board = nucleo_l476rg
framework = arduino
monitor_speed = 115200
build_flags = 
	-Wall
	-Wextra
	-D ARDUINO_LMIC_PROJECT_CONFIG_H_SUPPRESS
	-D CFG_eu868=1
	-D CFG_sx1276_radio=1 ; see src/lmic/radio_sx127x.c
	-D LMIC_DEBUG_LEVEL=0 ; DO NOT USE IT, IT RUINS TIMING! https://github.com/mcci-catena/arduino-lmic/issues/814#issuecomment-962465494
	-D LMIC_FAILURE_TO=Serial
	-D LMIC_ENABLE_arbitrary_clock_error=1 ; For using MAX_CLOCK_ERROR. See https://github.com/mcci-catena/arduino-lmic#lmic_setclockerror. For a variety of reasons, the LMIC normally ignores clock errors greater than 4000 ppm (0.4%). The compile-time flag LMIC_ENABLE_arbitrary_clock_error can remove this limit. To do this, define it to a non-zero value.
	-D LMIC_ENABLE_DeviceTimeReq=1 ; For device time request

lib_deps = 
	mcci-catena/MCCI LoRaWAN LMIC library@^5.0.1

Build Output of PlatformIO

 *  Executing task: platformio run --environment nucleo_l476rg 

Processing nucleo_l476rg (platform: ststm32; board: nucleo_l476rg; framework: arduino)
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Verbose mode can be enabled via `-v, --verbose` option
CONFIGURATION: https://docs.platformio.org/page/boards/ststm32/nucleo_l476rg.html
PLATFORM: ST STM32 (19.2.0) > ST Nucleo L476RG
HARDWARE: STM32L476RGT6 80MHz, 96KB RAM, 1MB Flash
DEBUG: Current (stlink) On-board (stlink) External (blackmagic, cmsis-dap, jlink)
PACKAGES: 
 - framework-arduinoststm32 @ 4.21001.0 (2.10.1) 
 - framework-cmsis @ 2.50900.0 (5.9.0) 
 - toolchain-gccarmnoneeabi @ 1.120301.0 (12.3.1)
LDF: Library Dependency Finder -> https://bit.ly/configure-pio-ldf
LDF Modes: Finder ~ chain, Compatibility ~ soft
Found 15 compatible libraries
Scanning dependencies...
Dependency Graph
|-- MCCI LoRaWAN LMIC library @ 5.0.1
|-- SPI @ 1.1.0
Building in release mode
Checking size .pio/build/nucleo_l476rg/firmware.elf
Advanced Memory Usage is available via "PlatformIO Home > Project Inspect"
RAM:   [          ]   2.6% (used 2516 bytes from 98304 bytes)
Flash: [          ]   3.7% (used 38648 bytes from 1048576 bytes)
Building .pio/build/nucleo_l476rg/firmware.bin
=========================================================================== [SUCCESS] Took 1.15 seconds ===========================================================================
 *  Terminal will be reused by tasks, press any key to close it.

For troubleshooting, I added logging to the function LMICeu868_nextTx in lmic_eu868.c

LMICeu868_nextTx

ostime_t LMICeu868_nextTx(ostime_t now) {
        ostime_t mintime = now + /*8h*/sec2osticks(28800);
        u2_t availMap;
        u2_t feasibleMap;
        u1_t bandMap;

        // set mintime to the earliest time of all enabled channels
        // (can't just look at bands); and for a given channel, we
        // can't tell if we're ready till we've checked all possible
        // avail times.
        bandMap = 0;
        for (u1_t chnl = 0; chnl < MAX_CHANNELS; ++chnl) {
                u2_t chnlBit = 1 << chnl;

                // none at any higher numbers?
                if (LMIC.channelMap < chnlBit)
                        break;

                // not enabled?
                if ((LMIC.channelMap & chnlBit) == 0)
                        continue;

                // not feasible?
                if ((LMIC.channelDrMap[chnl] & (1 << (LMIC.datarate & 0xF))) == 0)
                        continue;

                u1_t const band = LMIC.channelFreq[chnl] & 0x3;
                u1_t const thisBandBit = 1 << band;
                // already considered?
                if ((bandMap & thisBandBit) != 0)
                        continue;

                // consider this band.
                bandMap |= thisBandBit;

                // enabled, not considered, feasible: adjust the min time.
                if ((s4_t)(mintime - LMIC.bands[band].avail) > 0)
                        mintime = LMIC.bands[band].avail;
        }

        // make a mask of candidates available for use
        availMap = 0;
        feasibleMap = 0;
        for (u1_t chnl = 0; chnl < MAX_CHANNELS; ++chnl) {
                u2_t chnlBit = 1 << chnl;

                // none at any higher numbers?
                if (LMIC.channelMap < chnlBit)
                        break;

                // not enabled?
                if ((LMIC.channelMap & chnlBit) == 0)
                        continue;

                // not feasible?
                if ((LMIC.channelDrMap[chnl] & (1 << (LMIC.datarate & 0xF))) == 0)
                        continue;

                // This channel is feasible. But might not be available.
                feasibleMap |= chnlBit;

                // not available yet?
                u1_t const band = LMIC.channelFreq[chnl] & 0x3;
                if ((s4_t)(LMIC.bands[band].avail - mintime) > 0)
                        continue;

                // ok: this is a candidate.
                availMap |= chnlBit;
        }


        // ---- logging BEFORE choose (now that maps are valid)
        printf("nextTx: now=%ld mintime=%ld (%lums) map=0x%04X dr=DR%d\n",
                (long)now, (long)mintime, osticks2ms(mintime - now),
                LMIC.channelMap, LMIC.datarate);
        printf("nextTx: feasible=0x%04X avail=0x%04X shuffle(before)=0x%04X last=%d\n",
                feasibleMap, availMap, LMIC.channelShuffleMap,
                (LMIC.txChnl == 0xFF ? -1 : LMIC.txChnl));

        // find the next available chennel.
        u2_t saveShuffleMap = LMIC.channelShuffleMap;
        int candidateCh = LMIC_findNextChannel(&LMIC.channelShuffleMap, &availMap, 1, LMIC.txChnl == 0xFF ? -1 : LMIC.txChnl);

        // restore bits in the shuffleMap that were on, but might have reset
        // if availMap was used to refresh shuffleMap. These are channels that
        // are feasble but not yet candidates due to band saturation
        LMIC.channelShuffleMap |= saveShuffleMap & feasibleMap & ~availMap;

        if (candidateCh >= 0) {
                // update the channel; otherwise we'll just use the
                // most recent one.
                LMIC.txChnl = candidateCh;
        }

        // ---- logging AFTER choose
        printf("nextTx: cand=%d shuffle(after)=0x%04X keepLast=%d\n",
                candidateCh, LMIC.channelShuffleMap, (candidateCh < 0));

        return mintime;
}

This showed that mintime overflows. When mintime=-2142721635, cand stays at -1 and from this moment onwards the uplink channel stays the same.

Serial monitor log

nextTx: cand=7 shuffle(after)=0x0053 keepLast=0
nextTx: now=339711621 mintime=338748134 (4294951881ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x00FF shuffle(before)=0x0053 last=7
nextTx: cand=0 shuffle(after)=0x0052 keepLast=0
nextTx: now=340965519 mintime=340001221 (4294951868ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x00FF shuffle(before)=0x0052 last=0
nextTx: cand=1 shuffle(after)=0x0050 keepLast=0
nextTx: now=342218941 mintime=341255119 (4294951875ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x00FF shuffle(before)=0x0050 last=1
nextTx: cand=6 shuffle(after)=0x0010 keepLast=0
nextTx: now=343472406 mintime=342508541 (4294951875ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x00FF shuffle(before)=0x0010 last=6
nextTx: cand=4 shuffle(after)=0x0000 keepLast=0
nextTx: now=344725611 mintime=343762006 (4294951879ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x00FF shuffle(before)=0x0000 last=4
nextTx: cand=7 shuffle(after)=0x007F keepLast=0
nextTx: now=345979018 mintime=345015211 (4294951876ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x00FF shuffle(before)=0x007F last=7
nextTx: cand=2 shuffle(after)=0x007B keepLast=0
nextTx: now=347232365 mintime=346268618 (4294951877ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x00FF shuffle(before)=0x007B last=2
nextTx: cand=6 shuffle(after)=0x003B keepLast=0
nextTx: now=348485938 mintime=-2146481358 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=349739507 mintime=-2145227789 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=350992542 mintime=-2143974754 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=352245661 mintime=-2142721635 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=353498676 mintime=-2141468620 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=354751985 mintime=-2140215311 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=356004727 mintime=-2138962569 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=357257716 mintime=-2137709580 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=358510326 mintime=-2136456970 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1
nextTx: now=359763324 mintime=-2135203972 (28800000ms) map=0x00FF dr=DR5
nextTx: feasible=0x00FF avail=0x0000 shuffle(before)=0x003B last=6
nextTx: cand=-1 shuffle(after)=0x003B keepLast=1

In issue 968 I read something about problems using some compilers, but I guess this was fixed.

In the much older (and closed) issue 225, the discussion was about mintime. The maintainer replied to the question:

“The general question is, if these arithmetic operations are correct — for example, what happens if mintime overflows?”
with: “It wraps around and nothing bad happens, unless there’s a bug in the coding at the particular point.”

I believe the issue I’m seeing is that this wraparound does not happen in my case.

[terrillmoore]

Sorry you're having problems. Thanks for the careful report. Evidently when mintime becomes negative, none of the channels are available according to LMIC_findNextChannel(). This is becbecause avail is zero That is computed at line 309 (above your prints). And looking at the timestamps I can see why. mintime is 0x800F4b32, which is a long way from now, which is 0x14a3a3ca. And i the computation, it looks like the future, because 14a3a3ca is large enough that 0x8000f4b32 looks like the future (the difference is less than 2^31).

So this is not a wraparound; the code is doing the specified thing. The value of mintime is incorrect.

The question is how mintime becomes wrong. We have to look at the value stored in LMIC.bands[band] for each band so we find out which one is causing this. If you put a debug print (and curly braces) accompanying the assignment at line 283, then we will capture the band that has gone wrong (print bands at that point).

Based on a code search, it seems to be set at lmic_u_like.c line 153. That code looks innocuous. So we need to print out the calculations at that point: txbeg, airtime, band->txcap and the band number (freq & 0x3), along with the result of the calculation band->avail. From that, we'll either see the problem, or we'll need to go back further.

Is the Nucleo based on an AVR processor or a 32-bit processor? It should not make any difference, because line 153 is a 32-bit calculation, even with 16-bit ints; but...

[JSchimmelpfennig]

Hi Terry,
the L476RG microcontroller from STM32 uses an Arm® 32-bit Cortex®-M4 CPU with FPU, so I doubt the architecture is the problem. This is the link to the datasheet.

I’ve already spent quite a bit of time looking into this, and I was hoping that the team at MCCI Catena can take over from here. As I am also using the provided example implementation, the behaviour should be easily reproducible.