Strange problem: RFM95 + LMIC-Arduino, long JOIN delays and missing frames

bluejedi · June 27, 2018, 10:16am

Have you relaxed LMIC timing? The ATmega32 Pro Mini 3.3V is relatively slow (for LMIC) and needs this adjustment. See below:

If you don’t relax timing the OTAA join will fail on the lowest spreading factors (starts the first join at SB7). In which case it will do several retries and gradually increase the spreading factor until it reaches one where it receives the JOIN ACCEPT without timing issues.
But this does not explain why you do not see the framecounter starting at 0.

Some remarks:

“A $10 Arduino Pro Mini and a $5 bare RFM95 module from China”
That’s a relatively expensive Pro Mini. When ordering the RFM95 in China a Pro Mini can be ordered there for less than $1.50.
A more correct topic title would be “Evaluating RFM95 + Arduino LMIC versus RN2903 for DIY nodes”.
(Even more correct is to use “LMIC-Arduino” because that is the real name of the library".)
“and I don’t understand why anyone would design an Arduino board around one”.
Because it generates simpler and more compact boards that require less components with built-in USB support. You can even make the board a true USB device (not just use it for serial over USB).
Yes it is t is easier and more comfortable if you only have to select ‘upload’ from your IDE, but pressing a reset button before every upload is not a huge task. The ATmega32u4 is not the only microcontroller with such behavior. Using STM32 microcontrollers can have similar behavior when used with the Arduino framework (depending on the controller and used upload method).
If you use a few boards for generic prototyping then you will probably upload to them often. If you have multiple boards in use for dedicated purposes then you will normally do very little uploads once the board is running. Having to press a reset button is not such an issue then.
(I don’t have a Things Node so I have no experience with possible picky behavior of its reset button.)
When you need the serial port over USB in your sketch it may not be ready yet when your Arduino setup() function runs. In that case you can wait for the serial port to become ready and even use a timeout and continue in case there is no serial port connected via USB (i.e. when the board runs unconnected).
You do not have to wait for the Serial monitor in setup but with ATmega32u4 if you don’t you will very probably miss your first output.

bluejedi · June 27, 2018, 10:48am

The best and most simple would be if Semtech would provide (a) good LoRaWAN reference stack(s) with implementations for each of the popular microcontroller families and frameworks, Arduino included.

It’s Semtech’s hardware and IP but they have a monopoly position for LoRa(WAN) hence no competition so may less/not be motivated to provide the best software platforms and developer support.

LoRaTracker · June 27, 2018, 12:00pm

You would think a ‘universal’, easy to understand and well documented LoRaWAN stack would encorouge sales as more people found it they could develop applications.

But then I presume Semtech themselves have the best understanding of their market, so if they have not followed this route, then they have good reasons.

kersing · June 27, 2018, 4:23pm

They do provide a reference implementation at https://github.com/Lora-net/LoRaMac-node

m2mlorawan · June 28, 2018, 2:14am

For this option, we don’t have any problems to Join with OTAA. It normally joins accept in the first attempt.

tweil · June 28, 2018, 5:37am

Thanks for all the responses and help.

I did mention a Pro Mini when I was discussing prices, but the two nodes I am actually testing with are comprised of slightly faster:

Ardunio Uno R3 with a Dragino 1.4 Shield (5V, 16Mhz with level shifters in the Dragino shield)
Moteino R6 with no onboard transceiver
(Specifications | All about Moteino | LowPowerLab) an Atmel 328p board running at 3.3V and 16Mhz connected directly to a Hope RFM95 Lora module.

So these nodes are not slow 8Mhz Pro Mini, but I tried the relaxed timing.I put the relaxed timing command just after the reset command in each sketch. Is this correct?

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

// Have you relaxed the timing by using
LMIC_setClockError(MAX_CLOCK_ERROR * 1 / 100);

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

After adding the relaxed timing command my Uno/Dragino node joined during the first attempt at SF9. Sometimes the join is still failing many times until successful. Occasionally, the JOIN fails continuously until after another reboot attempt.

Should the timing be relaxed even further, and if so, how much and what is the command?

Here is the Gateway Console after a successful JOIN.

Here is the node log from a fast JOIN at SF9 :

Starting that joins at SF9
217: engineUpdate, opmode=0x8
Packet queued
2340: EV_JOINING
3509: engineUpdate, opmode=0xc
5796: TXMODE, freq=902300000, len=23, SF=7, BW=125, CR=4/5, IH=0
316243: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
377903: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
387521: engineUpdate, opmode=0xc
423391: engineUpdate, opmode=0xc
423692: TXMODE, freq=903000000, len=23, SF=8, BW=500, CR=4/5, IH=0
734155: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
795816: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
805434: engineUpdate, opmode=0xc
975011: engineUpdate, opmode=0xc
975312: TXMODE, freq=908300000, len=23, SF=8, BW=125, CR=4/5, IH=0
1289771: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
1352527: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1362082: engineUpdate, opmode=0xc
1371255: engineUpdate, opmode=0xc
1371557: TXMODE, freq=912600000, len=23, SF=8, BW=500, CR=4/5, IH=0
1682023: RXMODE_SINGLE, freq=926900000, SF=7, BW=500, CR=4/5, IH=0
1743682: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1753235: engineUpdate, opmode=0xc
1771035: engineUpdate, opmode=0xc
1771337: TXMODE, freq=905100000, len=23, SF=9, BW=125, CR=4/5, IH=0
2091521: RXMODE_SINGLE, freq=926900000, SF=9, BW=500, CR=4/5, IH=0
2097243: EV_JOINED

Here is the node log of a VERY slow JOIN that never completes after just restarting the node with no changes other changes:

Starting
181: engineUpdate, opmode=0x8
Packet queued
2304: EV_JOINING
3473: engineUpdate, opmode=0xc
5761: TXMODE, freq=902300000, len=23, SF=7, BW=125, CR=4/5, IH=0
316271: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
377931: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
387548: engineUpdate, opmode=0xc
402093: engineUpdate, opmode=0xc
402394: TXMODE, freq=903000000, len=23, SF=8, BW=500, CR=4/5, IH=0
712857: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
774517: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
784135: engineUpdate, opmode=0xc
815170: engineUpdate, opmode=0xc
815470: TXMODE, freq=910700000, len=23, SF=8, BW=125, CR=4/5, IH=0
1129994: RXMODE_SINGLE, freq=924500000, SF=8, BW=500, CR=4/5, IH=0
1192750: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1202303: engineUpdate, opmode=0xc
1252804: engineUpdate, opmode=0xc
1253105: TXMODE, freq=906200000, len=23, SF=8, BW=500, CR=4/5, IH=0
1563635: RXMODE_SINGLE, freq=924500000, SF=7, BW=500, CR=4/5, IH=0
1625295: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1634849: engineUpdate, opmode=0xc
1652304: engineUpdate, opmode=0xc
1652606: TXMODE, freq=911700000, len=23, SF=9, BW=125, CR=4/5, IH=0
1972790: RXMODE_SINGLE, freq=927500000, SF=9, BW=500, CR=4/5, IH=0
2035482: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
2045036: engineUpdate, opmode=0xc
2058187: engineUpdate, opmode=0xc
2058489: TXMODE, freq=914200000, len=23, SF=8, BW=500, CR=4/5, IH=0
2369019: RXMODE_SINGLE, freq=927500000, SF=7, BW=500, CR=4/5, IH=0
2430679: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
2440308: engineUpdate, opmode=0xc
2495607: engineUpdate, opmode=0xc
2495909: TXMODE, freq=908700000, len=23, SF=10, BW=125, CR=4/5, IH=0
2826455: RXMODE_SINGLE, freq=923300000, SF=10, BW=500, CR=4/5, IH=0
2889019: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
2898509: engineUpdate, opmode=0xc
2942977: engineUpdate, opmode=0xc
2943278: TXMODE, freq=903000000, len=23, SF=8, BW=500, CR=4/5, IH=0
3253808: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
3315468: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
3325022: EV_JOIN_FAILED
3325050: engineUpdate, opmode=0xc
4014527: engineUpdate, opmode=0xc
4014830: TXMODE, freq=903700000, len=23, SF=10, BW=125, CR=4/5, IH=0
4345439: RXMODE_SINGLE, freq=927500000, SF=10, BW=500, CR=4/5, IH=0
4408003: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
4417557: engineUpdate, opmode=0xc
4463986: engineUpdate, opmode=0xc
4464287: TXMODE, freq=914200000, len=23, SF=8, BW=500, CR=4/5, IH=0
4774754: RXMODE_SINGLE, freq=927500000, SF=7, BW=500, CR=4/5, IH=0
4836413: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
4845903: EV_JOIN_FAILED
.... much later ....
28251665: TXMODE, freq=906300000, len=23, SF=10, BW=125, CR=4/5, IH=0
28582083: RXMODE_SINGLE, freq=925700000, SF=10, BW=500, CR=4/5, IH=0
28644648: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
28654138: engineUpdate, opmode=0xc
28677971: engineUpdate, opmode=0xc
28678274: TXMODE, freq=909400000, len=23, SF=8, BW=500, CR=4/5, IH=0
28988742: RXMODE_SINGLE, freq=925700000, SF=7, BW=500, CR=4/5, IH=0
29050403: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
29059892: EV_JOIN_FAILED
29059924: engineUpdate, opmode=0xc
29831904: engineUpdate, opmode=0xc
29832207: TXMODE, freq=911700000, len=23, SF=10, BW=125, CR=4/5, IH=0
30162625: RXMODE_SINGLE, freq=927500000, SF=10, BW=500, CR=4/5, IH=0
30225189: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
30234678: engineUpdate, opmode=0xc
30234910: engineUpdate, opmode=0xc
30235284: TXMODE, freq=914200000, len=23, SF=8, BW=500, CR=4/5, IH=0
30545735: RXMODE_SINGLE, freq=927500000, SF=7, BW=500, CR=4/5, IH=0
30607395: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
30616884: EV_JOIN_FAILED

This node kept repeating the same JOIN pattern and never finished joining after 20 minutes or so.

So to summarize the JOIN behavior, the relaxed timimg seemed to help the JOIN process happen faster, but not every time and never as quickly as The Things Uno that joins immediately.

What hardware are you using? What version of the Arduino-LMIC library are you using? Have you relaxed the timing?

================================================

On to a different topic of why after a JOIN I don’t see data from the node for 15-60minutes

I didn’t explain this very well and still have the problem after relaxing the timing. It is probably a different issue. Let me try to explain again.

When you JOIN a node with OTAA, the frame counter always resets to 0 automatically and you don’t need to do anything to start getting data, which is great. (When I was using ABP in earlier single channel nodes and gateways, I needed to reset the frame counter in the Device Overview to 0 or I would miss frames.)

What I was poorly explaining is that once a node like my Uno/Dragino mentioned above JOINs, with or without the relaxed timing, I do not see data arriving in either the Gateway Traffic or the Application Data for the device for anywhere from 15-60 minutes. When it does start to arrive, the frame counter has already risen to anywhere from 15-60 (my test node sends data once/minute).

My Application Console generally looks like this. In this example, the node JOINS at 23:50. Then there is no data received in the Application Console (or the Gateway Console for that matter) until 00:24 and the counter is already at 33.

I am positive that the device frame counter resets to 0 after a successful OTAA JOIN:

During the time after the JOIN and before I see data in the Application Console, I do see is activity at the node Serial Monitor that looks like successful transmissions after a successful join at 2097243 below.

Starting
217: engineUpdate, opmode=0x8
Packet queued
2340: EV_JOINING
3509: engineUpdate, opmode=0xc
5796: TXMODE, freq=902300000, len=23, SF=7, BW=125, CR=4/5, IH=0
316243: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
377903: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
387521: engineUpdate, opmode=0xc
423391: engineUpdate, opmode=0xc
423692: TXMODE, freq=903000000, len=23, SF=8, BW=500, CR=4/5, IH=0
734155: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
795816: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
805434: engineUpdate, opmode=0xc
975011: engineUpdate, opmode=0xc
975312: TXMODE, freq=908300000, len=23, SF=8, BW=125, CR=4/5, IH=0
1289771: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
1352527: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1362082: engineUpdate, opmode=0xc
1371255: engineUpdate, opmode=0xc
1371557: TXMODE, freq=912600000, len=23, SF=8, BW=500, CR=4/5, IH=0
1682023: RXMODE_SINGLE, freq=926900000, SF=7, BW=500, CR=4/5, IH=0
1743682: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1753235: engineUpdate, opmode=0xc
1771035: engineUpdate, opmode=0xc
1771337: TXMODE, freq=905100000, len=23, SF=9, BW=125, CR=4/5, IH=0
2091521: RXMODE_SINGLE, freq=926900000, SF=9, BW=500, CR=4/5, IH=0
2097243: EV_JOINED

2097270: engineUpdate, opmode=0x808
2097650: TXMODE, freq=907500000, len=16, SF=9, BW=125, CR=4/5, IH=0
2166492: RXMODE_SINGLE, freq=924500000, SF=9, BW=500, CR=4/5, IH=0
2229249: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
2233681: EV_TXCOMPLETE (includes waiting for RX windows)
2233726: engineUpdate, opmode=0x900
5983725: engineUpdate, opmode=0x908
....
64297075: TXMODE, freq=910700000, len=16, SF=9, BW=125, CR=4/5, IH=0
Packet queued
64367068: RXMODE_SINGLE, freq=924500000, SF=9, BW=500, CR=4/5, IH=0
64429824: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
64434193: EV_TXCOMPLETE (includes waiting for RX windows)
64434241: engineUpdate, opmode=0x900
68184240: engineUpdate, opmode=0x908
68184622: TXMODE, freq=910900000, len=16, SF=9, BW=125, CR=4/5, IH=0
Packet queued
68254615: RXMODE_SINGLE, freq=925100000, SF=9, BW=500, CR=4/5, IH=0
68317371: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
68321750: EV_TXCOMPLETE (includes waiting for RX windows)
68321799: engineUpdate, opmode=0x900

So to summarize: After a successful JOIN, data does not start flowing into the Application Data Console or Gateway Traffic Console for sometimes 15-60 minutes. The device frame counter has been reset to 0 automatically after the OTAA JOIN. When the data does start to flow into the consoles, anywhere from 0 to 15 to 60 counter messages have been lost.

================================================

Last Topic, the dreaded 32U4 Arduino upload process:

bluejedi:

“and I don’t understand why anyone would design an Arduino board around one”.
Because it generates simpler and more compact boards that require less components with built-in USB support. You can even make the board a true USB device (not just use it for serial over USB).
Yes it is t is easier and more comfortable if you only have to select ‘upload’ from your IDE, but pressing a reset button before every upload is not a huge task. The ATmega32u4 is not the only microcontroller with such behavior. Using STM32 microcontrollers can have similar behavior when used with the Arduino framework (depending on the controller and used upload method).
If you use a few boards for generic prototyping then you will probably upload to them often. If you have multiple boards in use for dedicated purposes then you will normally do very little uploads once the board is running. Having to press a reset button is not such an issue then.
(I don’t have a Things Node so I have no experience with possible picky behavior of its reset button.

I have multiple boards, but as I evaluate them and explore attaching sensors and learning how to write the code, there are many opportunities for uploading new code. If it were simply a matter of pressing the reset button for each upload, I would not mind. Sometimes, a single press of the reset button is all you need and sometimes you don’t need to press it at all. (For the Things Node you need to open the case, remove the batteries and then remove the circuit board to reach the reset button.)

Many times you need to very carefully time when you need to double click the reset button to give the bootloader 8 seconds (Leonardo bootloader is compiled with a Rest Delay) to find the correct COM port.

Here is somewhat of a general explanation fo the problem:
https://www.avrfreaks.net/forum/com-port-change-during-flash-upload

The trick is to doubleclick the reset button as the second COM port (COM6 in this example) pops up in the command window. While annoying, this works consistently UNLESS for some reason you don’t get the “Forcing reset using 1200bps open/close on port COMx” line before the COM ports get listed. Then you are toast and need to start over again. I’m not sure why the forced reset fails sometimes. Here is what it looks like when it works:

Global variables use 498 bytes (19%) of dynamic memory, leaving 2,062 bytes for local variables. Maximum is 2,560 bytes.
Forcing reset using 1200bps open/close on port COM4 (Only if this appears can you double click reset below)
PORTS {COM4, } / {} => {}
PORTS {} / {} => {}
PORTS {} / {COM6, } => {COM6, }  (Double click the reset button here!)
Found upload port: COM6

When it doesn’t work, I could end up retrying dozens and dozens of times for hours sometimes until it magically works. Unless someone can explain it, I will just avoid 32U4 based boards from now on. It is too painful and there are plenty of other options for boards that have 2 hardware serial ports, one for debug and one to communicate with the RN2903.

The basic sketch for The Things Uno has a delay to allow the serial port to become ready. This part of the serial port has not been a problem:

void setup()
{
 loraSerial.begin(57600);
  debugSerial.begin(9600);

  // Wait a maximum of 10s for Serial Monitor
  while (!debugSerial && millis() < 10000 ;

bluejedi · June 28, 2018, 8:55am

I have used RFM95 with Pro Mini 8MHz and with 32u4 8MHz AVR microcontrollers only. I don’t know if a normal 16MHz AVR needs relaxed LMIC timing or not, but I think relaxing timing any further is not going to solve your issues. (No experience with 915MHz/US here).

I put the relaxed timing command just after the reset command in each sketch. Is this correct?

Yes.

Each of the two types of configurations used some type of Arduino supported microcontroller (UNO, Pro Micro, Leonardo, Mega) that I am very comfortable with (I’m not a great firmware guy) that was connected to

Please list the specific board and RFM95 LoRa module combinations that you have tested.
Which combinations do give problems?
Do all these combinations show exactly the same problems?
Are there any combinations that work without problems?
Have you checked the entries in the Console Application Data log to see which gateways received the messages and what the SNR and RSSI values are. Does this reveal any unusual patterns?

Ryanteck · June 28, 2018, 9:50am

As well as the fact the LoRa stack is on the RN2903 it is also LoRaWAN Certified along with being CE Marked and such which can be a benefit in some projects.

Another point that I’ve found is that the RN2903 according to the datasheet draws less amperage during operation of around 35mA vs the RFM95 at 100mA. Could be quite a difference for a long term battery powered node.

However for now I’m keeping primarily with the RFM95 as price is the main winner for DIY Nodes, As mentioned you can get a Pro Mini for very cheap and a Fridge Sensor node I built for my degree project works out at less than £10 per unit depending on if I order the parts from China or not it can be cut by another £2-3 compared to the RN2903 at around £12

However there’s also the factor of for me currently the only source of RFM95s is China so it can take 3-4 weeks to arrive. At the same time Farnell in the UK is out of stock of the EU Version (RN2483) however RS components has stock and I can order one and it’ll be here tomorrow.

From a code point of view the RN2483 looks much easier to code. I’ve currently been using it just by sending commands using a USB to UART Adaptor.

LoRaTracker · June 28, 2018, 10:38am

On the RFM95s I have here, powered by an Arduino Pro Mini and using the LMIC library I get around 6.8mA in idle, 17.9mA with the receiver permanently on and 114mA when transmitting a packet.

m2mlorawan · July 2, 2018, 6:30am

What hardware are you using? What version of the Arduino-LMIC library are you using? Have you relaxed the timing?

I use both ATMEGA328P-PU and ATMEGA1284P-PU on our own PCB. Yes, we relexed the timing. LMIC is https://github.com/orenonline/arduino-lmic-as923 that supports AS1.

aaaa

tweil · July 2, 2018, 6:20pm

I have tested two types of 915Mhz nodes that use a Hope RFM95 Lora module

Arduino Uno R3 with a Dragino 1.4 Shield (5V, 16Mhz with level shifters, HopeRFM95 module) . I am using the Dragino default jumpers with the following pin mapping:

// Pin mapping Dragino Shield
const lmic_pinmap lmic_pins = {
.nss = 10,
.rxtx = LMIC_UNUSED_PIN,
.rst = 9,
.dio = {2, 6, LMIC_UNUSED_PIN},
};

Moteino R6 with NO onboard transceiver
(Specifications | All about Moteino | LowPowerLab) an Atmel 328p board running at 3.3V and 16Mhz. This is connected directly to a Hope RFM95 Lora module using jumper wires and the following pin mapping:

//Hope RFM95 Lora Module
const lmic_pinmap lmic_pins = {
.nss = 10,
.rxtx = LMIC_UNUSED_PIN,
.rst = 5,
.dio = {2, 3, LMIC_UNUSED_PIN},
};

In both cases, I am using the ttn-otaa.ino example sketch from the LMIC-Arduino library. The only changes to the script are adding the Deveui, Appeui, Appkey and adding the relaxed timing:

    LMIC_reset();
    // Have you relaxed the timing by using
    LMIC_setClockError(MAX_CLOCK_ERROR * 1 / 100);

The library version I am using is the following. Maybe I should try a different one?

name=LMIC-Arduino
version=1.5.0+arduino-2
author=IBM
maintainer=Matthijs Kooijman <matthijs@stdin.nl>

Unfortunately, my TTN Gateway is the only one within 100 miles. The Gateway happily accepts messages and JOINs from my Things Uno and Things Node.

Both nodes give me the same problem of slow OTAA joins and sometimes 15-60 minutes of delay before the data starts showing up in the Gateway and App Console, and then the counter is already past 0.

bluejedi · July 2, 2018, 7:27pm

Summary:

So you have two different MCU’s and two different RFM95 modules that are used with LMIC-Arduino.
Both combinations give problems with OTAA JOINS.
The problem manifests in two different ways:

Long delays before a JOIN ACCEPT is successfully received on the nodes.
When looking at the Console Application Data log you are missing several messages because the frame number starts at a number much higher than 0.

Your two other nodes, both RN2903 based do not show the problematic symptoms that your RFM95+LMIC nodes are showing.
You are using the latest release of LMIC-Arduino (no need to try a different one).
,
,

You say your TTN gateway is the only one within 100 miles.

What gateway do you have? A real (normal TTN/LoRaWAN compliant) gateway or a single channel gateway?
What is the hardware and what software is it running?

It will be interesting to see your Gateway traffic log when only running one of the RN2903 based nodes, from the first join request, including join accept up to the first few messages (frames) with visible: time, frequency, data rate frame counter and device address.

And also the entries in the Application Data log from the first join request up to the first few messages with visible: time, counter and device address (in join request).

And then the same (both logs) for one of the problematic RFM95+LMIC nodes.
(From first join request up to the successful join accept and the first few messages.)
.
.

Have you checked the content of the Application Data log entries (fold out) and checked which gateway(s) have received the messages?

Have you checked data rates, RSSI and SNR for these messages. What are their values? Are they stable or is there possibly much variation?

Do you see all frames in the Gateway Traffic log but maybe not in the Application Data log?
If there are messages in the gateway log from your devices that are not in the application log then fold them out and have a look at RSSI and SNR.

Note that all values can vary per message.

tweil · July 3, 2018, 12:15am

Your summary of my nodes and problem are correct.

I am using a real, multi-channel “The Things Network Gateway” running beta version:
v1.0.4-a7beae91 (2018-05-02T11:06:21Z) (Hmmm, beta version?)

tweil · July 3, 2018, 3:23am

Your summary of my nodes and problem are correct.

I am using a real, multi-channel “The Things Network Gateway” running beta version:
v1.0.4-a7beae91 (2018-05-02T11:06:21Z) (Hmmm, beta version?)

Things Uno Node:
Atmel 32U4 and RN2903.
Powered on at 8:58pm, Transmit every 20 seconds.

Arduino Uno and Dragino Shield v1.4
Atmel 328P and Hope RF95RFM
Powered on at 9:33pm, Transmit every 20 seconds.

Unfortunately, this was one of the rare times it worked well. The JOIN was less than 1 minute:

Starting
167: engineUpdate, opmode=0x8
Packet queued
2290: EV_JOINING
…

Click to see the full logs

Starting
167: engineUpdate, opmode=0x8
Packet queued
2290: EV_JOINING
3459: engineUpdate, opmode=0xc
5746: TXMODE, freq=902300000, len=23, SF=7, BW=125, CR=4/5, IH=0
316257: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
377917: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
387470: engineUpdate, opmode=0xc
442268: engineUpdate, opmode=0xc
442569: TXMODE, freq=903000000, len=23, SF=8, BW=500, CR=4/5, IH=0
753033: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
814693: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
824311: engineUpdate, opmode=0xc
858246: engineUpdate, opmode=0xc
858547: TXMODE, freq=903300000, len=23, SF=8, BW=125, CR=4/5, IH=0
1173070: RXMODE_SINGLE, freq=926300000, SF=8, BW=500, CR=4/5, IH=0
1235826: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1245379: engineUpdate, opmode=0xc
1251102: engineUpdate, opmode=0xc
1251404: TXMODE, freq=911000000, len=23, SF=8, BW=500, CR=4/5, IH=0
1561869: RXMODE_SINGLE, freq=926300000, SF=7, BW=500, CR=4/5, IH=0
1623529: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1633082: engineUpdate, opmode=0xc
1992155: engineUpdate, opmode=0xc
1992456: TXMODE, freq=904100000, len=23, SF=9, BW=125, CR=4/5, IH=0
2312640: RXMODE_SINGLE, freq=923900000, SF=9, BW=500, CR=4/5, IH=0
2318334: EV_JOINED
2318362: engineUpdate, opmode=0x808
2318820: TXMODE, freq=903900000, len=26, SF=9, BW=125, CR=4/5, IH=0
2390220: RXMODE_SINGLE, freq=923300000, SF=9, BW=500, CR=4/5, IH=0
2452976: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
2474118: Received downlink, window=RX2, port=-1, ack=0
2474164: EV_TXCOMPLETE (includes waiting for RX windows)
2477249: engineUpdate, opmode=0x800
3727248: engineUpdate, opmode=0x808
3727707: TXMODE, freq=904100000, len=28, SF=7, BW=125, CR=4/5, IH=0
Packet queued
3791681: RXMODE_SINGLE, freq=923900000, SF=7, BW=500, CR=4/5, IH=0
3793014: Received downlink, window=RX1, port=-1, ack=1
3795266: EV_TXCOMPLETE (includes waiting for RX windows)
3799038: engineUpdate, opmode=0x800
5049038: engineUpdate, opmode=0x808
5049496: TXMODE, freq=904300000, len=26, SF=7, BW=125, CR=4/5, IH=0
Packet queued
5113150: RXMODE_SINGLE, freq=924500000, SF=7, BW=500, CR=4/5, IH=0
5175994: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
5180362: EV_TXCOMPLETE (includes waiting for RX windows)
5180407: engineUpdate, opmode=0x900
6430408: engineUpdate, opmode=0x908
6430866: TXMODE, freq=904500000, len=26, SF=7, BW=125, CR=4/5, IH=0
Packet queued
6494519: RXMODE_SINGLE, freq=925100000, SF=7, BW=500, CR=4/5, IH=0
6557363: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
6561871: EV_TXCOMPLETE (includes waiting for RX windows)
6561915: engineUpdate, opmode=0x900
7811915: engineUpdate, opmode=0x908
7812374: TXMODE, freq=904700000, len=26, SF=7, BW=125, CR=4/5, IH=0
Packet queued
7876026: RXMODE_SINGLE, freq=925700000, SF=7, BW=500, CR=4/5, IH=0
7938870: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
7943239: EV_TXCOMPLETE (includes waiting for RX windows)
7943284: engineUpdate, opmode=0x900

tweil · July 3, 2018, 3:24am

Moteino and HopeRFM95
Atmel 328P and Hope RF95RFM (device says Adafruit RFM9x, but that module was not used here)
Powered on at 9:54pm, Transmit every 20 seconds.

In this case, the JOIN was under a minute, but data did not begin to populate the Application Data for 40 minutes, and then it started at counter 109. As you can see below, the Frame Counter started at 0.

Event Data for Join Request from Gateway Traffic Log. RSSI of -54 and SNR of 11.75 seems good. Gateway is about 30 feet away, 2 floors up.

{
“gw_id”: “burns_park_north_ttn_gateway”,
“payload”: “AFgAAdB+1bNwAQAAAAAAAABhtkOAyio=”,
“dev_eui”: “0000000000000001”,
“lora”: {
“spreading_factor”: 8,
“bandwidth”: 125,
“air_time”: 113152000
},
“coding_rate”: “4/5”,
“timestamp”: “2018-07-03T01:54:16.533Z”,
“rssi”: -54,
“snr”: 11.75,
“app_eui”: “70B3D57ED0010058”,
“frequency”: 905100000
}

Starting
179: engineUpdate, opmode=0x8
Packet queued
2302: EV_JOINING
…

Click to see the full logs

Starting
179: engineUpdate, opmode=0x8
Packet queued
2302: EV_JOINING
3471: engineUpdate, opmode=0xc
5759: TXMODE, freq=902300000, len=23, SF=7, BW=125, CR=4/5, IH=0
316269: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
377930: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
387554: engineUpdate, opmode=0xc
410349: engineUpdate, opmode=0xc
410649: TXMODE, freq=903000000, len=23, SF=8, BW=500, CR=4/5, IH=0
721113: RXMODE_SINGLE, freq=923300000, SF=7, BW=500, CR=4/5, IH=0
782773: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
792398: engineUpdate, opmode=0xc
1001381: engineUpdate, opmode=0xc
1001683: TXMODE, freq=905100000, len=23, SF=8, BW=125, CR=4/5, IH=0
1316020: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
1320870: EV_JOINED
1320897: engineUpdate, opmode=0x808
1321356: TXMODE, freq=907700000, len=26, SF=8, BW=125, CR=4/5, IH=0
1386973: RXMODE_SINGLE, freq=925100000, SF=8, BW=500, CR=4/5, IH=0
1449794: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
1454230: EV_TXCOMPLETE (includes waiting for RX windows)
1454275: engineUpdate, opmode=0x900
2704276: engineUpdate, opmode=0x908
2704734: TXMODE, freq=907900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
2771567: RXMODE_SINGLE, freq=925700000, SF=8, BW=500, CR=4/5, IH=0
2834387: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
2838824: EV_TXCOMPLETE (includes waiting for RX windows)
2838869: engineUpdate, opmode=0x900
4088868: engineUpdate, opmode=0x908
4089327: TXMODE, freq=908100000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
4156224: RXMODE_SINGLE, freq=926300000, SF=8, BW=500, CR=4/5, IH=0
4219044: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
4223479: EV_TXCOMPLETE (includes waiting for RX windows)
4223525: engineUpdate, opmode=0x900
5473524: engineUpdate, opmode=0x908
5473983: TXMODE, freq=908300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
5540880: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
5603700: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
5608136: EV_TXCOMPLETE (includes waiting for RX windows)
5608180: engineUpdate, opmode=0x900
6858180: engineUpdate, opmode=0x908
6858639: TXMODE, freq=908500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
6925535: RXMODE_SINGLE, freq=927500000, SF=8, BW=500, CR=4/5, IH=0
6988355: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
6992866: EV_TXCOMPLETE (includes waiting for RX windows)
6992912: engineUpdate, opmode=0x900
8242911: engineUpdate, opmode=0x908
8243369: TXMODE, freq=908700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
8310266: RXMODE_SINGLE, freq=923300000, SF=8, BW=500, CR=4/5, IH=0
8373086: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
8377522: EV_TXCOMPLETE (includes waiting for RX windows)
8377567: engineUpdate, opmode=0x900
9627567: engineUpdate, opmode=0x908
9628026: TXMODE, freq=908900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
9694923: RXMODE_SINGLE, freq=923900000, SF=8, BW=500, CR=4/5, IH=0
9757743: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
9762179: EV_TXCOMPLETE (includes waiting for RX windows)
9762223: engineUpdate, opmode=0x900
11012223: engineUpdate, opmode=0x908
11012683: TXMODE, freq=909100000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
11079451: RXMODE_SINGLE, freq=924500000, SF=8, BW=500, CR=4/5, IH=0
11142335: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
11146643: EV_TXCOMPLETE (includes waiting for RX windows)
11146691: engineUpdate, opmode=0x900
12396692: engineUpdate, opmode=0x908
12397152: TXMODE, freq=909300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
12463857: RXMODE_SINGLE, freq=925100000, SF=8, BW=500, CR=4/5, IH=0
12526676: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
12531048: EV_TXCOMPLETE (includes waiting for RX windows)
12531096: engineUpdate, opmode=0x900
13781097: engineUpdate, opmode=0x908
13781557: TXMODE, freq=909500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
13848325: RXMODE_SINGLE, freq=925700000, SF=8, BW=500, CR=4/5, IH=0
13911145: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
13915516: EV_TXCOMPLETE (includes waiting for RX windows)
13915564: engineUpdate, opmode=0x900
15165564: engineUpdate, opmode=0x908
15166024: TXMODE, freq=909700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
15232792: RXMODE_SINGLE, freq=926300000, SF=8, BW=500, CR=4/5, IH=0
15295613: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
15299921: EV_TXCOMPLETE (includes waiting for RX windows)
15299969: engineUpdate, opmode=0x900
16549968: engineUpdate, opmode=0x908
16550428: TXMODE, freq=909900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
16617133: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
16679952: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
16684324: EV_TXCOMPLETE (includes waiting for RX windows)
16684372: engineUpdate, opmode=0x900
17934373: engineUpdate, opmode=0x908
17934833: TXMODE, freq=910100000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
18001601: RXMODE_SINGLE, freq=927500000, SF=8, BW=500, CR=4/5, IH=0
18064421: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
18068869: EV_TXCOMPLETE (includes waiting for RX windows)
18068916: engineUpdate, opmode=0x900
19318916: engineUpdate, opmode=0x908
19319375: TXMODE, freq=910300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
19386144: RXMODE_SINGLE, freq=923300000, SF=8, BW=500, CR=4/5, IH=0
19448964: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
19453336: EV_TXCOMPLETE (includes waiting for RX windows)
19453384: engineUpdate, opmode=0x900
20703385: engineUpdate, opmode=0x908
20703845: TXMODE, freq=910500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
20770549: RXMODE_SINGLE, freq=923900000, SF=8, BW=500, CR=4/5, IH=0
20833369: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
20837741: EV_TXCOMPLETE (includes waiting for RX windows)
20837789: engineUpdate, opmode=0x900
22087788: engineUpdate, opmode=0x908
22088248: TXMODE, freq=910700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
22155017: RXMODE_SINGLE, freq=924500000, SF=8, BW=500, CR=4/5, IH=0
22217838: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
22222210: EV_TXCOMPLETE (includes waiting for RX windows)
22222258: engineUpdate, opmode=0x900
23472257: engineUpdate, opmode=0x908
23472717: TXMODE, freq=910900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
23539487: RXMODE_SINGLE, freq=925100000, SF=8, BW=500, CR=4/5, IH=0
23602306: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
23606678: EV_TXCOMPLETE (includes waiting for RX windows)
23606726: engineUpdate, opmode=0x900
24856727: engineUpdate, opmode=0x908
24857187: TXMODE, freq=911100000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
24923892: RXMODE_SINGLE, freq=925700000, SF=8, BW=500, CR=4/5, IH=0
24986711: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
24991083: EV_TXCOMPLETE (includes waiting for RX windows)
24991131: engineUpdate, opmode=0x900
26241132: engineUpdate, opmode=0x908
26241592: TXMODE, freq=911300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
26308360: RXMODE_SINGLE, freq=926300000, SF=8, BW=500, CR=4/5, IH=0
26371181: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
26375553: EV_TXCOMPLETE (includes waiting for RX windows)
26375601: engineUpdate, opmode=0x900
27625602: engineUpdate, opmode=0x908
27626062: TXMODE, freq=911500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
27692832: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
27755652: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
27760024: EV_TXCOMPLETE (includes waiting for RX windows)
27760072: engineUpdate, opmode=0x900
29010071: engineUpdate, opmode=0x908
29010531: TXMODE, freq=911700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
29077235: RXMODE_SINGLE, freq=927500000, SF=8, BW=500, CR=4/5, IH=0
29140055: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
29144502: EV_TXCOMPLETE (includes waiting for RX windows)
29144550: engineUpdate, opmode=0x900
30394550: engineUpdate, opmode=0x908
30395010: TXMODE, freq=911900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
30461778: RXMODE_SINGLE, freq=923300000, SF=8, BW=500, CR=4/5, IH=0
30524599: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
30528907: EV_TXCOMPLETE (includes waiting for RX windows)
30528955: engineUpdate, opmode=0x900
31778954: engineUpdate, opmode=0x908
31779414: TXMODE, freq=912100000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
31846182: RXMODE_SINGLE, freq=923900000, SF=8, BW=500, CR=4/5, IH=0
31909002: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
31913374: EV_TXCOMPLETE (includes waiting for RX windows)
31913423: engineUpdate, opmode=0x900
33163423: engineUpdate, opmode=0x908
33163883: TXMODE, freq=912300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
33230652: RXMODE_SINGLE, freq=924500000, SF=8, BW=500, CR=4/5, IH=0
33293473: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
33297844: EV_TXCOMPLETE (includes waiting for RX windows)
33297892: engineUpdate, opmode=0x900
34547892: engineUpdate, opmode=0x908
34548351: TXMODE, freq=912500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
34615121: RXMODE_SINGLE, freq=925100000, SF=8, BW=500, CR=4/5, IH=0
34677940: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
34682249: EV_TXCOMPLETE (includes waiting for RX windows)
34682296: engineUpdate, opmode=0x900
35932296: engineUpdate, opmode=0x908
35932756: TXMODE, freq=912700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
35999526: RXMODE_SINGLE, freq=925700000, SF=8, BW=500, CR=4/5, IH=0
36062346: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
36066718: EV_TXCOMPLETE (includes waiting for RX windows)
36066766: engineUpdate, opmode=0x900
37316765: engineUpdate, opmode=0x908
37317225: TXMODE, freq=912900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
37383994: RXMODE_SINGLE, freq=926300000, SF=8, BW=500, CR=4/5, IH=0
37446813: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
37451185: EV_TXCOMPLETE (includes waiting for RX windows)
37451234: engineUpdate, opmode=0x900
38701234: engineUpdate, opmode=0x908
38701694: TXMODE, freq=913100000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
38768463: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
38831283: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
38835656: EV_TXCOMPLETE (includes waiting for RX windows)
38835703: engineUpdate, opmode=0x900
40085703: engineUpdate, opmode=0x908
40086162: TXMODE, freq=913300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
40152932: RXMODE_SINGLE, freq=927500000, SF=8, BW=500, CR=4/5, IH=0
40215752: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
40220199: EV_TXCOMPLETE (includes waiting for RX windows)
40220247: engineUpdate, opmode=0x900
41470248: engineUpdate, opmode=0x908
41470708: TXMODE, freq=913500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
41537476: RXMODE_SINGLE, freq=923300000, SF=8, BW=500, CR=4/5, IH=0
41600297: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
41604669: EV_TXCOMPLETE (includes waiting for RX windows)
41604717: engineUpdate, opmode=0x900
42854716: engineUpdate, opmode=0x908
42855176: TXMODE, freq=913700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
42921946: RXMODE_SINGLE, freq=923900000, SF=8, BW=500, CR=4/5, IH=0
42984831: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
42989139: EV_TXCOMPLETE (includes waiting for RX windows)
42989187: engineUpdate, opmode=0x900
44239186: engineUpdate, opmode=0x908
44239646: TXMODE, freq=913900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
44306350: RXMODE_SINGLE, freq=924500000, SF=8, BW=500, CR=4/5, IH=0
44369170: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
44373542: EV_TXCOMPLETE (includes waiting for RX windows)
44373590: engineUpdate, opmode=0x900
45623591: engineUpdate, opmode=0x908
45624051: TXMODE, freq=914100000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
45690819: RXMODE_SINGLE, freq=925100000, SF=8, BW=500, CR=4/5, IH=0
45753639: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
45758010: EV_TXCOMPLETE (includes waiting for RX windows)
45758058: engineUpdate, opmode=0x900
47008058: engineUpdate, opmode=0x908
47008518: TXMODE, freq=914300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
47075286: RXMODE_SINGLE, freq=925700000, SF=8, BW=500, CR=4/5, IH=0
47138106: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
47142415: EV_TXCOMPLETE (includes waiting for RX windows)
47142462: engineUpdate, opmode=0x900
48392462: engineUpdate, opmode=0x908
48392922: TXMODE, freq=914500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
48459691: RXMODE_SINGLE, freq=926300000, SF=8, BW=500, CR=4/5, IH=0
48522510: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
48526882: EV_TXCOMPLETE (includes waiting for RX windows)
48526930: engineUpdate, opmode=0x900
49776931: engineUpdate, opmode=0x908
49777391: TXMODE, freq=914700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
49844160: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
49906980: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
49911353: EV_TXCOMPLETE (includes waiting for RX windows)
49911401: engineUpdate, opmode=0x900
51161402: engineUpdate, opmode=0x908
51161862: TXMODE, freq=914900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
51228632: RXMODE_SINGLE, freq=927500000, SF=8, BW=500, CR=4/5, IH=0
51291452: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
51295834: EV_TXCOMPLETE (includes waiting for RX windows)
51295882: engineUpdate, opmode=0x900
52545883: engineUpdate, opmode=0x908
52546343: TXMODE, freq=902300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
52613047: RXMODE_SINGLE, freq=923300000, SF=8, BW=500, CR=4/5, IH=0
52675867: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
52680239: EV_TXCOMPLETE (includes waiting for RX windows)
52680287: engineUpdate, opmode=0x900
53930286: engineUpdate, opmode=0x908
53930746: TXMODE, freq=902500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
53997514: RXMODE_SINGLE, freq=923900000, SF=8, BW=500, CR=4/5, IH=0
54060335: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
54064707: EV_TXCOMPLETE (includes waiting for RX windows)
54064755: engineUpdate, opmode=0x900
55314756: engineUpdate, opmode=0x908
55315216: TXMODE, freq=902700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
55381985: RXMODE_SINGLE, freq=924500000, SF=8, BW=500, CR=4/5, IH=0
55444806: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
55449178: EV_TXCOMPLETE (includes waiting for RX windows)
55449226: engineUpdate, opmode=0x900
56699225: engineUpdate, opmode=0x908
56699685: TXMODE, freq=902900000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
56766390: RXMODE_SINGLE, freq=925100000, SF=8, BW=500, CR=4/5, IH=0
56829209: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
56833580: EV_TXCOMPLETE (includes waiting for RX windows)
56833628: engineUpdate, opmode=0x900
58083628: engineUpdate, opmode=0x908
58084088: TXMODE, freq=903100000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
58150857: RXMODE_SINGLE, freq=925700000, SF=8, BW=500, CR=4/5, IH=0
58213676: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
58218048: EV_TXCOMPLETE (includes waiting for RX windows)
58218096: engineUpdate, opmode=0x900
59468095: engineUpdate, opmode=0x908
59468555: TXMODE, freq=903300000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
59535323: RXMODE_SINGLE, freq=926300000, SF=8, BW=500, CR=4/5, IH=0
59598143: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
59602515: EV_TXCOMPLETE (includes waiting for RX windows)
59602563: engineUpdate, opmode=0x900
60852564: engineUpdate, opmode=0x908
60853024: TXMODE, freq=903500000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
60919729: RXMODE_SINGLE, freq=926900000, SF=8, BW=500, CR=4/5, IH=0
60982549: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0
60986921: EV_TXCOMPLETE (includes waiting for RX windows)
60986969: engineUpdate, opmode=0x900
62236970: engineUpdate, opmode=0x908
62237430: TXMODE, freq=903700000, len=26, SF=8, BW=125, CR=4/5, IH=0
Packet queued
62304198: RXMODE_SINGLE, freq=927500000, SF=8, BW=500, CR=4/5, IH=0
62367018: RXMODE_SINGLE, freq=923300000, SF=12, BW=500, CR=4/5, IH=0

Summary:
With all my Arduino-LMIC nodes, sometimes the JOIN is fast and most of the time it is very slow. Since I had no slow JOINs with these tests, maybe the relaxed timing is working now.

The same goes for the . Most of the time the Application Data it is delayed 30 minutes or more, but sometimes the data starts populating right away,
as with the Dragino node above.

See if you can make any sense out of this. I can send more data if you need it.

jmiller · July 3, 2018, 5:17am

I am experiencing much of the same issues as @tweil is seeing on my RFM95 based node, an Adafruit Feather M0 with an RFM95W in my case. My other node is a Multitech MDot. I tried both nodes on two separate gateways. Both use OTAA. I have no issues with the MDot, it just works. I am simply using Multitech’s build-in AT command processor over a serial terminal. MT has embedded the LoRa stack and AT command processor into the module’s STM32. The RFM95 is using LMIC on Arduino IDE. The M0/Arduino/RFM95 node takes a few tries before it joins successfully, and then the data, sent at 30s intervals during testing, takes 5-15 minutes before I see data packets in the gateway traffic console and in the TTN data console. I was beginning to think that I must have a bad RFM95 module until I came across this thread. Perhaps we both have bad modules but I am now beginning to wonder if temperature stability is an issue. I did just notice that the RFM’s op temp range -20/70C while the Mdot is -40/85C.

bluejedi · July 3, 2018, 10:38am

It is more useful to do some retries and show logging where the issues DO happen.

Looking at your first logs I observe the following:

Things Uno does a JOIN REQUEST on SF10BW125. JOIN ACCEPT received on SF10BW500.
It does the join request on SF10BW125 and not one of the lower spreading factors.
Is this US / 915MHz specs or a ‘feature’ of the Things Uno / RN2903 (sketch)?
After Things Uno receives the JOIN ACCEPT the first message is transmitted on SB7BW125. How does it know to transmit on SB7, is this ADR already ‘kicking in’ embedded in the join accept? is this US / 915MHz specs? or is this a feature of the Things Uno / RN2903 (sketch)?
The Arduino Uno starts its JOIN REQUEST on SF9BW125, not SF10BW125 like Things Uno and JOIN accept is received on SF9BW500.
Why does it start the request on SF9BW125 while Things Uno starts on SF10BW125?
Arduino Uno starts it first message on SF9BW125, which is different from Things Uno.
After first (uplink) message a downlink message is received on SF9BW500. The next message is sent at SF7BW125, so apparently this is ADR kicking in. A separate downlink message appears to be used for this, that downlink message is not visible in the log for Things Uno.
After the second uplink message another downlink message is received (at SB7BW125). What is it for? Maybe another ADR related message to adjust the power?

While the Arduino Uno + RFM95 + LMIC-Arduino combination appears to be working fine here, there are some notable differences with how the Things Uno behaves.

(FYI, as noted before I have little knowledge about US / 915MHz specs/specifics.)

bluejedi · July 3, 2018, 11:29am

Observations:

With the Moteino JOIN REQUEST starts on SF8BW125. This is different from both Things Uno and Arduino Uno.
I see 3 downlink messages. For Arduino Uno there were only two, For Things Uno there were none.
Frame counter starts at 109 instead of 0.
The time lapse between JOIN ACCEPT and the first message visible (frame 109) is around 30 minutes.
With around 1 uplink message every 20 seconds that whould be about 30 x 3 = 90 messages which comes close to the frame count 109.
Message with framecounter 109 appears to be the first message that is successfully received on the backend, because you see ‘almost directly’ appear three downlink messages after that which are probably ADR related. With Arduino Uno these downlink messages came ‘quickly after’ the join accept so it is plausible that the backend sees uplink message with framecounter 109 as the first successful uplink message (which is an assumption).
Once ‘the flow has started’ everything appears to continue normally.

Questions:

Assuming message with frame 109 was the first successfully received message by the backend, then what could be causing this?:
– An error on the node (in LMIC-Arduino)?
Would it be possible that the node periodically increments the framecounter every 20 seconds without actually sending out any message for half an our?
An error on the node appears the most plausible.
– An error on the gateway side? Less likely (but not impossible).
– An error on the backend side? Less likely (but not impossible).
Is this issue US / 915MHz related?
Would this be easy to pinpoint in LMIC-Arduino?

Todo:

What do you see happening in Console Gateway Overview in the received messages counter, does it increment between the Moteino’s JOIN REQUEST and sending the ‘first’ uplink message (framecounter 109)?
Similar for Console Device Overview.
What do Status , Frames up and Frames down show between JOIN REQUEST and transmitting the ‘first’ uplink message (framecounter 109)?

bluejedi · July 3, 2018, 11:50am

In the Arduino Uno? and Moteino node logs the join requests appear to be starting at SB7BW125 and then the spreading factor is gradually increased. This is not visible on the console logs but is probably because you have not included the failed join requests in the console log screendumps()?

This at least explains the behavior of and the difference between Arduino Uno succeeding the join at SF10BW125 and the Moteino succeeding the join at SF9BW125 (they both started joining at SF7BW125 but it is just not visible on the Console screen dumps).
This (failing to join at SF7BW125) behavior with Arduino’s and LMIC is normally fixed with relaxing LMIC timing.

It does not explain why Things Uno initally joins at SF10BW125 (which the directly switches to SF7BW125 when transmitting its first message).

bluejedi · July 3, 2018, 12:03pm

The Arduino M0 uses a SAMD ARM based microcontroller which is very different from the ATmega328(u4) AVR microcontrollers. It uses a diffenrent tool chain and different Arduino core.

You could experience similar experiences but the underlying technology is different.
Another MCU that can give problems in combination with LMIC-Arduino are (certain) STM32 ARM based microcontrollers. These also use a different toolchain and different Arduino core than the Atmel AVR controllers.
In case of the STM32 the issues manifest that LMIC completely hangs, which is different from your issues with Arduino M0.