search

LacunaSpace / basicmac

BasicMAC LoRaWAN stack that supports (but is not limited to) Arduino
Other
75 stars 18 forks source link

not receiving rx #32

Open wemaxon opened 2 years ago

wemaxon commented 2 years ago

Hello,

I am using the BasicMAC library with Arduino IDE on an Sparkfun LoRa Thing Plus. The Board features an NM180100 Module with an apollo3 microcontroller and sx1262 transceiver. I have set up my own chirpstack lora serverstack with a mikrotik gateway.

I am opening this issue because I am having problems with the Rx part. The module wont receive any frames sent from the gateway. The OTAA activation also takes lots of attempts until established. The Tx messages on the other hand do work, once the join is successfull.

The following is the serial debugging output when the device is trying to join and and then transmit:

[MAIN]Application started<\r><\n>
[lora]Initializing LMIC<\r><\n>
[lora]Joining<\r><\n>
[lora]EV_JOINING<\r><\n>
00:00:00.055: engineUpdate[opmode=0x4]<\r><\n>
00:00:06.000: engineUpdate[opmode=0x4]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:00:06.006: engineUpdate[opmode=0x884]<\r><\n>
00:00:06.010: TX[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.1,pow=16,len=23]: 000000000000000000AEB4F4B34759576F0FBDD1E1E628<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:00:06.093: engineUpdate[opmode=0x884]<\r><\n>
00:00:11.086: RX_MODE[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.1,rxtime=693245]<\r><\n>
00:00:11.100: WARNING: rxtime is 530 ticks in the past! (ramp-up time 5 ms / 365 ticks)<\r><\n>
00:00:11.114: RX: TIMEOUT<\r><\n>
00:00:12.102: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=756737]<\r><\n>
00:00:12.116: WARNING: rxtime is 537 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:00:12.321: RX: TIMEOUT<\r><\n>
00:00:12.442: engineUpdate[opmode=0x4]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:00:12.448: engineUpdate[opmode=0x884]<\r><\n>
00:00:12.452: TX[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.3,pow=16,len=23]: 000000000000000000AEB4F4B34759576FCD3CF5516130<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:00:12.535: engineUpdate[opmode=0x884]<\r><\n>
00:00:17.528: RX_MODE[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.3,rxtime=1095869]<\r><\n>
00:00:17.542: WARNING: rxtime is 535 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:00:17.556: RX: TIMEOUT<\r><\n>
00:00:18.544: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=1159361]<\r><\n>
00:00:18.558: WARNING: rxtime is 541 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:00:18.763: RX: TIMEOUT<\r><\n>
00:00:29.618: engineUpdate[opmode=0x4]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:00:29.623: engineUpdate[opmode=0x884]<\r><\n>
00:00:29.627: TX[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.5,pow=16,len=23]: 000000000000000000AEB4F4B34759576F9789CFD63655<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:00:29.762: engineUpdate[opmode=0x884]<\r><\n>
00:00:34.755: RX_MODE[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.5,rxtime=2172563]<\r><\n>
00:00:34.769: WARNING: rxtime is 538 ticks in the past! (ramp-up time 5 ms / 367 ticks)<\r><\n>
00:00:34.790: RX: TIMEOUT<\r><\n>
00:00:35.771: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=2236023]<\r><\n>
00:00:35.785: WARNING: rxtime is 539 ticks in the past! (ramp-up time 5 ms / 363 ticks)<\r><\n>
00:00:35.989: RX: TIMEOUT<\r><\n>
00:00:47.004: engineUpdate[opmode=0x4]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:00:47.010: engineUpdate[opmode=0x884]<\r><\n>
00:00:47.013: TX[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.1,pow=16,len=23]: 000000000000000000AEB4F4B34759576FB6694AF9FDBF<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:00:47.149: engineUpdate[opmode=0x884]<\r><\n>
00:00:52.142: RX_MODE[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.1,rxtime=3259225]<\r><\n>
00:00:52.156: WARNING: rxtime is 536 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:00:52.176: RX: TIMEOUT<\r><\n>
00:00:53.157: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=3322685]<\r><\n>
00:00:53.171: WARNING: rxtime is 542 ticks in the past! (ramp-up time 5 ms / 365 ticks)<\r><\n>
00:00:53.376: RX: TIMEOUT<\r><\n>
00:01:18.377: engineUpdate[opmode=0x4]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:01:18.382: engineUpdate[opmode=0x884]<\r><\n>
00:01:18.386: TX[mod=LoRa,sf=9,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.3,pow=16,len=23]: 000000000000000000AEB4F4B34759576F02BFC6F3751F<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:01:18.614: engineUpdate[opmode=0x884]<\r><\n>
00:01:23.608: RX_MODE[mod=LoRa,sf=9,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.3,rxtime=5225870]<\r><\n>
00:01:23.622: WARNING: rxtime is 536 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:01:23.655: RX: TIMEOUT<\r><\n>
00:01:24.623: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=5289266]<\r><\n>
00:01:24.636: WARNING: rxtime is 542 ticks in the past! (ramp-up time 5 ms / 365 ticks)<\r><\n>
00:01:24.841: RX: TIMEOUT<\r><\n>
00:01:37.841: engineUpdate[opmode=0x4]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:01:37.847: engineUpdate[opmode=0x884]<\r><\n>
00:01:37.850: TX[mod=LoRa,sf=9,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.5,pow=16,len=23]: 000000000000000000AEB4F4B34759576F17528A5A0E62<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:01:38.078: engineUpdate[opmode=0x884]<\r><\n>
00:01:43.072: RX_MODE[mod=LoRa,sf=9,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.5,rxtime=6442376]<\r><\n>
00:01:43.086: WARNING: rxtime is 536 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:01:43.119: RX: TIMEOUT<\r><\n>
00:01:44.087: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=6505772]<\r><\n>
00:01:44.100: WARNING: rxtime is 539 ticks in the past! (ramp-up time 5 ms / 363 ticks)<\r><\n>
00:01:44.305: RX: TIMEOUT<\r><\n>
00:02:05.235: engineUpdate[opmode=0x4]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:02:05.241: engineUpdate[opmode=0x884]<\r><\n>
00:02:05.244: TX[mod=LoRa,sf=10,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.1,pow=16,len=23]: 000000000000000000AEB4F4B34759576F17AE3CF4ECEC<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:02:05.637: engineUpdate[opmode=0x884]<\r><\n>
00:02:10.633: RX_MODE[mod=LoRa,sf=10,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.1,rxtime=8164939]<\r><\n>
00:02:10.647: WARNING: rxtime is 541 ticks in the past! (ramp-up time 5 ms / 365 ticks)<\r><\n>
00:02:11.090: RX[rssi=-57,snr=8.50,len=33]: 20A9BDE16DE535D6A80423F0CBF47797169064D412DFEE2FFA3D626728914706E7<\r><\n>
00:02:11.102: Setup channel[idx=3,freq=867.1]<\r><\n>
00:02:11.106: Setup channel[idx=4,freq=867.3]<\r><\n>
00:02:11.110: Setup channel[idx=5,freq=867.5]<\r><\n>
00:02:11.114: Setup channel[idx=6,freq=867.7]<\r><\n>
00:02:11.118: Setup channel[idx=7,freq=867.9]<\r><\n>
[lora]EV_JOINED<\r><\n>
00:02:11.124: engineUpdate[opmode=0x800]<\r><\n>
[MAIN] Entering Loop <\n>
[MAIN] Send event<\r><\n>
[mavlink] Message packed. Length: 39 Content:0xFD,0x1B,0x0,0x0,0x0,0x1,0x1,0x21,0x0,0x0,0x3B,0x0,0x2,0x0,0x1,0x0,0x0,0x0,0x2,0x0,0x0,0x0,0x3,0x0,0x0,0x0,0x4,0x0,0x0,0x0,0x5,0x0,0x6,0x0,0x7,0x0,0x8,0xFD,0x49,<\n>
00:02:11.149: engineUpdate[opmode=0x808]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:02:11.156: engineUpdate[opmode=0x888]<\r><\n>
00:02:11.160: TX[mod=LoRa,sf=10,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=867.5,pow=16,len=52]: 4012E8D1008000000172AF5F98FF2A25CE53AC24E5E3D8A6B143862F44AAB52FF040185A691FE6..<\r><\n>
[lora]Packet queued<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:02:11.802: engineUpdate[opmode=0x888]<\r><\n>
00:02:12.798: RX_MODE[mod=LoRa,sf=10,bw=125,cr=4/5,nocrc=1,ih=0,freq=867.5,rxtime=8300246]<\r><\n>
00:02:12.812: WARNING: rxtime is 542 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:02:13.133: RX[rssi=-57,snr=9.00,len=17]: 6012E8D1008500000350FF0001747AF281<\r><\n>
[lora]EV_DATARATE<\r><\n>
00:02:13.143: engineUpdate[opmode=0x888]<\r><\n>
00:02:13.147: Received downlink[window=RX1,port=-1,ack=0]<\r><\n>
[lora]EV_TXCOMPLETE (includes waiting for RX windows)<\r><\n>
00:02:13.157: engineUpdate[opmode=0x800]<\r><\n>
[MAIN] Send event<\r><\n>
[mavlink] Message packed. Length: 39 Content:0xFD,0x1B,0x0,0x0,0x1,0x1,0x1,0x21,0x0,0x0,0x5D,0x4E,0x2,0x0,0x1,0x0,0x0,0x0,0x2,0x0,0x0,0x0,0x3,0x0,0x0,0x0,0x4,0x0,0x0,0x0,0x5,0x0,0x6,0x0,0x7,0x0,0x8,0xA,0xE6,<\n>
00:02:31.151: engineUpdate[opmode=0x808]<\r><\n>
[lora]Packet queued<\r><\n>
00:02:42.997: engineUpdate[opmode=0x808]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:02:43.005: engineUpdate[opmode=0x888]<\r><\n>
00:02:43.009: TX[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=1,freq=868.5,pow=16,len=54]: 4012E8D100820100030701C05C7FC95F9E67AEEDDE9202238F858D42A3AA15BE5F6DCD95264FC4..<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:02:43.137: engineUpdate[opmode=0x888]<\r><\n>
00:02:44.130: RX_MODE[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.5,rxtime=10258478]<\r><\n>
00:02:44.144: WARNING: rxtime is 542 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:02:44.158: RX: TIMEOUT<\r><\n>
00:02:45.146: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=10321970]<\r><\n>
00:02:45.160: WARNING: rxtime is 548 ticks in the past! (ramp-up time 5 ms / 365 ticks)<\r><\n>
00:02:45.365: RX: TIMEOUT<\r><\n>
[lora]EV_TXCOMPLETE (includes waiting for RX windows)<\r><\n>
00:02:46.862: engineUpdate[opmode=0x800]<\r><\n>
[MAIN] Send event<\r><\n>
[mavlink] Message packed. Length: 39 Content:0xFD,0x1B,0x0,0x0,0x2,0x1,0x1,0x21,0x0,0x0,0x7F,0x9C,0x2,0x0,0x1,0x0,0x0,0x0,0x2,0x0,0x0,0x0,0x3,0x0,0x0,0x0,0x4,0x0,0x0,0x0,0x5,0x0,0x6,0x0,0x7,0x0,0x8,0xB0,0x77,<\n>
00:02:51.153: engineUpdate[opmode=0x808]<\r><\n>
[lora]Packet queued<\r><\n>
00:02:53.997: engineUpdate[opmode=0x808]<\r><\n>
[lora]EV_TXSTART<\r><\n>
00:02:54.004: engineUpdate[opmode=0x888]<\r><\n>
00:02:54.008: TX[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=2,freq=868.3,pow=16,len=52]: 4012E8D100800200012E286DF9B718EA29FBC2D8146AF8D07BAB9264C6CB09BAFCA71B7C26CAC5..<\r><\n>
[lora]EV_TXDONE<\r><\n>
00:02:54.137: engineUpdate[opmode=0x888]<\r><\n>
00:02:55.130: RX_MODE[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.3,rxtime=10945943]<\r><\n>
00:02:55.143: WARNING: rxtime is 543 ticks in the past! (ramp-up time 5 ms / 365 ticks)<\r><\n>
00:02:55.158: RX: TIMEOUT<\r><\n>
00:02:56.145: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=11009435]<\r><\n>
00:02:56.159: WARNING: rxtime is 548 ticks in the past! (ramp-up time 5 ms / 364 ticks)<\r><\n>
00:02:56.364: RX: TIMEOUT<\r><\n>
[lora]EV_TXCOMPLETE (includes waiting for RX windows)<\r><\n>
00:02:58.060: engineUpdate[opmode=0x800]<\r><\n>

This is the gateway traffic log of the exact same event: gateway_join_log

You can clearly see multiple join requests and accepts by the server stack until the join procedure is successful. Even then the device is not receiving any Rx Frames (Unconfirmed Data Down) sent by the server-stack.

The Error WARNING: rxtime is 543 ticks in the past! (ramp-up time 5 ms / 365 ticks) also happens in the Sparkfun example, it can be seen in the Sparkfun Hookup Guide mentioned below. This fix (changing RX_RAMPUP in oslmic.h) proposed in the sparkfun forum gets rid of the warning but doesnt fix the other problems.

I got the pinout from this Sparkfun Hookup Guide and included the most recent library version from this repository, which was generated as an arduino library with the export script. To get the library to compile I had to modify hal.cpp and comment out the calls to the arduino functions noInterrupts() and interrupts() in the functions hal_disableIRQs and hal_enableIRQs, as they arent implemented in the Sparkfun apollo3 arduino core. I copied this change from the basicMAC library modified by Sparkfun which is provided by the Sparkfun Hookup Guide. The changes in hal.cpp can be seen below:

...
void hal_disableIRQs () {
    //noInterrupts();                  --> COMMENTED IN THE SPARKFUN MODIFIED BASICMAC LIBRARY
    irqlevel++;
}

void hal_enableIRQs () {
    if(--irqlevel == 0) {
        //interrupts();                  --> COMMENTED IN THE SPARKFUN MODIFIED BASICMAC LIBRARY

        // Instead of using proper interrupts (which are a bit tricky
        // and/or not available on all pins on AVR), just poll the pin
        // values. Since os_runloop disables and re-enables interrupts,
        // putting this here makes sure we check at least once every
        // loop.
        //
        // As an additional bonus, this prevents the can of worms that
        // we would otherwise get for running SPI transfers inside ISRs
        hal_io_check();
    }
}
...

Could this be about timing or because of the missing interrupt functionality on my board?

This is my code: SFE_LoRa_Module_Firmware.zip

I'd be grateful for any help. thanks in advance!

tfeseker commented 1 year ago

Hi,

I am trying to solve the same problem... Has anyone ever managed to get the Sparkfun LoRa Thing Plus working in OTAA mode?

I would appreciate if someone could point out a solution. Thanks!

wemaxon commented 1 year ago

Hi @tfeseker,

i remember getting it to work. I think the Arduino IDE Code Examples provided by Sparkfun didnt have the correct setup for the GPIO Connection to the Antenna RF Switch. Also I think I had to adjust a timing variable inside the library.

I have attached my final working firmware including that includes the changes necessary to libs to get it to work. lora-modul-firmware.zip

If you have any questions let me know. Ill try to remember.