BNNorman / dragino-1

LoRaWAN implementation in python
Other
13 stars 3 forks source link

OTAA Connection Issue #5

Closed Alixpat closed 5 months ago

Alixpat commented 5 months ago

Dear @BNNorman,

I am experiencing difficulties in establishing an OTAA connection using the library. Below are the logs captured during my attempt to connect with test.py :

2024-04-22 21:46:00,582 - __init__ - 78 - INFO - __init__ starting
2024-04-22 21:46:01,223 - setCacheDefaults - 413 - INFO - Setting default MAC values using user config values
2024-04-22 21:46:01,223 - getFrequencyPlan - 342 - INFO - loading frequency plan
2024-04-22 21:46:01,223 - getFrequencyPlan - 345 - INFO - Frequency Plan is EU_863_870_TTN
2024-04-22 21:46:01,224 - getFrequencyPlan - 354 - INFO - Frequency Plan loaded ok
2024-04-22 21:46:01,224 - setCacheDefaults - 479 - INFO - MAC default settings finished
2024-04-22 21:46:01,224 - __init__ - 104 - DEBUG - Setting self.cache[fCntUp] to 0
2024-04-22 21:46:01,225 - __init__ - 104 - DEBUG - Setting self.cache[fCntDn] to 0
2024-04-22 21:46:01,225 - __init__ - 104 - DEBUG - Setting self.cache[rx1_delay] to 5
2024-04-22 21:46:01,225 - __init__ - 104 - DEBUG - Setting self.cache[rx2_delay] to 1
2024-04-22 21:46:01,225 - __init__ - 104 - DEBUG - Setting self.cache[rx1_DR] to 3
2024-04-22 21:46:01,226 - __init__ - 104 - DEBUG - Setting self.cache[rx2_DR] to 3
2024-04-22 21:46:01,226 - __init__ - 108 - INFO - missing TTN section key rx1_freq_fixed ignored
2024-04-22 21:46:01,227 - __init__ - 108 - INFO - missing TTN section key rx1_frequency ignored
2024-04-22 21:46:01,227 - __init__ - 104 - DEBUG - Setting self.cache[rx2_frequency] to 869.525
2024-04-22 21:46:01,227 - __init__ - 108 - INFO - missing TTN section key duty_cycle ignored
2024-04-22 21:46:01,227 - __init__ - 104 - DEBUG - Setting self.cache[data_rate] to 3
2024-04-22 21:46:01,228 - __init__ - 116 - DEBUG - Setting self.cache[devaddr] to [0, 0, 0, 0]
2024-04-22 21:46:01,228 - __init__ - 116 - DEBUG - Setting self.cache[deveui] to [112, 179, 213, 126, 208, 6, 110, 35]
2024-04-22 21:46:01,228 - __init__ - 119 - INFO - Missing OTAA TTN key nwkskey ignored
2024-04-22 21:46:01,229 - __init__ - 119 - INFO - Missing OTAA TTN key appskey ignored
2024-04-22 21:46:01,229 - __init__ - 116 - DEBUG - Setting self.cache[appeui] to [170, 170, 170, 170, 170, 170, 170, 170]
2024-04-22 21:46:01,229 - __init__ - 116 - DEBUG - Setting self.cache[appkey] to [5, 164, 28, 178, 1, 211, 183, 215, 203, 94, 232, 60, 155, 89, 238, 86]
2024-04-22 21:46:01,230 - loadCache - 524 - INFO - Loading MAC settings
2024-04-22 21:46:01,230 - loadCache - 542 - INFO - cached settings load failed [Errno 2] No such file or directory: 'cache.json'. Saving current defaults
2024-04-22 21:46:01,230 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:01,232 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:01,234 - __init__ - 141 - INFO - __init__ done
2024-04-22 21:46:01,235 - __init__ - 97 - WARNING - Not enabling GPS (see enableGPS param)
2024-04-22 21:46:01,236 - __init__ - 134 - INFO - __init__ done
2024-04-22 21:46:01,237 - registered - 557 - INFO - checking if already registered.
2024-04-22 21:46:01,237 - registered - 563 - INFO - devaddr [0, 0, 0, 0] len 4.
2024-04-22 21:46:01,237 - registered - 571 - DEBUG - devaddr not assigned 
2024-04-22 21:46:01,238 - join - 491 - INFO - Performing OTAA Join
2024-04-22 21:46:01,238 - getJoinSettings - 230 - DEBUG - using join settings: freq 868.5 sf 9 bw 7
2024-04-22 21:46:01,238 - configureRadio - 174 - INFO -  freq=868.5 sf=9 bw=7
2024-04-22 21:46:01,241 - _tryToJoin - 504 - INFO - trying to join TTN
2024-04-22 21:46:01,241 - registered - 557 - INFO - checking if already registered.
2024-04-22 21:46:01,242 - registered - 563 - INFO - devaddr [0, 0, 0, 0] len 4.
2024-04-22 21:46:01,242 - registered - 571 - DEBUG - devaddr not assigned 
2024-04-22 21:46:01,242 - _tryToJoin - 514 - DEBUG - App key = [5, 164, 28, 178, 1, 211, 183, 215, 203, 94, 232, 60, 155, 89, 238, 86]
2024-04-22 21:46:01,243 - _tryToJoin - 515 - DEBUG - App eui = [170, 170, 170, 170, 170, 170, 170, 170]
2024-04-22 21:46:01,243 - _tryToJoin - 516 - DEBUG - Dev eui = [112, 179, 213, 126, 208, 6, 110, 35]
2024-04-22 21:46:01,243 - _tryToJoin - 517 - DEBUG - Devnonce= [69, 132]
2024-04-22 21:46:01,246 - _tryToJoin - 528 - DEBUG - sending packet [0, 170, 170, 170, 170, 170, 170, 170, 170, 35, 110, 6, 208, 126, 213, 179, 112, 69, 132, 128, 42, 207, 219]
2024-04-22 21:46:01,248 - registered - 557 - INFO - checking if already registered.
2024-04-22 21:46:01,248 - registered - 563 - INFO - devaddr [0, 0, 0, 0] len 4.
2024-04-22 21:46:01,248 - registered - 571 - DEBUG - devaddr not assigned 
2024-04-22 21:46:01,454 - on_tx_done - 427 - INFO - switching to RX1
2024-04-22 21:46:01,455 - getRX1Settings - 278 - DEBUG - RX1 settings : freq 868.5 sf 9 bw 7
2024-04-22 21:46:01,455 - configureRadio - 174 - INFO -  freq=868.5 sf=9 bw=7
2024-04-22 21:46:01,457 - on_tx_done - 433 - INFO - setting timer delay {delay} to switch to RX2
2024-04-22 21:46:03,251 - registered - 557 - INFO - checking if already registered.
2024-04-22 21:46:03,252 - registered - 563 - INFO - devaddr [0, 0, 0, 0] len 4.
2024-04-22 21:46:03,252 - registered - 571 - DEBUG - devaddr not assigned 
2024-04-22 21:46:05,255 - registered - 557 - INFO - checking if already registered.
2024-04-22 21:46:05,255 - registered - 563 - INFO - devaddr [0, 0, 0, 0] len 4.
2024-04-22 21:46:05,256 - registered - 571 - DEBUG - devaddr not assigned 
2024-04-22 21:46:06,703 - on_rx_done - 350 - DEBUG - Received message...
2024-04-22 21:46:06,705 - on_rx_done - 366 - DEBUG - raw payload [32, 124, 35, 143, 135, 113, 126, 151, 212, 149, 21, 34, 28, 23, 89, 140, 97, 2, 114, 4, 234, 237, 216, 150, 144, 23, 14, 228, 154, 203, 6, 54, 206]
2024-04-22 21:46:06,705 - process_JOIN_ACCEPT - 218 - DEBUG - Trying to process JOIN_ACCEPT
2024-04-22 21:46:06,707 - process_JOIN_ACCEPT - 226 - DEBUG - decoded JOIN_ACCEPT payload [15, 0, 0, 19, 0, 0, 61, 89, 11, 38, 3, 5, 24, 79, 132, 232, 86, 132, 184, 94, 132, 136, 102, 132, 88, 110, 132, 0]
2024-04-22 21:46:06,708 - setLastSNR - 149 - INFO - last SNR value 50.5
2024-04-22 21:46:06,708 - setRX1Delay - 169 - INFO - set RX1 delay 5
2024-04-22 21:46:06,709 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:06,712 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:06,717 - setDLsettings - 376 - INFO - DL settings rx1_dr_offset0 rx1_DR 3 rx2_DR 3
2024-04-22 21:46:06,719 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:06,724 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:06,729 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:06,734 - process_JOIN_ACCEPT - 269 - DEBUG - devaddr: [38, 11, 89, 61]
2024-04-22 21:46:06,734 - process_JOIN_ACCEPT - 270 - DEBUG - nwkskey: [152, 85, 14, 179, 75, 201, 101, 250, 245, 50, 1, 230, 104, 39, 137, 56]
2024-04-22 21:46:06,735 - process_JOIN_ACCEPT - 271 - DEBUG - appskey: [211, 201, 209, 25, 141, 23, 253, 4, 69, 39, 66, 148, 125, 255, 59, 206]
2024-04-22 21:46:06,735 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:06,739 - saveCache - 489 - INFO - Saving MAC settings
2024-04-22 21:46:07,258 - registered - 557 - INFO - checking if already registered.
2024-04-22 21:46:07,259 - registered - 563 - INFO - devaddr [38, 11, 89, 61] len 4.
2024-04-22 21:46:07,260 - registered - 583 - INFO - whilst checking devaddr [38, 11, 89, 61] error was 'devaddr'
2024-04-22 21:46:09,262 - registered - 557 - INFO - checking if already registered.
2024-04-22 21:46:09,263 - registered - 563 - INFO - devaddr [38, 11, 89, 61] len 4.
2024-04-22 21:46:09,263 - registered - 583 - INFO - whilst checking devaddr [38, 11, 89, 61] error was 'devaddr'
2024-04-22 21:46:11,266 - registered - 557 - INFO - checking if already registered.
2024-04-22 21:46:11,266 - registered - 563 - INFO - devaddr [38, 11, 89, 61] len 4.
2024-04-22 21:46:11,267 - registered - 583 - INFO - whilst checking devaddr [38, 11, 89, 61] error was 'devaddr'
2024-04-22 21:46:13,269 - registered - 557 - INFO - checking if already registered.
...

It appears that despite receiving a JOIN_ACCEPT packet, the device does not seem to be properly registered, as indicated by the repeated 'devaddr' error.

Could you please advise if there are specific configurations or steps I might have missed? Any help in resolving this issue would be greatly appreciated.

Thank you for your time and assistance.

Best regards,

BNNorman commented 5 months ago

That's a weird Exception. Your devaddr is correct (valid ttn devaddr begins with 38) so no exception should be thrown. Can you paste/attach the cache.json for me to look at plz. Also check dragino.py indentation hasn't gotten out of kilter. Note, I'm halfway through a bottle of wine right now so would only make sense in the morning. Lol.

BNNorman commented 5 months ago

I have a sneaking suspicion that the devaddr has been cached as a bytearray instead of a list. If you delete cache.json and run the test.py again the code will rejoin TTN and store fresh data in cache.json. That may or may not work.

Alixpat commented 5 months ago

cache.json :

{"data_rate": 3, "channelJoinFrequencies": [868.1, 868.3, 868.5], "channelTxFrequencies": [868.1, 868.3, 868.5, 867.1, 867.3, 867.5, 868.7, 867.9], "channelRX1Frequencies": [868.1, 868.3, 868.5, 867.1, 867.3, 867.5, 868.7, 867.9], "output_power": 15, "max_power": 15, "duty_cycle": 1, "rx1_DR": 3, "rx2_DR": 3, "rx1_freq_fixed": false, "rx2_frequency": 869.525, "rx1_delay": 5, "rx2_delay": 1, "appkey": [5, 164, 28, 178, 1, 211, 183, 215, 203, 94, 232, 60, 155, 89, 238, 86], "appeui": [170, 170, 170, 170, 170, 170, 170, 170], "deveui": [112, 179, 213, 126, 208, 6, 110, 35], "devaddr": [38, 11, 89, 61], "appskey": [211, 201, 209, 25, 141, 23, 253, 4, 69, 39, 66, 148, 125, 255, 59, 206], "nwkskey": [152, 85, 14, 179, 75, 201, 101, 250, 245, 50, 1, 230, 104, 39, 137, 56], "fCntUp": 1, "fCntDn": 0, "max_duty_cycle": 1.0}

I remove cache.json, try again, I have a new devaddr but the error is the same

BNNorman commented 5 months ago

My original suspicion was wrong - the devaddr is not stored as a bytearray but I have found a typo in dragino.py at line 575

      if not devaddr[0] in self.config[DEVADDR][VAILD_DEVADDR]:

should be

      if not devaddr[0] in self.config[DEVADDR][VALID_DEVADDR]:

that might be the cause. I have updated the repo.

I do apologise for this, the code was being developed on a couple of devices simultaneously. Careless of me.

Alixpat commented 5 months ago

I have cloned the modified repository. However, I am still encountering the same error.

2024-04-23 19:21:05,505 - registered - 583 - INFO - whilst checking devaddr [38, 11, 85, 170] error was 'devaddr'
2024-04-23 19:21:07,507 - registered - 557 - INFO - checking if already registered.
2024-04-23 19:21:07,508 - registered - 563 - INFO - devaddr [38, 11, 85, 170] len 4.
2024-04-23 19:21:07,508 - registered - 583 - INFO - whilst checking devaddr [38, 11, 85, 170] error was 'devaddr'
2024-04-23 19:21:09,511 - registered - 557 - INFO - checking if already registered.
2024-04-23 19:21:09,512 - registered - 563 - INFO - devaddr [38, 11, 85, 170] len 4.
2024-04-23 19:21:09,512 - registered - 583 - INFO - whilst checking devaddr [38, 11, 85, 170] error was 'devaddr'
BNNorman commented 5 months ago

on line 51 in Strings.py change this

VALID_DEVADDR="VALID_DEV_ADDR"

to this.

VALID_DEVADDR="validDevAddr"

it needs to match the case in dragino.toml. Gosh, I need to be more careful. It's difficult to track changes made on several machines.

I have updated the repo.

Alixpat commented 5 months ago

I am still encountering the same error :

2024-04-23 19:51:33,961 - saveCache - 489 - INFO - Saving MAC settings
2024-04-23 19:51:33,976 - process_JOIN_ACCEPT - 269 - DEBUG - devaddr: [38, 11, 39, 53]
2024-04-23 19:51:33,977 - process_JOIN_ACCEPT - 270 - DEBUG - nwkskey: [104, 219, 224, 120, 18, 237, 40, 138, 224, 46, 225, 108, 155, 228, 44, 37]
2024-04-23 19:51:33,977 - process_JOIN_ACCEPT - 271 - DEBUG - appskey: [67, 72, 79, 20, 249, 229, 7, 107, 35, 139, 249, 195, 151, 94, 56, 80]
2024-04-23 19:51:33,978 - saveCache - 489 - INFO - Saving MAC settings
2024-04-23 19:51:34,004 - saveCache - 489 - INFO - Saving MAC settings
2024-04-23 19:51:34,487 - registered - 557 - INFO - checking if already registered.
2024-04-23 19:51:34,488 - registered - 563 - INFO - devaddr [38, 11, 39, 53] len 4.
2024-04-23 19:51:34,488 - registered - 583 - INFO - whilst checking devaddr [38, 11, 39, 53] error was 'devaddr'
2024-04-23 19:51:36,491 - registered - 557 - INFO - checking if already registered.
2024-04-23 19:51:36,492 - registered - 563 - INFO - devaddr [38, 11, 39, 53] len 4.
2024-04-23 19:51:36,493 - registered - 583 - INFO - whilst checking devaddr [38, 11, 39, 53] error was 'devaddr'
BNNorman commented 5 months ago

This is a really weird error - I'd expect Python to say something like the devaddr key doesn't exist. I have added a traceback.print_exception(e) to dragino.py - maybe it can tell me exactly which line is causing the grief.

This would appear in the console window not in the log file.

Alixpat commented 5 months ago

pi@raspberry:~/dragino-1 $ ./test.py Configuring GPIOs BOARD SpiDev created SX127x chip version is 0x12 initial mode is HF_LORA_RXCONT set_mode : HF_FSK_STDBY initial mode changed to HF_FSK_STDBY set_mode : HF_LORA_SLEEP set_mode : HF_LORA_RXCONT set_mode : HF_LORA_STDBY set_mode : HF_LORA_TX Waiting for JOIN ACCEPT .set_mode : HF_LORA_SLEEP set_mode : HF_LORA_RXCONT ..Traceback (most recent call last): File "/home/pi/dragino-1/dragino/dragino.py", line 577, in registered if not devaddr[0] in self.config[DEVADDR][VALID_DEVADDR]: KeyError: 'devaddr'

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/home/pi/dragino-1/./test.py", line 30, in while not D.registered(): File "/home/pi/dragino-1/dragino/dragino.py", line 586, in registered traceback.print_exception(e) TypeError: print_exception() missing 2 required positional arguments: 'value' and 'tb'

BNNorman commented 5 months ago

That's more helpful. I can see the problem./

if not devaddr[0] in self.config[DEVADDR][VALID_DEVADDR]:

for now just put quotes around DEVADDR - its a misuse of the DEVADDR as defined in Strings.py (devaddr). It needs to be capitalised for accessing the toml file section. I'll probably just underscore it in a minute or two

if not devaddr[0] in self.config["DEVADDR"][VALID_DEVADDR]:

Ok have just pushed an update to Strings.py and Dragino.py - I think that will fix it.

Alixpat commented 5 months ago

The bug is now fixed !

pi@raspberry:~/dragino-1 $ ./test.py 
Configuring GPIOs
BOARD SpiDev created
SX127x chip version is 0x12
initial mode is HF_LORA_RXCONT
set_mode : HF_FSK_STDBY
initial mode changed to HF_FSK_STDBY
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_STDBY
set_mode : HF_LORA_TX
Waiting for JOIN ACCEPT
.set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
..
Joined
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_STDBY
set_mode : HF_LORA_TX
Sent Hello World message
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_STDBY
set_mode : HF_LORA_TX
Sent Hello World message
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_STDBY
set_mode : HF_LORA_TX
Sent Hello World message
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_STDBY
set_mode : HF_LORA_TX
Sent Hello World message
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT
set_mode : HF_LORA_STDBY
set_mode : HF_LORA_TX
Sent Hello World message
set_mode : HF_LORA_SLEEP
set_mode : HF_LORA_RXCONT

Thanks a lot again !

BNNorman commented 5 months ago

No, thank you for helping fix my incompetence.