search

mcci-catena / arduino-lmic

LoraWAN-MAC-in-C library, adapted to run under the Arduino environment
https://forum.mcci.io/c/device-software/arduino-lmic/
MIT License
628 stars 207 forks source link

EV_JOINING not success #311

Open svelmurugan92 opened 5 years ago

svelmurugan92 commented 5 years ago

With the current master changes, tried to build the example sketch in catena 4450 and catena 4612. While doing the step clear the FRAM and redo the provisioning. Then join not happening, EV_JOINING not success. 

-------------------------------------------------------------------------------
This is the catena4612_simple program V0.1.1.
Target network: The Things Network / in866
Enter 'help' for a list of commands.
(remember to select 'Line Ending: Newline' at the bottom of the monitor window.)
SYSCLK: 32 MHz
USB enabled
message cycle time 30 seconds for 10 messages
CPU Unique ID: 08-20-47-04-32-37-47-04-33-34-37-39-47-00-43-00
--------------------------------------------------------------------------------

LoRaWAN init: ?CatenaBase::GetAbpProvisioningInfo: failing
succeeded
EUI64: 00-02-cc-01-00-00-01-97
Platform Flags:  0x00007019
Operating Flags:  0x00000001
FLASH found, put power down
vBat:    2114 mV
vBus:    4259 mV
BME280:  T: 29 P: 100435 RH: 43
Si1133:  67 IR, 33 White, 0 UV
EV_JOINING
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART
EV_JOIN_TXCOMPLETE
EV_TXSTART

Tried the compliance test code in 4450. Still same problem, joining not happened.

Starting
Packet queued
313387: EV_JOINING
645082: EV_TXSTART: ch 0 rps=0x1 (SF7 BW125 CR 4/5 Crc IH=0), datarate 5, opmode 88C
953455: EV_RXSTART: freq=865.0 rps=0x81 (SF7 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 648984, delta ms 4871
1005940: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 648984, delta ms 5711
1045937: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
1293838: EV_TXSTART: ch 1 rps=0x1 (SF7 BW125 CR 4/5 Crc IH=0), datarate 5, opmode 88C
1602212: EV_RXSTART: freq=865.4 rps=0x81 (SF7 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 1297740, delta ms 4871
1654696: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 1297740, delta ms 5711
1694696: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
2311232: EV_TXSTART: ch 2 rps=0x1 (SF7 BW125 CR 4/5 Crc IH=0), datarate 5, opmode 88C
2619605: EV_RXSTART: freq=865.9 rps=0x81 (SF7 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 2315134, delta ms 4871
2672089: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 2315134, delta ms 5711
2712087: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
2925129: EV_TXSTART: ch 0 rps=0x2 (SF8 BW125 CR 4/5 Crc IH=0), datarate 4, opmode 88C
3229196: EV_RXSTART: freq=865.0 rps=0x82 (SF8 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 88C, txend 2932245, delta ms 4751
3289200: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 88C, txend 2932245, delta ms 5711
3329197: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
4436769: EV_TXSTART: ch 1 rps=0x2 (SF8 BW125 CR 4/5 Crc IH=0), datarate 4, opmode 88C
4740836: EV_RXSTART: freq=865.4 rps=0x82 (SF8 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 88C, txend 4443884, delta ms 4751
4800839: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 88C, txend 4443884, delta ms 5711
4840837: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
5202884: EV_TXSTART: ch 2 rps=0x2 (SF8 BW125 CR 4/5 Crc IH=0), datarate 4, opmode 88C
5506951: EV_RXSTART: freq=865.9 rps=0x82 (SF8 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 88C, txend 5209999, delta ms 4751
5566955: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 88C, txend 5209999, delta ms 5711
5606953: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
6501534: EV_TXSTART: ch 0 rps=0x3 (SF9 BW125 CR 4/5 Crc IH=0), datarate 3, opmode 88C
6811578: EV_RXSTART: freq=865.0 rps=0x83 (SF9 BW125 CR 4/5 NoCrc IH=0), datarate 3, opmode 88C, txend 6514435, delta ms 4754
6871390: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 3, opmode 88C, txend 6514435, delta ms 5711
6911387: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
7375946: EV_TXSTART: ch 1 rps=0x3 (SF9 BW125 CR 4/5 Crc IH=0), datarate 3, opmode 88C
7685992: EV_RXSTART: freq=865.4 rps=0x83 (SF9 BW125 CR 4/5 NoCrc IH=0), datarate 3, opmode 88C, txend 7388848, delta ms 4754
7745803: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 3, opmode 88C, txend 7388848, delta ms 5711
7785861: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
9686407: EV_TXSTART: ch 2 rps=0x3 (SF9 BW125 CR 4/5 Crc IH=0), datarate 3, opmode 88C
9996452: EV_RXSTART: freq=865.9 rps=0x83 (SF9 BW125 CR 4/5 NoCrc IH=0), datarate 3, opmode 88C, txend 9699308, delta ms 4754
10056263: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 3, opmode 88C, txend 9699308, delta ms 5711
10096258: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
10631994: EV_TXSTART: ch 0 rps=0x4 (SF10 BW125 CR 4/5 Crc IH=0), datarate 2, opmode 88C
10952719: EV_RXSTART: freq=865.0 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 2, opmode 88C, txend 10655192, delta ms 4760
11012147: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 2, opmode 88C, txend 10655192, delta ms 5711
11052141: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
15120099: EV_TXSTART: ch 1 rps=0x4 (SF10 BW125 CR 4/5 Crc IH=0), datarate 2, opmode 88C
15440825: EV_RXSTART: freq=865.4 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 2, opmode 88C, txend 15143298, delta ms 4760
15500254: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 2, opmode 88C, txend 15143298, delta ms 5711
15540251: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
15855397: EV_TXSTART: ch 2 rps=0x4 (SF10 BW125 CR 4/5 Crc IH=0), datarate 2, opmode 88C
16176123: EV_RXSTART: freq=865.9 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 2, opmode 88C, txend 15878595, delta ms 4760
16235551: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 2, opmode 88C, txend 15878595, delta ms 5711
16275612: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80

Please share your views

terrillmoore commented 5 years ago

Vel, having been out for more than a week, I'm way behind and won't be able to look at this soon.

Can you please use the compliance app and git bisect on the LMIC, to find the change that broke this?

Thanks, --Terry

terrillmoore commented 5 years ago

For what it's worth, I noticed that JOIN had become more fragile and required that I widen the clock tolerances in order to make it robust. I thought it was beause of the new event reporting (particularly receive). However, I also notice that your log stops at datarate 2, can you please check that the first tx goes all the way to datarate 0 before going back to datarate 5. Also tell me what is happening at the gateway (which downlink window is being used, and what timing/channel/datarate).

svelmurugan92 commented 5 years ago

Hello Terry,

I tried the same today, Now join working. Looks like its not a lmic code problem. Maybe a network issue. BTW, Checked the datarate, first Tx itself starting at datarate 5. Attached the success log below

Starting
Packet queued
313395: EV_JOINING
752319: EV_TXSTART: ch 1 rps=0x1 (SF7 BW125 CR 4/5 Crc IH=0), datarate 5, opmode 88C
1060694: EV_RXSTART: freq=865.4 rps=0x81 (SF7 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 756222, delta ms 4871
1113177: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 756222, delta ms 5711
1153244: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
1477698: EV_TXSTART: ch 2 rps=0x1 (SF7 BW125 CR 4/5 Crc IH=0), datarate 5, opmode 88C
1786073: EV_RXSTART: freq=865.9 rps=0x81 (SF7 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 1481601, delta ms 4871
1838556: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 1481601, delta ms 5711
1878622: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
2091308: EV_TXSTART: ch 0 rps=0x1 (SF7 BW125 CR 4/5 Crc IH=0), datarate 5, opmode 88C
2399682: EV_RXSTART: freq=865.0 rps=0x81 (SF7 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 2095211, delta ms 4871
2452166: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 5, opmode 88C, txend 2095211, delta ms 5711
2492234: EV_JOIN_TXCOMPLETE: saveIrqFlags 0x80
3498319: EV_TXSTART: ch 1 rps=0x2 (SF8 BW125 CR 4/5 Crc IH=0), datarate 4, opmode 88C
3802386: EV_RXSTART: freq=865.4 rps=0x82 (SF8 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 88C, txend 3505435, delta ms 4751
3823717: EV_JOINED: ch 1
netid: 19
devaddr: 2601255D
artKey: C9-DA-D6-B6-4A-0-77-9D-B6-9D-C0-F2-48-62-CB-E4
nwkKey: 53-E0-83-E6-83-A0-15-55-F7-EE-88-3A-B0-9D-67-2F
3823851: EV_TXSTART: ch 0 rps=0x2 (SF8 BW125 CR 4/5 Crc IH=0), datarate 4, opmode 888
3890463: EV_RXSTART: freq=865.0 rps=0x82 (SF8 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 888, txend 3830967, delta ms 951
3950467: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 888, txend 3830967, delta ms 1912
4234028: EV_TXCOMPLETE: ch 0 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0) txrxflags 0x20
Packet queued
4546662: EV_TXSTART: ch 1 rps=0x2 (SF8 BW125 CR 4/5 Crc IH=0), datarate 4, opmode 888
4613276: EV_RXSTART: freq=865.4 rps=0x82 (SF8 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 888, txend 4553780, delta ms 951
4673280: EV_RXSTART: freq=866.5 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0), datarate 4, opmode 888, txend 4553780, delta ms 1912
4982624: EV_TXCOMPLETE: ch 1 rps=0x84 (SF10 BW125 CR 4/5 NoCrc IH=0) txrxflags 0x20

I will experiment more. We can close this ticket.

terrillmoore commented 5 years ago

That's reassuring. Thanks.

cyberman54 commented 4 years ago

@svelmurugan92 @terrillmoore I'm fighting the same symptom for a long time, including current LMIC (https://github.com/mcci-catena/arduino-lmic/commit/852f3489b6c9d016a1c9821833a595a9ca2aef71), testing on EU868 with TTNv2.

See my issue https://github.com/mcci-catena/arduino-lmic/issues/455

Some days no joins at all, last days smooth join, and these days "EV_JOIN_TXCOMPLETE" again.

No clue where to look at.

svelmurugan92 commented 4 years ago

@cyberman54 Which board are you using? I normally use India band which is very similar to EU. I will try to setup the device in EU band and check.

terrillmoore commented 4 years ago

Seems like we should reopen this for now

cyberman54 commented 4 years ago

@svelmurugan92 i'm using ESP32, running my app on arduino-esp32 stack.

@terrillmoore meanwhile i managed to write logs

while the device repeatedly reports the "EV_JOIN_TXCOMPLETE" event.

I turned out, that in this situation there was no JOIN ACCEPT packet sent by both gateways, according to the gateway logs. While this is happening, TTN gateway console shows the yellow join request packet, but no green join accept packet.

So this seems a TTN network related issue. For some reason, sometimes (when?) or on certain conditions (which?) join accept packets seem not to be answered by the network. Thus, the behaviour of LMIC is correct.

DaveDavenport commented 4 years ago

I am hit by this same issue, it often takes days to successfully connect.

Weirdly enough I have some old code that does work using: https://github.com/matthijskooijman/arduino-lmic (on same hardware).

Any suggestions on what I can do to debug this issue?

I regrettably do not have my own gateway, so cannot grab logs from that.

terrillmoore commented 4 years ago

HI @DaveDavenport. Sorry, this one is my fault. During cert testing I ran into a problem with data reliability. I looked into the code and found that the LMIC was using radically different timing parameters than Semtech. This is issue #442.

When I applied this change, I didn't realize that in fact RX for SF12 was adversely affected. I am planning to set up a test jig this weekend, and hope to finally characterize this. (I have test equipment, but nothing that will give me a GPIO signal at the start and end of the downlink TX, so I can match to my downlink RX.)

Unfortunately, joins in EU use SF12.

You can revert to an older LMIC, or try backing out the changes around #442. The changeset is 42da75b560c. This will reduce your overall RX quality, but will make SF12 (specifically) work beter.

DaveDavenport commented 4 years ago

Thanks, will try.

cyberman54 commented 4 years ago

@DaveDavenport If you work out a patch, please let us know here. I am facing the same problem since weeks.

DaveDavenport commented 4 years ago

I reverted my checkout to the commit before: 42da75b. This worked-ish for me.

cyberman54 commented 4 years ago

I reverted my checkout to the commit before: 42da75b. This worked-ish for me

@DaveDavenport Do you have a fork online which is in current HEAD level of MCCI LMIC, but has the above changeset/commit reverted?

DaveDavenport commented 4 years ago

why would you make a fork? its a single command to get the right checkout?

DaveDavenport commented 4 years ago

Any update on this issue?

terrillmoore commented 4 years ago

@DaveDavenport I have committed a number of changes to head; they resolved the device-specific SF12 issues that I was seeing. I've had no feedback from testers (positive or negative). I ran the full EU868 pre-compliance test with the RWC5020, and everything worked well. But... others may have different experiences. I don't have resources to do commercial-scale testing. The problems were related to timing. I added features to https://github.com/mcci-catena/rwc_nst_test that allowed me to sweep the window, and I observed interesting reliability problems related to grounding; on a hunch, I moved the window opening earlier. It helped for me.

One thing that's clear: your platform must have access to a reasonably accurate time base. Some devices, like the Murata module, use an oscillator that's only 4000ppm accurate. The LoRaWAN spec practically requires 100ppm accuracy, and the Semtech and mbed sample code assume that accxuracy. The LMIC can accommodate 4000ppm for class A, but this appears to require using a different RX windowing scheme than Semtech uses.

See lengthy discussion starting at https://github.com/mcci-catena/arduino-lmic/issues/483#issuecomment-568632897.

DaveDavenport commented 4 years ago

thx.

DaveDavenport commented 4 years ago

I can confirm that that master allows me to connect and send a message..

terrillmoore commented 4 years ago

@DaveDavenport excellent, thanks so much for testing. What radio/CPU, network, and region are you using?

DaveDavenport commented 4 years ago

RFM95W module.. uses SX1276 I think connected to a blue pill (stm32f108).

On EU network. 868 MHz. data rate: SF10BW125 coding rate: 4/5

Using the things network

terrillmoore commented 4 years ago

Great, thanks very much. There's some test diversity, as I'm using (primarily) Murata modules. And I don't have a live EU network to test against, just the network simulator that's part of the RWC5020A.

DaveDavenport commented 4 years ago

I am completely new to this, I bought some units to play around.

terrillmoore commented 4 years ago

Welcome to the party, have fun!

DaveDavenport commented 4 years ago

It seems to be running pretty reliable. Better then I had this/other libs running before.

terrillmoore commented 4 years ago

Excellent, thanks for letting me know.

cyberman54 commented 4 years ago

To be more precise on my testing results:

After devices join, stable transmissions, no issues. Joins delays seem still to be random:

Chance that devices join immediately when trying a bunch of joins is around 30%.

ifrew commented 4 years ago

Hi Folks,

I just started moving up the stack from developing lora apps working at the physical layer over the last couple of years. Last couple of days I started using Lorawan and the MCCI LMIC library. As per the instructions which were really clear, I managed to get my TTGO TBeam board running the TTN-ABP example and sending data to The Things Network. So feeing happy I moved up to use the OTTA-TTN example as per the recommendations. I am using the latest libraries as of today and I am now getting the "EV_JOIN_TXCOMPLETE" event repeatedly. Has their been a regression n the OTTA code? I should also say I'm in the USA using the CFG_us915 configuration and the "bad" workaround of disabling all subbands and then enabling just one channel.. Working up the stack incrementally.

Any thoughts?

EV_JOIN_TXCOMPLETE.txt

DaveDavenport commented 4 years ago

Hi Folks,

I just started moving up the stack from developing lora apps working at the physical layer over the last couple of years. Last couple of days I started using Lorawan and the MCCI LMIC library. As per the instructions which were really clear, I managed to get my TTGO TBeam board running the TTN-ABP example and sending data to The Things Network. So feeing happy I moved up to use the OTTA-TTN example as per the recommendations. I am using the latest libraries as of today and I am now getting the "EV_JOIN_TXCOMPLETE" event repeatedly. Has their been a regression n the OTTA code? I should also say I'm in the USA using the CFG_us915 configuration and the "bad" workaround of disabling all subbands and then enabling just one channel.. Working up the stack incrementally.

Any thoughts?

EV_JOIN_TXCOMPLETE.txt

regrettable for me it has been pretty hit and miss. Once connected it works well, but it sometimes takes days to connect othertimes it is really quick. I kinda gave up for now and shelved my project.