computenodes / dragino

LoRaWAN implementation in python
GNU Affero General Public License v3.0
27 stars 10 forks source link

OTAA - waiting repeats.... v2 ttn and v3 both see the activation. #6

Open Dukat-Gul opened 3 years ago

Dukat-Gul commented 3 years ago

console_OTAA_attempt_metadata Hi All. I have tried to get this working on my Raspberry Pi2 (with Dragino Lora/GPS_HAT v1.4) https://wiki.dragino.com/index.php?title=Lora/GPS_HAT

After adjusting for Subband 2 within AU915 (which TTN uses). I run the test.py code and all I see is the Waiting repeat.

pi@raspberrypi2:~/dragino $ ./test.py Mode <- SLEEP Mode <- FSK_STDBY Mode <- SLEEP Mode <- FSK_STDBY Mode <- SLEEP 2021-03-28 16:07:16,977 - Dragino - 58 - DEBUG - Nonce = [240, 225] 2021-03-28 16:07:16,986 - DraginoConfig - 303 - INFO - Using OTAA mode 2021-03-28 16:07:16,987 - DraginoConfig - 416 - DEBUG - Converted 8/8 items 2021-03-28 16:07:16,988 - DraginoConfig - 416 - DEBUG - Converted 8/8 items 2021-03-28 16:07:16,990 - DraginoConfig - 416 - DEBUG - Converted 16/16 items 2021-03-28 16:07:16,991 - DraginoConfig - 313 - WARNING - Unable to read session details 2021-03-28 16:07:16,992 - DraginoConfig - 325 - DEBUG - GPS Baud Rate: 9600 2021-03-28 16:07:16,994 - DraginoConfig - 326 - DEBUG - GPS Serial Port: /dev/serial0 2021-03-28 16:07:16,995 - DraginoConfig - 327 - DEBUG - GPS Serial Timeout: 1 2021-03-28 16:07:16,997 - DraginoConfig - 328 - DEBUG - GPS Wait Period: 10 2021-03-28 16:07:16,998 - DraginoConfig - 329 - DEBUG - Spreading factor: 7 2021-03-28 16:07:16,999 - DraginoConfig - 330 - DEBUG - Max Power: 0F 2021-03-28 16:07:17,000 - DraginoConfig - 331 - DEBUG - Output Power: 0E 2021-03-28 16:07:17,001 - DraginoConfig - 332 - DEBUG - Sync Word: 34 2021-03-28 16:07:17,002 - DraginoConfig - 333 - DEBUG - RX CRC: True 2021-03-28 16:07:17,003 - DraginoConfig - 334 - DEBUG - Frame Count Filename: .lora_fcount 2021-03-28 16:07:17,004 - DraginoConfig - 335 - DEBUG - Auth mode: OTAA 2021-03-28 16:07:17,006 - DraginoConfig - 349 - DEBUG - Device EUI: 00 60 59 E0 EF F9 49 A3 2021-03-28 16:07:17,008 - DraginoConfig - 352 - DEBUG - App EUI: 70 B3 D5 7E D0 03 FE 74 2021-03-28 16:07:17,009 - DraginoConfig - 355 - DEBUG - App Key: 0A 50 50 01 40 07 06 00 E3 0D E0 F2 09 D0 4D 04 2021-03-28 16:07:17,016 - DraginoConfig - 365 - DEBUG - Joined False 2021-03-28 16:07:17,018 - Dragino - 171 - DEBUG - Performing OTAA Join 2021-03-28 16:07:17,019 - Dragino - 175 - INFO - App key = [10, 80, 80, 1, 64, 7, 6, 0, 227, 13, 224, 242, 9, 208, 77, 4] 2021-03-28 16:07:17,020 - Dragino - 176 - INFO - App eui = [112, 179, 213, 126, 208, 3, 254, 116] 2021-03-28 16:07:17,021 - Dragino - 177 - INFO - Dev eui = [0, 96, 89, 224, 239, 249, 73, 163] 2021-03-28 16:07:17,023 - Dragino - 102 - INFO - Frequency = 916.8 Mode <- STDBY Mode <- TX Waiting 2021-03-28 16:07:17,092 - Dragino - 148 - DEBUG - TX Complete Mode <- STDBY Mode <- RXCONT Waiting Waiting Waiting Waiting Waiting Waiting Similar reported issue - https://github.com/jeroennijhof/LoRaWAN/issues/5

When I have looked at the console of the v2 TTN - I see that the activation request was seen.

{ "time": "2021-03-28T07:57:37.449676372Z", "frequency": 917.2, "modulation": "LORA", "data_rate": "SF7BW125", "coding_rate": "4/5", "gateways": [ { "gtw_id": "eui-00800000a0003e55", "timestamp": 3476306715, "time": "2021-03-28T07:57:37.39437Z", "channel": 2, "rssi": -110, "snr": -3.5 }, { "gtw_id": "eui-60c5a8fffe76f86a", "timestamp": 1912733067, "time": "2021-03-28T07:57:37.394368Z", "channel": 2, "rssi": -120, "snr": -7.3 } ] }

For fun I also added to the v3 and the following was a little more detailed, but still im at a loss as to the problem..

`Last seen7 minutes ago arrow_upwardn/a arrow_downwardn/a Created 7 minutes ago

16:07:17 Drop join-request MIC mismatch v3_OTAA_attempt_metadata

16:07:17 Join-request to cluster-local Join Server failed MIC mismatch

16:07:17 Send join-request to cluster-local Join Server JoinEUI 70B3D57ED003FE74 DevEUI 006059E0EFF949A3 Selected MAC version 1.0.2

16:07:17 Receive join-request JoinEUI 70B3D57ED003FE74 DevEUI 006059E0EFF949A3 Bandwidth 125000 SNR -6.2 RSSI -110 Raw payload 0074FE03D07ED5B370A349F9EFE0596000F0EDE55EB292 Event details Close event info Eve` v2_OTAA_attempt_metadata

BNNorman commented 3 years ago

I use the code, from 9 months ago, on a project and it worked fine in the UK (815Mhz).

The MIC Mismatch you get from using V3 suggests to me that V3, somehow, calculates the MIC differently so you should stick with V2 for now. Look at dragino\LoraWAN\JoinAcceptPayload.py and JoinRequestPayload.py - you will find an example of the compute_mic() method.

However, 'waiting' forever suggests the join-accept response has been missed or not sent. What does your logfile have in it? If you look in dragino.py there's an on_rx_done() method on line 118 which logs the message "Received message". If the message is a JOIN_ACCEPT it logs 'Join resp' to the log file then validates the MIC etc. This should give you some idea what is/isn't happening.

pjb304 commented 3 years ago

I'm afraid I'm not sure what's going on here - I suspect there's something else that needs changing to adapt it to the different region. As it works fine on both v2 & v3 in the Uk

Dukat-Gul commented 3 years ago

Thanks @pjb304 & @BNNorman . Not sure how to further turn on logging - have experimented with editing dragino.py and adjusting the

D = Dragino("dragino.ini", logging_level=logging.INFO)

changing it to DEBUG - but nothing of note was showing on stdout or elsewhere.

Also tried - DEFAULT_LOG_LEVEL = logging.DEBUG

Anyhow - I made a small change in the v3 console and updated my settings to be 1.0.1 Lorawan and I got a few extra steps, no sign of the MIC errors now. v3_OTAA_slightprogress_metadata_rx-freq_9233

I have a feeling the issue is that I am not receiving anything. When I tweaked the dragino/FrequncyPlan.py to align to the AU915 (subband 2) frequencies for TTN in Australia, I didnt see any place to adjust the down (RX) frequencies.

As you can see from this - https://github.com/Fluent-networks/floranet/blob/f025825fa234194646d9831bd52fa3a3a55c0666/floranet/lora/bands.py

AU915 TX freq are 200khz stepped - Channel 8 (916.8) through Ch15 (917.5) plus a 500khz Ch65 (917.5) but unlike the EU868 the downlink (RX) frequencies are (also for US915) not the same as the uplink (TX). They are 8 channels numbered 0 to 7 utilizing 500 kHz BW starting at 923.3 MHz and incrementing by 600 kHz to 927.5 MHz.

OTAA_AU915_tx_rx-freq

I have tried a few quick and dirty edits but all without any progress. For example I edited a few places where I saw 868

dragino/SX127x/LoRa.py: def init(self, verbose=True, do_calibration=True, calibration_freq=923): dragino/SX127x/LoRa.py: :param calibration_freq: call rx_chain_calibration with this parameter. Default is 923 dragino/SX127x/LoRa.py: def rx_chain_calibration(self, freq=923.3):

Any suggestions as to next (easy) steps I can try? Or will it require a significant code edit to have a TX and RX frequency alignment for this region?

pjb304 commented 3 years ago

Yes, the code does currently have the assumption that uplink and downlink happen on the same frequency.

I think the way to change that would be to use similar calls to those in _choose_freq in the on_tx_done to change onto the correct frequency before entering RX mode.

As for the calibration I'm afraid I'm not sure how best to change that to 923MHz.

Dukat-Gul commented 3 years ago

Yeah.... cool Thanks.

I tried (i think) something along the lines of your suggestion prior to you suggesting it. As I looked at some of the other other forks - specifically the https://github.com/ryanzav/LoRaWAN/blob/master/otaa_helium.py and he did it for the US downlink (which is the same as mine in AU). I put into FrequncyPlan CH0 as the 923.3 then edited dragino.py:

def on_tx_done(self):
    """
        Callback on TX complete is signaled using I/O
    """
    self.clear_irq_flags(TxDone=1)
    self.set_mode(MODE.STDBY)
    self.set_dio_mapping([0, 0, 0, 0, 0, 0])
    self.set_invert_iq(1)
    self.reset_ptr_rx()
    self.set_freq(LORA_FREQS.CH0)
    self.set_spreading_factor(7)
    self.set_bw(9)
    self.set_rx_crc(False)
    self.set_mode(MODE.RXCONT)

didnt seem to hit the mark, or make any real difference. but its late here.... time to goto bed and perhaps tomorrow have another look

justin-cotarla commented 3 years ago

According to the specs, in the US902-928 channels:

RX1 Channel Number = Transmit Channel Number modulo 8

In other words, there are two sets of frequencies in the US frequency plan, one for uplink and one for downlink. If you use the first uplink channel, you will get a response on the first downlink channel.

I modified the code slightly to this effect:

FrequencyPlan.py

UPLINK_FREQS = (903.9, 904.1, 904.3, 904.5, 904.7, 904.9, 905.1, 905.3)
DOWNLINK_FREQS = (923.3, 923.9, 924.5, 925.1, 925.7, 926.3, 926.9, 927.5)

Dragino.py

def _choose_freq(self, uplink=False):
    if self.freq_index is None:
        self.freq_index = randrange(len(UPLINK_FREQS)) #Pick a random frequency

    if uplink:
        available = UPLINK_FREQS
    else:
        available = DOWNLINK_FREQS

    freq = available[self.freq_index]
    self.set_mode(MODE.SLEEP)
    self.set_freq(freq)
    self.logger.info("Frequency = %s", freq)

Then, every time there would be an uplink (such as when registering), I call self._choose_freq(uplink=True), and whenever I need to listen to a response, such as on_tx_done, I call self._choose_freq(uplink=False).