EV_TXComplete takes 240 sec to finish after EV_TXSTART due to RXTimeout

End Devices (Nodes) Pycom
1

Hi,

I am right now looking for an solution to very slow TX_Interval problems.
Each time I sent the EV_TXSTART is fired I need to wait 270 sec(4min) until I get a EV_TXCOMPLETE.

My Code:
OTAA Example Code
In Setup I disabled linkCheckMode with LMIC_setLinkCheckMode(0);
Set MAX Clock Error with LMIC_setClockError(MAX_CLOCK_ERROR * 10 / 100);
Disable Confirmed Uplinks with LMIC_setTxData2(1, buffer, sizeof(buffer), 0
TX_INTERVAL = 30; (sec)
Reset Frame Counter in TTN Network done
Used mcci-catena/arduino-lmic Stack from Jan 2020

Used HW:
ESP32 with a 40 MHz XCO and proper ppm rate = TTGO T5
RFM95 Module
DIO00 connected to GPIO 34 of ESP32
DIO01 connected to GPIO 25 of ESP32
Enabled Pulldown on GPIO25 and GPIO34 with Command

pinMode(LORA_PIN_SPI_DIO, INPUT_PULLDOWN);

Joining works after some join requests
Identical HW on 2 nodes, happens on both

Pinning:

//Lora Pinning for TTGO T5 Addon Board
  #define LORA_PIN_SPI_MOSI 15
  #define LORA_PIN_SPI_MISO 2
  #define LORA_PIN_SPI_SCK  14
  #define LORA_PIN_SPI_NSS  26  
  #define LORA_PIN_SPI_RST  33  
  #define LORA_PIN_SPI_DIO  25
  #define LORA_PIN_SPI_DIO0 34

and some modifications in the file hal.cpp LMIC to make this pinning accepted
static void hal_spi_init () {
	//SPI.begin(lmic_pins.sck, lmic_pins.miso, lmic_pins.mosi, 0x00);
	SPI.begin(14, 2, 15, 26);
}

Gateway Traffic:
I can not see any Downlink Gateway Traffic on my Gateway which requires a Wait for RX.
I can not see any Downlink Traffic on the TTN Application Console.
I installed a Single Channel Gateway (with a terrible Antenna) which only recieves packages from this node.
Same issue as well happens on other 3 Public professional RAK Gateways which are in sight and good recivable

My Issue:
In Serial log below you see at 21:12:20.312 a TX_START
After 2 Minutes I get RXTimeout at 21:14:19.960
After Another 2 Minutes I get another RXTimeout at 21:15:19.959
And finally at 21:16:19.965 I got a TX_Complete.
In total 4 minutes to sent a Message for 51ms Airtime
This is going on for every packet transmitted

**My Question is: **
Why does RXTimeout takes sooo long?
What causes the RXTimeout?
Why is there even a Recieving window if I do not enable ACK in txdata2?
How can I shorten or Disable RX Window
If I try out to Reieve Messages with the Uplink function they are never recieved…
If I use different nodes with similar ESP32 and similar RM95(different GPIOs used) modules an the
matthijskooijman/arduino-lmic it works like a charm and trasnmits within seconds

Serial Logs:

20:54:47.246 -> Starting
20:54:47.246 -> ** Stopping WiFi+BT
20:54:47.339 -> BME check: 1 BMP280 Temp Sensor found on I2C
20:54:47.339 -> BMP280 I2C: Temp = 23.37 *C Pressure = 975.61 hPa Approx altitude = 318.18 m
20:54:49.915 -> Display setup done
20:54:50.009 -> _PowerOn : 91001
20:54:53.938 -> _Update_Full : 3858001
20:54:54.172 -> _PowerOff : 232001
20:54:54.172 -> Basic E-Ink Display Update done -> No more E-Ink Display is Touched
20:54:54.172 -> RXMODE_RSSI
20:54:54.172 -> 562181: engineUpdate, opmode=0x8
20:54:54.172 -> Temp:23.37Packet queued
20:54:54.172 -> 562202: EV_JOINING
20:54:54.172 -> 562205: engineUpdate, opmode=0xc
20:54:55.813 -> 662454: engineUpdate, opmode=0xc
20:54:55.813 -> 662470: EV_TXSTART
20:54:55.813 -> 662535: TXMODE, freq=868100000, len=23, SF=8, BW=125, CR=4/5, IH=0
20:55:00.902 -> start single rx: now-rxtime: 3
20:55:00.902 -> 980748: RXMODE_SINGLE, freq=868100000, SF=8, BW=125, CR=4/5, IH=0
20:55:00.949 -> rxtimeout: entry: 984221 rxtime: 980742 entry-rxtime: 3479 now-entry: 3 rxtime-txend: 311126
20:55:01.886 -> start single rx: now-rxtime: 3
20:55:01.886 -> 1042998: RXMODE_SINGLE, freq=869525000, SF=12, BW=125, CR=4/5, IH=0
20:55:02.167 -> rxtimeout: entry: 1059399 rxtime: 1042992 entry-rxtime: 16407 now-entry: 3 rxtime-txend: 373376
20:55:02.167 -> 1059418: EV_JOIN_TXCOMPLETE: No JoinAccept
20:55:02.167 -> 1059467: engineUpdate, opmode=0xc
20:56:53.303 -> 8007806: engineUpdate, opmode=0xc
20:56:53.303 -> 8007820: EV_TXSTART
20:56:53.303 -> 8007884: TXMODE, freq=868300000, len=23, SF=8, BW=125, CR=4/5, IH=0
20:56:58.421 -> start single rx: now-rxtime: 3
20:56:58.421 -> 8326097: RXMODE_SINGLE, freq=868300000, SF=8, BW=125, CR=4/5, IH=0
20:56:58.466 -> rxtimeout: entry: 8329569 rxtime: 8326091 entry-rxtime: 3478 now-entry: 4 rxtime-txend: 311126
20:56:59.390 -> start single rx: now-rxtime: 3
20:56:59.390 -> 8388347: RXMODE_SINGLE, freq=869525000, SF=12, BW=125, CR=4/5, IH=0
20:56:59.702 -> rxtimeout: entry: 8404748 rxtime: 8388341 entry-rxtime: 16407 now-entry: 3 rxtime-txend: 373376
20:56:59.702 -> 8404767: EV_JOIN_TXCOMPLETE: No JoinAccept
20:56:59.702 -> 8404816: engineUpdate, opmode=0xc
20:58:59.570 -> 15899208: engineUpdate, opmode=0xc
20:58:59.570 -> 15899222: EV_TXSTART
20:58:59.570 -> 15899286: TXMODE, freq=868500000, len=23, SF=8, BW=125, CR=4/5, IH=0
20:59:04.669 -> start single rx: now-rxtime: 3
20:59:04.669 -> 16217498: RXMODE_SINGLE, freq=868500000, SF=8, BW=125, CR=4/5, IH=0
20:59:04.843 -> 16227370: EV_JOINED
20:59:04.843 -> netid: 19
20:59:04.843 -> devaddr: XXXXX
20:59:04.843 -> AppSKey: XXXXXX
20:59:04.843 -> NwkSKey: XXXXXXX
20:59:04.843 -> 16227580: engineUpdate, opmode=0x808
20:59:04.843 -> 16227797: EV_TXSTART
20:59:04.843 -> 16227957: TXMODE, freq=867500000, len=15, SF=8, BW=125, CR=4/5, IH=0
21:00:19.963 -> start single rx: now-rxtime: 3687927
21:00:19.963 -> 20922061: RXMODE_SINGLE, freq=867500000, SF=8, BW=125, CR=4/5, IH=0
21:00:49.939 -> rxtimeout: entry: 22797069 rxtime: 17234130 entry-rxtime: 5562939 now-entry: 3 rxtime-txend: 62126
21:01:49.942 -> start single rx: now-rxtime: 9250739
21:01:49.942 -> 26547122: RXMODE_SINGLE, freq=869525000, SF=9, BW=125, CR=4/5, IH=0
21:02:19.942 -> rxtimeout: entry: 28422131 rxtime: 17296380 entry-rxtime: 11125751 now-entry: 4 rxtime-txend: 124376
21:02:49.954 -> 30297136: EV_TXCOMPLETE (includes waiting for RX windows)
21:02:49.954 -> 30297140: engineUpdate, opmode=0x900
21:03:20.046 -> _PowerOn : 91001
21:03:20.352 -> _Update_Part : 292001
21:03:20.385 ->  next_time:544728
21:03:20.385 -> BMP280 I2C: Temp = 23.36 *C Druck = 975.55 hPa Approx altitude = 318.71 m
21:03:20.385 -> 32199447: engineUpdate, opmode=0x908
21:03:20.385 -> 32199474: EV_TXSTART
21:03:20.385 -> 32199534: TXMODE, freq=867700000, len=15, SF=8, BW=125, CR=4/5, IH=0
21:03:20.385 -> Temp:23.36Packet queued
21:04:49.930 -> start single rx: now-rxtime: 3687926
21:04:49.930 -> 37796623: RXMODE_SINGLE, freq=867700000, SF=8, BW=125, CR=4/5, IH=0
21:05:19.949 -> rxtimeout: entry: 39671631 rxtime: 34108693 entry-rxtime: 5562938 now-entry: 4 rxtime-txend: 62126
21:06:19.945 -> start single rx: now-rxtime: 9250738
21:06:19.945 -> 43421685: RXMODE_SINGLE, freq=869525000, SF=9, BW=125, CR=4/5, IH=0
21:06:49.961 -> rxtimeout: entry: 45296693 rxtime: 34170943 entry-rxtime: 11125750 now-entry: 4 rxtime-txend: 124376
21:07:19.956 -> 47171694: EV_TXCOMPLETE (includes waiting for RX windows)
21:07:19.956 -> 47171697: engineUpdate, opmode=0x900
21:07:50.273 -> _Update_Part : 292001
21:07:50.305 ->  next_time:814728
21:07:50.305 -> BMP280 I2C: Temp = 23.21 *C Druck = 975.49 hPa Approx altitude = 319.24 m
21:07:50.305 -> 49068254: engineUpdate, opmode=0x908
21:07:50.305 -> 49068280: EV_TXSTART
21:07:50.305 -> 49068341: TXMODE, freq=867900000, len=15, SF=8, BW=125, CR=4/5, IH=0
21:07:50.305 -> Temp:23.21Packet queued
21:09:19.954 -> start single rx: now-rxtime: 3687927
21:09:19.954 -> 54671686: RXMODE_SINGLE, freq=867900000, SF=8, BW=125, CR=4/5, IH=0
21:09:49.960 -> rxtimeout: entry: 56546693 rxtime: 50983755 entry-rxtime: 5562938 now-entry: 4 rxtime-txend: 62126
21:10:49.952 -> start single rx: now-rxtime: 9250738
21:10:49.952 -> 60296747: RXMODE_SINGLE, freq=869525000, SF=9, BW=125, CR=4/5, IH=0
21:11:19.948 -> rxtimeout: entry: 62171755 rxtime: 51046005 entry-rxtime: 11125750 now-entry: 4 rxtime-txend: 124376
21:11:49.968 -> 64046756: EV_TXCOMPLETE (includes waiting for RX windows)
21:11:49.968 -> 64046759: engineUpdate, opmode=0x900
21:12:20.276 -> _Update_Part : 292001
21:12:20.312 ->  next_time:1084728
21:12:20.312 -> BMP280 I2C: Temp = 23.14 *C Druck = 975.43 hPa Approx altitude = 319.75 m
21:12:20.312 -> 65943316: engineUpdate, opmode=0x908
21:12:20.312 -> 65943343: EV_TXSTART
21:12:20.312 -> 65943403: TXMODE, freq=868100000, len=15, SF=8, BW=125, CR=4/5, IH=0
21:12:20.312 -> Temp:23.14Packet queued
21:13:49.967 -> start single rx: now-rxtime: 3687927
21:13:49.967 -> 71546748: RXMODE_SINGLE, freq=868100000, SF=8, BW=125, CR=4/5, IH=0
21:14:19.960 -> rxtimeout: entry: 73421755 rxtime: 67858817 entry-rxtime: 5562938 now-entry: 4 rxtime-txend: 62126
21:15:19.959 -> start single rx: now-rxtime: 9250738
21:15:19.959 -> 77171809: RXMODE_SINGLE, freq=869525000, SF=9, BW=125, CR=4/5, IH=0
21:15:49.968 -> rxtimeout: entry: 79046817 rxtime: 67921067 entry-rxtime: 11125750 now-entry: 4 rxtime-txend: 124376
21:16:19.965 -> 80921818: EV_TXCOMPLETE (includes waiting for RX windows)
21:16:19.965 -> 80921821: engineUpdate, opmode=0x900
21:16:50.287 -> _Update_Part : 292001
21:16:50.321 ->  next_time:1354728
21:16:50.321 -> BMP280 I2C: Temp = 23.05 *C Druck = 975.35 hPa Approx altitude = 320.42 m
21:16:50.321 -> 82818378: engineUpdate, opmode=0x908
21:16:50.321 -> 82818404: EV_TXSTART
21:16:50.321 -> 82818465: TXMODE, freq=868300000, len=15, SF=8, BW=125, CR=4/5, IH=0
21:16:50.321 -> Temp:23.05Packet queued

TTN Console
Public Gateway:

{
  "time": "2020-01-16T20:03:28.232177553Z",
  "frequency": 867.7,
  "modulation": "LORA",
  "data_rate": "SF8BW125",
  "coding_rate": "4/5",
  "gateways": [
    {
      "gtw_id": "eui-7276ff000b0325b8",
      "timestamp": 237909852,
      "time": "",
      "channel": 3,
      "rssi": -123,
      "snr": -10.2,
      "latitude": xxx,
      "longitude": xxx,
      "location_source": "registry"
    },
    {
      "gtw_id": "eui-7276ff000b031dec",
      "timestamp": 776810852,
      "time": "",
      "channel": 3,
      "rssi": -121,
      "snr": -6.8,
      "latitude": xxx,
      "longitude": xxx,
      "location_source": "registry"
    },
    {
      "gtw_id": "eui-7276ff000b031f26",
      "timestamp": 127337836,
      "time": "",
      "channel": 3,
      "rssi": -120,
      "snr": -1.8,
      "latitude": xxxx,
      "longitude":xxx,
      "location_source": "registry"
    }
  ],
  "latitude": 48.76929,
  "longitude": 8.935963,
  "altitude": 440,
  "location_source": "registry"
}

Another Packet with good SNR

{
  "time": "2020-01-16T19:59:12.220644021Z",
  "frequency": 867.5,
  "modulation": "LORA",
  "data_rate": "SF8BW125",
  "coding_rate": "4/5",
  "gateways": [
    {
      "gtw_id": "eui-7276ff000b0325b8",
      "timestamp": 4277333764,
      "time": "",
      "channel": 2,
      "rssi": -121,
      "snr": -8.2,
      "latitude": xxxx,
      "longitude": XXXX,
      "location_source": "registry"
    },
    {
      "gtw_id": "eui-7276ff000b031f26",
      "timestamp": 4166761740,
      "time": "",
      "channel": 2,
      "rssi": -117,
      "snr": 0.8,
      "latitude": XXXXX,
      "longitude": XXXX,
      "location_source": "registry"
    }
  ],
  "latitude": XXX,
  "longitude": XXXX,
  "altitude": 440,
  "location_source": "registry"
}

Single Channel Gateway:

{
  "time": "2020-01-16T20:16:57.762160282Z",
  "frequency": 868.3,
  "modulation": "LORA",
  "data_rate": "SF8BW125",
  "coding_rate": "4/5",
  "gateways": [
    {
      "gtw_id": "eui-d8a01dffff63473c",
      "timestamp": 1124468549,
      "time": "",
      "channel": 0,
      "rssi": -31,
      "snr": 11,
      "latitude": xxx
      "longitude": xxxx
      "altitude": 440
    }
  ],
  "latitude": xxx
  "longitude": xxx
  "altitude": 440,
  "location_source": "registry"
}
2

I installed a Single Channel Gateway (with a terrible Antenna) which only recieves packages from this node.

That was a serious mistake, though it’s not actually the cause of your observation, because

I can not see any Downlink Gateway Traffic on my Gateway which requires a Wait for RX.

A node is required to execute the two receive windows regardless if it expects to hear anything or not (the second would not be necessary if the first gets something, but that is about it)

21:13:49.967 → 71546748: RXMODE_SINGLE, freq=868100000, SF=8, BW=125, CR=4/5, IH=0
21:14:19.960 → rxtimeout: entry: 73421755 rxtime: 67858817 entry-rxtime: 5562938 now-entry: 4 rxtime-txend: 62126

This would be either a bug in the program logic or a wiring or pin configuration error causing the program to be unable to see that the radio has timed out.

Note however that it’s a ~30 second delay in detecting failure. You only get the larger number by including the inactive time between attempts.

Functionally the delay in recognizing that the radio has not received antyhing is not necessarily even an issue, except that you may be keeping things in an unnecessarily active state wasting battery, and that if this is happening on RX1 it would prevent receiving in RX2, which is rather heavily used for EU868.

The fact that most of your receives time out promptly suggests this this time it took 30 seconds is a glitchy behavior, either the hardware or some corruption of state causing the software to misoperate.

3

All TTN devices will listen after any uplink this is not optional, following the uplink all devices then have two small downlink windows to listen (RX1 and RX2) but these are very brief. All these are configured dependent on the region/country you are based in and so your device should match these too.

RX windows are there not just for your device ACK but also if the backend wishes to send your device data, ie your application is sending the device data.

Single channel gateways will not help diagnosis.

I’m curios why you had to force SPI.begin in hal_spi_init, was there an issue before this?

4

@jezd, @cslorabox: Many Thanks for your answer… I only used the single channel gateway to see if there is any traffic from TTN Network(in the console) that I might be missing.

I think I can rule out the Pin configuration and HW pinning due to the fact that OTAA is joining(which needs a working RX for the Keys). You might see this in the logs above.
Therefore I guess DIO0 and DIO1 is connected correct.

So it must be something in my SW.
But what might cause this hickup? or this delay.

@jezd: The only thing i changed in hal.cpp is my pin config
//SPI.begin();//Original commented out
//SPI.begin(lmic_pins.sck, lmic_pins.miso, lmic_pins.mosi, lmic_pins.cs);
SPI.begin(14, 2, 15, 26); /r/eplaced with my pin Config

5

Ok, have you set pinmap?

const lmic_pinmap lmic_pins = {
.nss = 10,
.rxtx = LMIC_UNUSED_PIN,
.rst = 9,
.dio = {2, 5, LMIC_UNUSED_PIN},
}

Just an example, so can you share yours?

have you got DIO1 set correctly? important re DIO1: RxTimeout

see link

6

here we go: here you can see my pin mappings:

//Lora Pinning for TTGO T5 Addon Board
  #define LORA_PIN_SPI_MOSI 15
  #define LORA_PIN_SPI_MISO 2
  #define LORA_PIN_SPI_SCK  14
  #define LORA_PIN_SPI_NSS  26  
  #define LORA_PIN_SPI_RST  33  
  #define LORA_PIN_SPI_DIO1 25
  #define LORA_PIN_SPI_DIO0 34

const lmic_pinmap lmic_pins = {
    .nss = LORA_PIN_SPI_NSS,
    .rxtx = LMIC_UNUSED_PIN,
    .rst = LMIC_UNUSED_PIN,
    .dio = {LORA_PIN_SPI_DIO0, LORA_PIN_SPI_DIO1, LMIC_UNUSED_PIN}, 
    .rxtx_rx_active = 0,
    // optional: set RSSI cal for listen-before-talk
    // this value is in dB, and is added to RSSI
    // measured prior to decision.
    // Must include noise guardband! Ignored in US,
    // EU, IN, other markets where LBT is not required.
    .rssi_cal = 0,
    // optional: override LMIC_SPI_FREQ if non-zero
    .spi_freq = 0,*/
    .rxtx_rx_active = 0,//copied from TTGO Board
    .rssi_cal = 10,//copied from TTGO ESP32 Board, doesn't matter if you set 0 or 10
    .spi_freq = 8000000, /* 8MHz */ //copied from TTGO Board 
};

copied from TTGO Board ```means identical values can be found in the MCCI LMIC
https://github.com/mcci-catena/arduino-lmic/blob/master/src/hal/getpinmap_ttgo_lora32_v1.cpp in line 64

And I am using the Library for LMIC from MCCI Catena: not the one from matthijskooijman

maybe I need to switch over to matthijskooijman Arduino LMIC and try out there.???

You may want to see the whole sketch here:

7

If you look at the respective number of fixes in each, that one is much less maintained

1 Like
8

found it :slight_smile:
in my loop{} the os_runloop_once(); was not fired often enough.

Since I am only calculating Stuff now when no TX is ongoing everything works fine. :slight_smile:
Thanks for all your help.

Still got the issue that I can’t recieve any packets…but thats a different story :frowning:

1 Like
9

That’s probably due to either incorrect timing on the node, or else the issues many “fakeways” have with transmitting downlinks

10

In may well all be related to code and timing, LMIC is very sensitive on the EVENT handling side too even with logging to serial ports - its prob worth posting to MCCI github too, they are quick to respond.

MCCI libraries are well supported.

1 Like