OTAA failed / Debugging device activation OTAA issues

I have same issue BUT:
setting SF10 results in 100% joinAccept reception by end node
setting SF11 results in 50% joinAccept reception
setting SF12 results in 0% joinAccept reception and failure to join.

Tried using ABP with confirmed messages. Node sends packages with confirmation request. Again
SF10 - 100% confirmed
SF11 - 50% confirmed
SF12 - none is confirmed

Raising SF causes end node to fail receiving downlink packages. My end node is class A.

I suppose SF12 should be more stable…
What might be the reason?

Most likely SF12 is being rejected as the packets would be too illicitly long in time.

SF11 may be failing because they are so long in time that statistically some interference or time collisions may be happening before they are done.

Or there may be implementation bugs in your node that get triggered at higher spreading factors, for example wrong calculation of the transmit time leading to receiving at the wrong point in time.

Dear friends, I have a LoraWAN device. It’s a water-meter. It works on frequency 485.7MHz to 487.1MHz. When using OTAA, JoinAccept will use 506.1MHz or 506.5MHz. How can I change the frequency to 485.7Mhz - 487.1Mhz?

Hello everyone,
How do I change the LoRaWAN mac versions? I cannot seem to find the device- profile. Where do I start looking?

In the device-profile :wink:

image

Hello,

Sorry to revive this thread but after extensive reading I still cannot find a solution to the JoinRequest/JoinAccept loop.

I am currently testing on my local network the entire loraserver suite, with a few stumbles I managed to actually make the join request in a correct way for it to accept it, but now I am stuck on this loop.

I am currently using an Elsys ERSCO2 sensor, which is correctly configured so I’m positive my error was inside the loraserver configuration but I cannot pinpoint where.

I don’t think my sensor supports 1.1.x Lora MAC so I’ve tried all 1.0.x versions, although I read that it doesn’t matter much unless I swap to 1.1.x versions.

Can anyone help me regarding this matter, so far all things I’ve found in this thread have no helped, so i’m at a loss.

What should I do?

I should mention I don’t run the gateway bridge on my kerlink ifemtocell gateway, but on the same machine I run the server and app server on.

Thank you

I want to say that the same happens with two BOSCH parking sensors that only support OTAA, the TPS110EU

I can’t seem to figure out why and where it fails. I am SURE that it’s MSB and the keys are correct. I don’t know where to bang my head at this point!

This is the log from my gateway, I can’t seem to figure out what’s wrong.

This is the Join Request / Join Accept event on my parking sensor:

May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> FIFO content: 1 8b 2 5 17
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> [6 17]
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> LoRa packet
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7>   api.send:  0a 60 08 80 c9 80 96 01 12 27 0a 17 00 fc d6 bd 00 00 19 00 00 2b 2d 19 00 00 bd d6 fc cf 1f a4  |.`.......'...........+-.........|
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7>   api.send:  a1 f8 bd 10 e0 e9 84 9e 03 18 00 20 00 28 03 30 00 1a 2f 08 86 02 12 2a 08 fc cd 88 b2 04 12 0c  |........... .(.0../....*........|
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7>   api.send:  08 00 10 d0 85 ba e7 05 18 88 9e 14 1d 00 00 40 c2 22 0f 0d 00 00 44 41 15 00 00 6c 41 1d 00 00  |...............@."....DA...lA...|
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7>   api.send:  18 41                                                                                            |.A|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.recv:  0A 60 08 80 C9 80 96 01 12 27 0A 17 00 FC D6 BD 00 00 19 00 00 2B 2D 19 00 00 BD D6 FC CF 1F A4  |.`.......'...........+-.........|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.recv:  A1 F8 BD 10 E0 E9 84 9E 03 18 00 20 00 28 03 30 00 1A 2F 08 86 02 12 2A 08 FC CD 88 B2 04 12 0C  |........... .(.0../....*........|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.recv:  08 00 10 D0 85 BA E7 05 18 88 9E 14 1D 00 00 40 C2 22 0F 0D 00 00 44 41 15 00 00 6C 41 1D 00 00  |...............@."....DA...lA...|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.recv:  18 41                                                                                            |.A|
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> Received uplink message: 
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> | lora uplink (12C02480), payload 23 B, channel 868.3 MHz, crc ok, bw 125 kHz, sf 10, cr 4/5
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> | Join Request, JoinEUI 0000190000BDD6FC, DevEUI FCD6BD0000192D2B, DevNonce 8143
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> |  - radio (00000106)
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> |   - demodulator counter 1178740476, UTC time 2019-05-29T13:02:08.331528Z, rssi -48 dB, snr 9.5< 12.25 <14.75 dB
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  02 39 D5 00 72 76 FF 00 39 03 09 69 7B 22 72 78 70 6B 22 3A 5B 7B 22 61 65 73 6B 22 3A 30 2C 22  |.9..rv..9..i{"rxpk":[{"aesk":0,"|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  62 72 64 22 3A 32 36 32 2C 22 63 6F 64 72 22 3A 22 34 2F 35 22 2C 22 64 61 74 61 22 3A 22 41 50  |brd":262,"codr":"4/5","data":"AP|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  7A 57 76 51 41 41 47 51 41 41 4B 79 30 5A 41 41 43 39 31 76 7A 50 48 36 53 68 2B 4C 30 3D 22 2C  |zWvQAAGQAAKy0ZAAC91vzPH6Sh+L0=",|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  22 64 61 74 72 22 3A 22 53 46 31 30 42 57 31 32 35 22 2C 22 66 72 65 71 22 3A 38 36 38 2E 33 2C  |"datr":"SF10BW125","freq":868.3,|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  22 6A 76 65 72 22 3A 32 2C 22 6D 6F 64 75 22 3A 22 4C 4F 52 41 22 2C 22 72 73 69 67 22 3A 5B 7B  |"jver":2,"modu":"LORA","rsig":[{|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  22 61 6E 74 22 3A 30 2C 22 63 68 61 6E 22 3A 36 2C 22 6C 73 6E 72 22 3A 31 32 2E 32 2C 22 72 73  |"ant":0,"chan":6,"lsnr":12.2,"rs|
May 29 15:02:08 klk-wifc-030969 local1.info lorad[934]: <6> Sent 1 uplink message
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  73 69 63 22 3A 2D 34 38 7D 5D 2C 22 73 69 7A 65 22 3A 32 33 2C 22 73 74 61 74 22 3A 31 2C 22 74  |sic":-48}],"size":23,"stat":1,"t|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  69 6D 65 22 3A 22 32 30 31 39 2D 30 35 2D 32 39 54 31 33 3A 30 32 3A 30 38 2E 33 33 31 35 32 38  |ime":"2019-05-29T13:02:08.331528|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  5A 22 2C 22 74 6D 73 74 22 3A 31 31 37 38 37 34 30 34 37 36 7D 5D 7D                             |Z","tmst":1178740476}]}|
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> Uplink message (39D5) sent
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  02 39 D5 01                                                                                      |.9..|
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> Uplink message (39D5) acknowledged in 1.92948 ms
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  02 B3 18 03 7B 22 74 78 70 6B 22 3A 7B 22 69 6D 6D 65 22 3A 66 61 6C 73 65 2C 22 72 66 63 68 22  |....{"txpk":{"imme":false,"rfch"|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  3A 30 2C 22 70 6F 77 65 22 3A 31 34 2C 22 61 6E 74 22 3A 30 2C 22 62 72 64 22 3A 32 36 32 2C 22  |:0,"powe":14,"ant":0,"brd":262,"|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  74 6D 73 74 22 3A 31 31 38 33 37 34 30 34 37 36 2C 22 66 72 65 71 22 3A 38 36 38 2E 33 2C 22 6D  |tmst":1183740476,"freq":868.3,"m|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  6F 64 75 22 3A 22 4C 4F 52 41 22 2C 22 64 61 74 72 22 3A 22 53 46 31 30 42 57 31 32 35 22 2C 22  |odu":"LORA","datr":"SF10BW125","|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  63 6F 64 72 22 3A 22 34 2F 35 22 2C 22 69 70 6F 6C 22 3A 74 72 75 65 2C 22 73 69 7A 65 22 3A 31  |codr":"4/5","ipol":true,"size":1|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  37 2C 22 64 61 74 61 22 3A 22 49 45 37 61 2B 6B 6A 71 38 54 65 64 31 36 69 77 59 49 54 68 49 34  |7,"data":"IE7a+kjq8Ted16iwYIThI4|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  59 3D 22 7D 7D                                                                                   |Y="}}|
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> Downlink message (B318) received
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> Received downlink message: 
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> | lora downlink (0000B318), payload 17 B, required 1, preamble 8 B, header enabled, crc enabled, polarity inverted
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> | Join Accept
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> |  - radio (00000106), channel 868.3 MHz, bw 125 kHz, sf 10, cr 4/5, power 14 dB
May 29 15:02:08 klk-wifc-030969 local1.info lorafwd[960]: <6> |   - transmission (00000000), priority 1, on counter 1183740476
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.send:  0A 47 08 98 E6 02 12 11 20 4E DA FA 48 EA F1 37 9D D7 A8 B0 60 84 E1 23 86 18 01 20 08 28 01 30  |.G...... N..H..7....`..#... .(.0|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.send:  00 38 01 42 24 08 86 02 10 E0 E9 84 9E 03 18 00 20 03 2D 00 00 60 41 30 00 3A 0E 08 00 10 01 18  |.8.B$........... .-..`A0.:......|
May 29 15:02:08 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.send:  BC E4 B9 B4 04 30 00 38 00                                                                       |.....0.8.|
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7>   api.recv:  0a 47 08 98 e6 02 12 11 20 4e da fa 48 ea f1 37 9d d7 a8 b0 60 84 e1 23 86 18 01 20 08 28 01 30  |.G...... N..H..7....`..#... .(.0|
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7>   api.recv:  00 38 01 42 24 08 86 02 10 e0 e9 84 9e 03 18 00 20 03 2d 00 00 60 41 30 00 3a 0e 08 00 10 01 18  |.8.B$........... .-..`A0.:......|
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7>   api.recv:  bc e4 b9 b4 04 30 00 38 00                                                                       |.....0.8.|
May 29 15:02:08 klk-wifc-030969 local1.info lorad[934]: <6> Received downlink message
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> Requested power: 14 dB
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> Selected power: 11 dB
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> Current concentrator time is 1179026890, pkt_type=0
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> sorting queue in ascending order packet timestamp - queue size:1
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> sorting queue done - swapped:0
May 29 15:02:08 klk-wifc-030969 local1.info lorad[934]: <6> [jit] queue contains 1 packets:
May 29 15:02:08 klk-wifc-030969 local1.info lorad[934]: <6> [jit] queue contains 0 beacons:
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7>  - node[0]: count_us=1183740476 - type=0
May 29 15:02:08 klk-wifc-030969 local1.debug lorad[934]: <7> enqueued packet with count_us=1183740476 (size=17 bytes, toa=329000 us, type=0)
May 29 15:02:10 klk-wifc-030969 local1.debug lorad[934]: <7> Demodulator synchronized with MONOTONIC: drift=-3us
May 29 15:02:10 klk-wifc-030969 local1.debug lorad[934]: <7> Demodulator synchronized with UTC: drift=10us
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7> peek packet with count_us=1183740476 at index 0
May 29 15:02:13 klk-wifc-030969 local1.info lorad[934]: <6> [jit] queue is empty
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7> dequeued packet with count_us=1183740476 from index 0
May 29 15:02:13 klk-wifc-030969 local1.err lorad[934]: <3> SELECTED RF_CHAIN IS DISABLED FOR TX ON SELECTED BOARD
May 29 15:02:13 klk-wifc-030969 local1.err lorad[934]: <3> Failed to send message
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7>   api.send:  1a 0a 12 08 08 98 e6 02 10 00 18 01                                                              |............|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.recv:  1A 0A 12 08 08 98 E6 02 10 00 18 01                                                              |............|
May 29 15:02:13 klk-wifc-030969 local1.info lorafwd[960]: <6> Received uplink message: transmission event (0000B318 / 00000000), status "Transmission failed"
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  02 B3 18 05 72 76 FF 00 39 03 09 69 7B 22 74 78 70 6B 5F 61 63 6B 22 3A 7B 22 65 72 72 6F 72 22  |....rv..9..i{"txpk_ack":{"error"|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.send:  3A 22 55 4E 4B 4E 4F 57 4E 22 7D 7D                                                              |:"UNKNOWN"}}|
May 29 15:02:13 klk-wifc-030969 local1.info lorafwd[960]: <6> Downlink message (B318) acknowledged
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  02 B3 18 03 7B 22 74 78 70 6B 22 3A 7B 22 69 6D 6D 65 22 3A 66 61 6C 73 65 2C 22 72 66 63 68 22  |....{"txpk":{"imme":false,"rfch"|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  3A 30 2C 22 70 6F 77 65 22 3A 31 34 2C 22 61 6E 74 22 3A 30 2C 22 62 72 64 22 3A 32 36 32 2C 22  |:0,"powe":14,"ant":0,"brd":262,"|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  74 6D 73 74 22 3A 31 31 38 34 37 34 30 34 37 36 2C 22 66 72 65 71 22 3A 38 36 39 2E 35 32 35 2C  |tmst":1184740476,"freq":869.525,|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  22 6D 6F 64 75 22 3A 22 4C 4F 52 41 22 2C 22 64 61 74 72 22 3A 22 53 46 31 32 42 57 31 32 35 22  |"modu":"LORA","datr":"SF12BW125"|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  2C 22 63 6F 64 72 22 3A 22 34 2F 35 22 2C 22 69 70 6F 6C 22 3A 74 72 75 65 2C 22 73 69 7A 65 22  |,"codr":"4/5","ipol":true,"size"|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  3A 31 37 2C 22 64 61 74 61 22 3A 22 49 45 37 61 2B 6B 6A 71 38 54 65 64 31 36 69 77 59 49 54 68  |:17,"data":"IE7a+kjq8Ted16iwYITh|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>  gwmp.recv:  49 34 59 3D 22 7D 7D                                                                             |I4Y="}}|
May 29 15:02:13 klk-wifc-030969 local1.info lorafwd[960]: <6> Downlink message (B318) received
May 29 15:02:13 klk-wifc-030969 local1.info lorafwd[960]: <6> Received downlink message: 
May 29 15:02:13 klk-wifc-030969 local1.info lorafwd[960]: <6> | lora downlink (0000B318), payload 17 B, required 1, preamble 8 B, header enabled, crc enabled, polarity inverted
May 29 15:02:13 klk-wifc-030969 local1.info lorafwd[960]: <6> | Join Accept
May 29 15:02:13 klk-wifc-030969 local1.info lorafwd[960]: <6> |  - radio (00000106), channel 869.525 MHz, bw 125 kHz, sf 12, cr 4/5, power 14 dB
May 29 15:02:13 klk-wifc-030969 local1.info lorafwd[960]: <6> |   - transmission (00000000), priority 1, on counter 1184740476
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.send:  0A 47 08 98 E6 02 12 11 20 4E DA FA 48 EA F1 37 9D D7 A8 B0 60 84 E1 23 86 18 01 20 08 28 01 30  |.G...... N..H..7....`..#... .(.0|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.send:  00 38 01 42 24 08 86 02 10 88 CC CF 9E 03 18 00 20 05 2D 00 00 60 41 30 00 3A 0E 08 00 10 01 18  |.8.B$........... .-..`A0.:......|
May 29 15:02:13 klk-wifc-030969 local1.debug lorafwd[960]: <7>   api.send:  FC E8 F6 B4 04 30 00 38 00                                                                       |.....0.8.|
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7>   api.recv:  0a 47 08 98 e6 02 12 11 20 4e da fa 48 ea f1 37 9d d7 a8 b0 60 84 e1 23 86 18 01 20 08 28 01 30  |.G...... N..H..7....`..#... .(.0|
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7>   api.recv:  00 38 01 42 24 08 86 02 10 88 cc cf 9e 03 18 00 20 05 2d 00 00 60 41 30 00 3a 0e 08 00 10 01 18  |.8.B$........... .-..`A0.:......|
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7>   api.recv:  fc e8 f6 b4 04 30 00 38 00                                                                       |.....0.8.|
May 29 15:02:13 klk-wifc-030969 local1.info lorad[934]: <6> Received downlink message
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7> Requested power: 14 dB
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7> Selected power: 11 dB
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7> Current concentrator time is 1183729971, pkt_type=0
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7> sorting queue in ascending order packet timestamp - queue size:1
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7> sorting queue done - swapped:0
May 29 15:02:13 klk-wifc-030969 local1.info lorad[934]: <6> [jit] queue contains 1 packets:
May 29 15:02:13 klk-wifc-030969 local1.info lorad[934]: <6> [jit] queue contains 0 beacons:
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7>  - node[0]: count_us=1184740476 - type=0
May 29 15:02:13 klk-wifc-030969 local1.debug lorad[934]: <7> enqueued packet with count_us=1184740476 (size=17 bytes, toa=1318000 us, type=0)

Hello!

Have anyone eventually solved this?
I somehow have a weird situation, my node gets activated normally until the machine that runs loraserver is rebooted. After that I am not able anymore to activate the end node, and on the server I can see join request and join accept. Any sugestions what can I do?

Thanks in advance!

Nobody is replying here sadly, all new threads about this get redirected here but it just dies

Hi all, I´m triying with a RN2903 node, who works well on OTAA 1.02 over ORBIWISE lora server. But , trying with Loraserver, I have the same problem of “Join Request/Join Accept " loop messages. But no activation device performed, nor " Live device Data”. Observing the logs, I have the following messages:

{“log”:“time=“2019-07-12T13:16:27Z” level=info msg=“js: request received” message_type=JoinReq receiver_id=0000000000000000 sender_id=000000 transaction_id=4149628007\n”,“stream”:“stderr”,“time”:“2019-07-12T13:16:27.14633477Z”}
{“log”:“time=“2019-07-12T13:16:27Z” level=info msg=“device-keys updated” dev_eui=0004a30b002171fb\n”,“stream”:“stderr”,“time”:“2019-07-12T13:16:27.146386847Z”}
{“log”:“time=“2019-07-12T13:16:27Z” level=info msg=“js: sending response” message_type=JoinAns receiver_id=000000 result_code=Success sender_id=0000000000000000 transaction_id=4149628007\n”,“stream”:“stderr”,“time”:“2019-07-12T13:16:27.146394303Z”}

{“log”:“time=“2019-07-12T13:17:17Z” level=info msg=“js: request received” message_type=JoinReq receiver_id=0000000000000000 sender_id=000000 transaction_id=2892994530\n”,“stream”:“stderr”,“time”:“2019-07-12T13:17:17.458615718Z”}
{“log”:“time=“2019-07-12T13:17:17Z” level=info msg=“device-keys updated” dev_eui=0004a30b002171fb\n”,“stream”:“stderr”,“time”:“2019-07-12T13:17:17.460690634Z”}
{“log”:“time=“2019-07-12T13:17:17Z” level=info msg=“js: sending response” message_type=JoinAns receiver_id=000000 result_code=Success sender_id=0000000000000000 transaction_id=2892994530\n”,“stream”:“stderr”,“time”:“2019-07-12T13:17:17.460709009Z”}

{“log”:“time=“2019-07-12T13:18:07Z” level=info msg=“js: request received” message_type=JoinReq receiver_id=0000000000000000 sender_id=000000 transaction_id=3323708117\n”,“stream”:“stderr”,“time”:“2019-07-12T13:18:07.802149814Z”}
{“log”:“time=“2019-07-12T13:18:07Z” level=info msg=“device-keys updated” dev_eui=0004a30b002171fb\n”,“stream”:“stderr”,“time”:“2019-07-12T13:18:07.805253541Z”}
{“log”:“time=“2019-07-12T13:18:07Z” level=info msg=“js: sending response” message_type=JoinAns receiver_id=000000 result_code=Success sender_id=0000000000000000 transaction_id=3323708117\n”,“stream”:“stderr”,“time”:“2019-07-12T13:18:07.805501181Z”}

{“log”:“time=“2019-07-12T13:21:41Z” level=info msg=“js: request received” message_type=JoinReq receiver_id=0000000000000000 sender_id=000000 transaction_id=46488453\n”,“stream”:“stderr”,“time”:“2019-07-12T13:21:41.706950764Z”}
{“log”:“time=“2019-07-12T13:21:41Z” level=info msg=“device-keys updated” dev_eui=0004a30b002171fb\n”,“stream”:“stderr”,“time”:“2019-07-12T13:21:41.709136599Z”}
{“log”:“time=“2019-07-12T13:21:41Z” level=info msg=“js: sending response” message_type=JoinAns receiver_id=000000 result_code=Success sender_id=0000000000000000 transaction_id=46488453\n”,“stream”:“stderr”,“time”:“2019-07-12T13:21:41.709305924Z”}

Any help on this?? Thanks in advance to all. Best regards

To meaningfully debug something like this, you need to look at the node’s perspective and not just the server’s. As far as the server is concerned, it got a request and responded. Yet the node sent another request after that, so you need to figure out why.

Did the node even receive a packet? Was it listening at the right time and with the right settings?

Did the packet have a valid MIC?

Did the packet decrypt to something meaningful that the node understood and could act on?

The server claims it did its part, you need to figure out why the node “didn’t hear” or “didn’t like”

Get some serial debug output going from your node firmware so that it gives you a running commentary of what is happening from its perspective.

I have just gone through this exact same problem and for me, I fixed it.

My EndNode firmware was defective. It’s a long story.

I suggest that you change the log level in the .toml files, to debug and see if the increased information helps you to track down the problem.

I can confirm, an installation of LoraServer, lora-gateway-bridge, loraserver and lora-app-server, performed according to to the Debian/Ubuntu Quick Start Guide published by Orne, works out of the box.

Dang those End-Node coders. :wink:

This entry is to help folks troubleshoot an OTAA Join Request / Accept cycle.
This is what it should look like
I went through a Join Request / Accept cycle on my now running system.
I recorded a log of lora-app-server with debug on, sudo journalctl -f -n 100 -u lora-app-server,

LOG FILE OUTPUT
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time=“2019-07-12T18:49:10-04:00” level=info msg=“finished streaming call with code Canceled” error=“rpc error: code = Canceled desc = context canceled” grpc.code=Canceled grpc.method=StreamFrameLogs grpc.service=api.DeviceService grpc.start_time=“2019-07-12T18:46:54-04:00” grpc.time_ms=136462.11 peer.address=“127.0.0.1:57912” span.kind=server system=grpc

Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=info msg="js: request received" message_type=JoinReq receiver_id=696f740101010101 sender_id=030201 transaction_id=2352370911

Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=debug msg="sql query executed" args="[[52 53 49 49 121 55 119 18]]" duration="799.958µs" query="select * from device_keys where dev_eui = $1"
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=debug msg="sql query executed" args="[[52 53 49 49 121 55 119 )]À    18] 2019-07-12 18:49:10.530369552 -0400 EDT m=+136.857560805 [43 126 21 22 40 174 210 166 171 247 21 136 9 207 79 60] [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] 8 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]]" duration=4.14284ms query="\n        update device_keys\n        set\n            updated_at = $2,\n\t\t\tnwk_key = $3,\n\t\t\tapp_key = $4,\n\t\t\tjoin_nonce = $5,\n\t\t\tgen_app_key = $6\n        where\n            dev_eui = $1"
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=info msg="device-keys updated" dev_eui=3435313179377712

Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=info msg="js: sending response" message_type=JoinAns receiver_id=030201 result_code=Success sender_id=696f740101010101 transaction_id=2352370911

Jul 12 18:49:11 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:11-04:00" level=debug msg="sql query executed" args="[3 2019-07-12 18:49:11.084050786 -0400 EDT m=+137.411241976 100]" duration="896.612µs" query="\n\t)]ý    \tselect\n\t\t\t*\n\t\tfrom\n\t\t\tremote_multicast_setup\n\t\twhere\n\t\t\tstate_provisioned = false\n\t\t\tand retry_count < $1\n\t\t\tand retry_after < $2\n\t\tlimit $3\n\t\tfor update\n\t\tskip locked"

LORWAN FRAMES FROM UI

Content for the JSON entries in the picture
[
{
“downlinkMetaData”: {
“txInfo”: {
“gatewayId”: “0004a30b0022813c”,
“frequency”: 924500000,
“power”: 20,
“modulation”: “LORA”,
“loraModulationInfo”: {
“bandwidth”: 500,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: true
},
“board”: 0,
“antenna”: 0,
“timing”: “DELAY”,
“delayTimingInfo”: {
“delay”: “1s”
},
“context”: “t2xTBA==”
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “UnconfirmedDataDown”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“fhdr”: {
“devAddr”: “034b35eb”,
“fCtrl”: {
“adr”: true,
“adrAckReq”: false,
“ack”: false,
“fPending”: false,
“classB”: false
},
“fCnt”: 1,
“fOpts”: [
{
“cid”: “LinkADRReq”,
“payload”: {
“dataRate”: 0,
“txPower”: 9,
“chMask”: [
true,
true,
true,
true,
true,
true,
true,
true,
false,
false,
false,
false,
false,
false,
false,
false
],
“redundancy”: {
“chMaskCntl”: 0,
“nbRep”: 1
}
}
}
]
},
“fPort”: null,
“frmPayload”: null
},
“mic”: “50267fae”
}
},
{
“uplinkMetaData”: {
“rxInfo”: [
{
“gatewayId”: “0004a30b0022813c”,
“time”: null,
“timeSinceGpsEpoch”: null,
“rssi”: -42,
“loraSnr”: 7.8,
“channel”: 2,
“rfChain”: 0,
“board”: 0,
“antenna”: 0,
“location”: {
“latitude”: 45.37303,
“longitude”: -75.6234,
“altitude”: 227,
“source”: “UNKNOWN”,
“accuracy”: 0
},
“fineTimestampType”: “NONE”,
“context”: “t2xTBA==”
}
],
“txInfo”: {
“frequency”: 902700000,
“modulation”: “LORA”,
“loRaModulationInfo”: {
“bandwidth”: 125,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: false
}
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “UnconfirmedDataUp”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“fhdr”: {
“devAddr”: “034b35eb”,
“fCtrl”: {
“adr”: true,
“adrAckReq”: false,
“ack”: false,
“fPending”: false,
“classB”: false
},
“fCnt”: 2,
“fOpts”: null
},
“fPort”: 0,
“frmPayload”: [
{
“cid”: “LinkADRReq”,
“payload”: {
“channelMaskAck”: true,
“dataRateAck”: true,
“powerAck”: true
}
},
{
“cid”: “LinkADRReq”,
“payload”: {
“channelMaskAck”: true,
“dataRateAck”: true,
“powerAck”: true
}
}
]
},
“mic”: “2d0871fd”
}
},
{
“downlinkMetaData”: {
“txInfo”: {
“gatewayId”: “0004a30b0022813c”,
“frequency”: 923900000,
“power”: 20,
“modulation”: “LORA”,
“loraModulationInfo”: {
“bandwidth”: 500,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: true
},
“board”: 0,
“antenna”: 0,
“timing”: “DELAY”,
“delayTimingInfo”: {
“delay”: “1s”
},
“context”: “ttRgjA==”
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “UnconfirmedDataDown”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“fhdr”: {
“devAddr”: “034b35eb”,
“fCtrl”: {
“adr”: true,
“adrAckReq”: false,
“ack”: false,
“fPending”: false,
“classB”: false
},
“fCnt”: 0,
“fOpts”: [
{
“cid”: “LinkADRReq”,
“payload”: {
“dataRate”: 0,
“txPower”: 0,
“chMask”: [
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false
],
“redundancy”: {
“chMaskCntl”: 7,
“nbRep”: 0
}
}
},
{
“cid”: “LinkADRReq”,
“payload”: {
“dataRate”: 0,
“txPower”: 5,
“chMask”: [
true,
true,
true,
true,
true,
true,
true,
true,
false,
false,
false,
false,
false,
false,
false,
false
],
“redundancy”: {
“chMaskCntl”: 0,
“nbRep”: 1
}
}
}
]
},
“fPort”: null,
“frmPayload”: null
},
“mic”: “a0256faa”
}
},
{
“uplinkMetaData”: {
“rxInfo”: [
{
“gatewayId”: “0004a30b0022813c”,
“time”: null,
“timeSinceGpsEpoch”: null,
“rssi”: -41,
“loraSnr”: 10,
“channel”: 1,
“rfChain”: 0,
“board”: 0,
“antenna”: 0,
“location”: {
“latitude”: 45.37303,
“longitude”: -75.6234,
“altitude”: 227,
“source”: “UNKNOWN”,
“accuracy”: 0
},
“fineTimestampType”: “NONE”,
“context”: “ttRgjA==”
}
],
“txInfo”: {
“frequency”: 902500000,
“modulation”: “LORA”,
“loRaModulationInfo”: {
“bandwidth”: 125,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: false
}
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “UnconfirmedDataUp”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“fhdr”: {
“devAddr”: “034b35eb”,
“fCtrl”: {
“adr”: true,
“adrAckReq”: false,
“ack”: false,
“fPending”: false,
“classB”: false
},
“fCnt”: 1,
“fOpts”: null
},
“fPort”: 99,
“frmPayload”: [
{
“bytes”: “cVa80j4c/p4b2Dk=”
}
]
},
“mic”: “b98e89ef”
}
},
{
“downlinkMetaData”: {
“txInfo”: {
“gatewayId”: “0004a30b0022813c”,
“frequency”: 925700000,
“power”: 20,
“modulation”: “LORA”,
“loraModulationInfo”: {
“bandwidth”: 500,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: true
},
“board”: 0,
“antenna”: 0,
“timing”: “DELAY”,
“delayTimingInfo”: {
“delay”: “5s”
},
“context”: “tjuRDA==”
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “JoinAccept”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“bytes”: “rRhFmXoqzPerBoL4bF82n6H4BSpUad2XyF3FwA==”
},
“mic”: “f2d2f108”
}
},
{
“uplinkMetaData”: {
“rxInfo”: [
{
“gatewayId”: “0004a30b0022813c”,
“time”: null,
“timeSinceGpsEpoch”: null,
“rssi”: -41,
“loraSnr”: 11,
“channel”: 4,
“rfChain”: 1,
“board”: 0,
“antenna”: 0,
“location”: {
“latitude”: 45.37303,
“longitude”: -75.6234,
“altitude”: 227,
“source”: “UNKNOWN”,
“accuracy”: 0
},
“fineTimestampType”: “NONE”,
“context”: “tjuRDA==”
}
],
“txInfo”: {
“frequency”: 903100000,
“modulation”: “LORA”,
“loRaModulationInfo”: {
“bandwidth”: 125,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: false
}
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “JoinRequest”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“joinEUI”: “696f740101010101”,
“devEUI”: “3435313179377712”,
“devNonce”: 21441
},
“mic”: “665251e3”
}
}
]

This isn’t really going to show the issue in most cases. If there’s a join accept being sent (and for the people asking the questions, there is repeatedly) then there’s likely not much that can be learned from server logs, rather what is needed is to figure out what the node is seeing.

Also in real world situations, occasional repeats of the join process can be possible, because it’s just about as easy for a node to miss the downlink transmission as it is for a gateway to miss an uplink one. The key difference between a working and a non-working situation is that in fairly short order one of the join accepts should get through and result in application traffic.

Another thing to note (which is not showing up in the reports of difficulty so far but easily could) is that nonce re-use by the node can lead to initial join attempts being rejected. Some node firmwares are particularly bad about this, for example picking a random number but then simply incrementing or decrementing it on re-tries. Couple that with a random number generator that might be a bit too deterministic, and you can end up with a node that takes longer and longer to send a not previously used nonce each time it starts up.

1 Like

You are correct.
My point was that for all the new folks that are just starting out, it’s nice (I wish it had been there for me) to have some real world examples of what things should look like and assurance that LoraServer performs properly out of the box.
So, given that the user has done all the correct things to start out, according to Orne’s Quick Start Guide, then the issue is with the EndNode. Radio problems (too far away from Gateway) or in my case, bad firmware, or as you have suggested nonce issue in random seeds.
For me, I could create new and updated firmware and load it.
For someone else with a purchased EndNode, they may have to contact the Manufacturer to get updated firmware or to arrange a unit exchange.

Thanks for your help and fast responses @rtomkins2, @cstratton . I´ll take your advices and look at the node side too. Also I´m experiencing with LMIC and RFM95w nodes, and had the same problem. Anyway, thanks again and keep all informed about news on this.

Thank you for the support! Its a amazing project.

I am also trying with a CMWX1ZZABZ-091 module using I-CUBE-LRWAN v1.2.2. I’m facing the same problem… The OTAA and ABP doesn’t connect to loraserver.

Using the same configuration (same id and keys) I can connect successfully to Loriot and TTN (this one with some packet loss), using the same gateway Laird RG1xx.

Hey @kuoyaoming I can verify that OTAA and I-CUBE-LRWAN works fine without any issues. Your issue must be something else like key order. I also have a few Laird RG1xx gateways and things work fine. I’ve actually never experienced the join loop issue in the past 3 to 4 releases of I-CUBE-LRWAN.

If ABP doesn’t work either, you’re surely doing something wrong with your keys.

Hey @bryansmith, thank you for your quick response, I solved the problem. In device profile, I have to set lorawan version as v.1.0.0 A/B.

Now I’m facing packet loss but it doesn’t correspond to this topic.