Occasionally drops packets

sslupsky · August 6, 2019, 1:34pm

I have noticed that occasionally when I send an unconfirmed packet (modem.endpacket(false)), a packet is not received when observing at the data over a period of an hour or more. At first, I though that perhaps this because the packet was sent as an unconfirmed message and the message was not received. However, when I dig a little deeper, what I am observing is that the packet is not transmitted. That is to say, endpacket() returns immediately and the LoRa firmware does not send the packet.

I send a packet every 60 to 120 seconds to a private gateway. The packets are typically small, less than 20 bytes.

Does anyone know what the reasons are that the LoRa stack would refuse to send a packet? I know that this can happen if the packet is too large for the dr but the data rate is 3 so that should not be a problem. The rssi is very good so the radio link itself is robust.

I am wondering if anyone else has noticed this?

Steve

sslupsky · August 6, 2019, 1:49pm

The rate of the failed packet transmissions appears to be correlated to the number of packets transmitted. When the sending period is 60 seconds, most probably one packet per hour is not transmitted. Occasionally there will be two packets not transmitted, rarely all the packets are sent.

I have another device where the sending period is 120 seconds and most probably one packet is missing every two hours.

mjunior-fitec · August 6, 2019, 5:12pm

Hello Steve, I have experimented some problems related to not sent packets.
You told it happens for UNconfirmed packets, have you tested just changing it to confirmed?
Do you believe it won't happen for confirmed transmitions?

In my case, I have put a sending interval of 4 minutes and now I rarely have a not received packet. I can't tell for sure if it was sent or not.

As I already told you before I had some serious issues with the Join procedure. Sometimes, the joinOTAA function just returns after the timeout (60 sec) and after that if one calls the joinOTAA again it just does NOTHING! No Join Request nor other packets sent and no error message returned. Really, absolutelly nothing happens, and the only workaround I found was to restart the modem.

So, it's actually likely to exist some undocumented behaviour that may cause a packet to not be sent.
I have a spectrum analyzer here in my lab, and I would be more than happy to help you find out more about this error.

Regards,
Marcio Jr.

MITEL · August 7, 2019, 11:12am

At which SF?

sslupsky · August 12, 2019, 2:07pm

I recall the SF is 7. At the moment, the device is about 10m from the gateway and rssi is about -40 dB

endPacket() is returning an error so the packet is not being sent across the air. endPacket() returns the return value from modemSend(). modemSend() returns -1 for all errors.

 int modemSend(const void* buff, size_t len, bool confirmed) {

   size_t max_len = modemGetMaxSize();
   if (len > max_len) {
       return -1;
   }

   if (confirmed) {
       sendAT(GF("+CTX "), len);
   } else {
       sendAT(GF("+UTX "), len);
   }

   stream.write((uint8_t*)buff, len);

   if (waitResponse() != 1) {
     return -1;
   }
   if (confirmed) {
       if (waitResponse(10000L, "+ACK") != 1) {
           return -1;
       }
   }
   return len;
 }

sslupsky · August 14, 2019, 4:41pm

I set up another test using confirmed packets only. I changed the period between packets to 5 seconds to increase the probability of a failed send. When I do this, I can usually get the mkrwan to fail a transmit in 10 - 15 minutes. Sometimes is takes more than an hour. Other times is happens in a minute or two.

I changed modemSend() so that it returns -2 if there is no response from the modem and -3 if there is no ack.

The error returned from modemSend() appears to be -3 which tells me that the ACK is not received. This seems odd. When I look at the raw packets on the server side, every confirmed data up is followed by an unconfirmed data down ACK. What I think may be happening is that the packet isn't actually transmitted. So, there is no ACK. But, that should cause an error response from the modem (-2).

Generally, if I wait 30 seconds and send again, the packet goes through. But not all the time. Sometimes I need to retry two or even three times.

Does the modem queue an unconfirmed packet and automatically resend it?

sslupsky · August 14, 2019, 6:18pm

This may have something to do with ADR and Status packets. I noticed today that on two occasions when the TX failed, there was an ADR packet.

sslupsky · August 15, 2019, 3:38pm

I slowed down the confirmed packet rate to once every 10 minutes and made the following observations.

Referring to the six packets in the json (see the next message in the thread), a confirmed packet is transmitted at 7:47:33. The server responds with an ACK at 7:47:48. At 7:48.15 the module transmits an unconfirmed packet. This packet appears to be empty (no payload, just metadata). The server sends an unconfirmed packet at 7:48:15 (some sort of response?) which is NOT an ACK (but has the ADR flag set). At 7:57:33 a confirmed packet is transmitted and at 7:57:34, the server sends an ACK. Note times are relative to my local time zone.

My analysis indicates that the module transmits a packet at 7:47:33 and the server responds with an ACK at 7:47:34. The log output of my application indicates that the ACK is not received by the waitResponse() method before it times out (10 seconds) and indicates this error. Then my application adds some additional data to the packet to indicate the retry and sends a confirmed packet 31 seconds later. The server log shows an unconfirmed packet with no payload is received at 7:48:15 which is the same time that I sent the confirmed packet with a modified payload. At 7:57:33 I transmit the next confirmed packet, it is ACK'ed by the server and the application receives the ACK.

So, a couple odd things here: The "retry" does not actually send the updated payload (or any payload for that matter). And the "response" is not an ACK according to the frame log but the application log shows the retry is confirmed. Clearly, the LoRa stack is doing something here but I do not fully understand what is going on. Moreover, I do not understand why the ACk for the first packet in this sequence is not received by the waitResponse() method.

Can anyone explain what this mystery packet exchange is?

modem.endpacket() fails

opened 03:08PM - 13 Nov 18 UTC

sslupsky

question

This is probably more a question than a problem. I have on several occasion…s noticed that when I attempt to sent a packet, I receive an error with the call to modem.endpacket(). I prepare and send the packet as follows: ` modem.beginPacket(); modem.write( (uint8_t *) &sensorPayload, sizeof(sensorPayload)); err = modem.endPacket(false); if (err > 0) { ... ` I have noticed that sometimes endPacket() returns an error. Often the next time (about 10 seconds later) the loop tries to send a packet it goes through. On several occasions though, I have noticed that I get into a loop where the endPacket() always returns an error and the packet is never sent. I have noticed this behaviour occasionally when the device has not joined the network. At other times, it appears that the device joined the network but still will not send a packet. I am struggling to understand why that would happen. Would is be appropriate that beginPacket() be preceded first by a check to connected() to confirm that the device is still connected? Can the module "loose" its' join status from time to time?

github.com/arduino-libraries/MKRWAN

waitResponse() check ambiguity

opened 06:34PM - 14 Aug 19 UTC

sslupsky

I think I have found an situation where there is ambiguity in waitResponse(). T…his method is used to parse the AT response from the modem. It defaults to parse for r1=LORA_OK ("+OK") or r2=LORA_ERROR ("+ERR"). There appears to be provision to add additional checks (r3, r4, r5). The following line is typical of the parsing method used: https://github.com/arduino-libraries/MKRWAN/blob/2fa519d6bd8aceb359e3c3fcff91f0bd4b4324be/src/MKRWAN.h#L855 A problem arises because the modem can return seven types of error message as shown here: https://github.com/arduino/mkrwan1300-fw/blob/63787fe5ed8bd07119caba20d2065a26004b2261/Projects/Multi/Applications/LoRa/AT_Slave/src/command.c#L83-L93 Because the parsing method uses the .endswith() string method, and the string is checked with every new character, any error message will match the first "+ERR" and therefore, you cannot add additional error codes when you call waitResponse(). I think this needs to be fixed. It seems to me that the string comparison should be done only after the entire response is received from the modem?

sslupsky · August 15, 2019, 3:46pm

Server LoRaWAN Frame Log @ 7:47:33

    {
        "downlinkMetaData": {
            "txInfo": {
                "gatewayId": "c0ee40ffff293f83",
                "immediately": false,
                "timeSinceGpsEpoch": null,
                "timestamp": 3054577635,
                "frequency": 925100000,
                "power": 20,
                "modulation": "LORA",
                "loraModulationInfo": {
                    "bandwidth": 500,
                    "spreadingFactor": 7,
                    "codeRate": "4/5",
                    "polarizationInversion": true
                },
                "board": 0,
                "antenna": 0
            }
        },
        "phyPayload": {
            "mhdr": {
                "mType": "UnconfirmedDataDown",
                "major": "LoRaWANR1"
            },
            "macPayload": {
                "fhdr": {
                    "devAddr": "0682dd3c",
                    "fCtrl": {
                        "adr": true,
                        "adrAckReq": false,
                        "ack": true,
                        "fPending": false,
                        "classB": false
                    },
                    "fCnt": 90,
                    "fOpts": null
                },
                "fPort": null,
                "frmPayload": null
            },
            "mic": "0e7168cd"
        }
    },
    {
        "uplinkMetaData": {
            "rxInfo": [
                {
                    "gatewayId": "c0ee40ffff293f83",
                    "time": null,
                    "timeSinceGpsEpoch": null,
                    "timestamp": 3053577635,
                    "rssi": -42,
                    "loraSnr": 10.2,
                    "channel": 3,
                    "rfChain": 0,
                    "board": 0,
                    "antenna": 0,
                    "location": {
                        "latitude": 53.48991001460846,
                        "longitude": -113.47415205820373,
                        "altitude": 0,
                        "source": "UNKNOWN",
                        "accuracy": 0
                    },
                    "fineTimestampType": "NONE"
                }
            ],
            "txInfo": {
                "frequency": 902900000,
                "modulation": "LORA",
                "loRaModulationInfo": {
                    "bandwidth": 125,
                    "spreadingFactor": 7,
                    "codeRate": "4/5",
                    "polarizationInversion": false
                }
            }
        },
        "phyPayload": {
            "mhdr": {
                "mType": "ConfirmedDataUp",
                "major": "LoRaWANR1"
            },
            "macPayload": {
                "fhdr": {
                    "devAddr": "0682dd3c",
                    "fCtrl": {
                        "adr": true,
                        "adrAckReq": false,
                        "ack": false,
                        "fPending": false,
                        "classB": false
                    },
                    "fCnt": 90,
                    "fOpts": null
                },
                "fPort": 10,
                "frmPayload": [
                    {
                        "bytes": "5UlztTzr"
                    }
                ]
            },
            "mic": "cb0e4120"
        }
    },

sslupsky · August 15, 2019, 3:52pm

Server LoRaWAN Frame Log @ 7:48:15

    {
        "downlinkMetaData": {
            "txInfo": {
                "gatewayId": "c0ee40ffff293f83",
                "immediately": false,
                "timeSinceGpsEpoch": null,
                "timestamp": 3095819316,
                "frequency": 923900000,
                "power": 20,
                "modulation": "LORA",
                "loraModulationInfo": {
                    "bandwidth": 500,
                    "spreadingFactor": 10,
                    "codeRate": "4/5",
                    "polarizationInversion": true
                },
                "board": 0,
                "antenna": 0
            }
        },
        "phyPayload": {
            "mhdr": {
                "mType": "UnconfirmedDataDown",
                "major": "LoRaWANR1"
            },
            "macPayload": {
                "fhdr": {
                    "devAddr": "0682dd3c",
                    "fCtrl": {
                        "adr": true,
                        "adrAckReq": false,
                        "ack": false,
                        "fPending": false,
                        "classB": false
                    },
                    "fCnt": 91,
                    "fOpts": [
                        {
                            "cid": "LinkADRReq",
                            "payload": {
                                "dataRate": 3,
                                "txPower": 2,
                                "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": "8c9e638c"
        }
    },
    {
        "uplinkMetaData": {
            "rxInfo": [
                {
                    "gatewayId": "c0ee40ffff293f83",
                    "time": null,
                    "timeSinceGpsEpoch": null,
                    "timestamp": 3094819316,
                    "rssi": -41,
                    "loraSnr": 11.8,
                    "channel": 1,
                    "rfChain": 0,
                    "board": 0,
                    "antenna": 0,
                    "location": {
                        "latitude": 53.48991001460846,
                        "longitude": -113.47415205820373,
                        "altitude": 0,
                        "source": "UNKNOWN",
                        "accuracy": 0
                    },
                    "fineTimestampType": "NONE"
                }
            ],
            "txInfo": {
                "frequency": 902500000,
                "modulation": "LORA",
                "loRaModulationInfo": {
                    "bandwidth": 125,
                    "spreadingFactor": 10,
                    "codeRate": "4/5",
                    "polarizationInversion": false
                }
            }
        },
        "phyPayload": {
            "mhdr": {
                "mType": "UnconfirmedDataUp",
                "major": "LoRaWANR1"
            },
            "macPayload": {
                "fhdr": {
                    "devAddr": "0682dd3c",
                    "fCtrl": {
                        "adr": true,
                        "adrAckReq": false,
                        "ack": false,
                        "fPending": false,
                        "classB": false
                    },
                    "fCnt": 91,
                    "fOpts": null
                },
                "fPort": null,
                "frmPayload": null
            },
            "mic": "a91f2190"
        }
    },

sslupsky · August 15, 2019, 4:07pm

Server LoRaWAN Frame Log @ 7:57:33

    {
        "downlinkMetaData": {
            "txInfo": {
                "gatewayId": "c0ee40ffff293f83",
                "immediately": false,
                "timeSinceGpsEpoch": null,
                "timestamp": 3654576483,
                "frequency": 925700000,
                "power": 20,
                "modulation": "LORA",
                "loraModulationInfo": {
                    "bandwidth": 500,
                    "spreadingFactor": 7,
                    "codeRate": "4/5",
                    "polarizationInversion": true
                },
                "board": 0,
                "antenna": 0
            }
        },
        "phyPayload": {
            "mhdr": {
                "mType": "UnconfirmedDataDown",
                "major": "LoRaWANR1"
            },
            "macPayload": {
                "fhdr": {
                    "devAddr": "0682dd3c",
                    "fCtrl": {
                        "adr": true,
                        "adrAckReq": false,
                        "ack": true,
                        "fPending": false,
                        "classB": false
                    },
                    "fCnt": 92,
                    "fOpts": [
                        {
                            "cid": "LinkADRReq",
                            "payload": {
                                "dataRate": 3,
                                "txPower": 3,
                                "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": "284a77df"
        }
    },
    {
        "uplinkMetaData": {
            "rxInfo": [
                {
                    "gatewayId": "c0ee40ffff293f83",
                    "time": null,
                    "timeSinceGpsEpoch": null,
                    "timestamp": 3653576483,
                    "rssi": -37,
                    "loraSnr": 8.2,
                    "channel": 4,
                    "rfChain": 1,
                    "board": 0,
                    "antenna": 0,
                    "location": {
                        "latitude": 53.48991001460846,
                        "longitude": -113.47415205820373,
                        "altitude": 0,
                        "source": "UNKNOWN",
                        "accuracy": 0
                    },
                    "fineTimestampType": "NONE"
                }
            ],
            "txInfo": {
                "frequency": 903100000,
                "modulation": "LORA",
                "loRaModulationInfo": {
                    "bandwidth": 125,
                    "spreadingFactor": 7,
                    "codeRate": "4/5",
                    "polarizationInversion": false
                }
            }
        },
        "phyPayload": {
            "mhdr": {
                "mType": "ConfirmedDataUp",
                "major": "LoRaWANR1"
            },
            "macPayload": {
                "fhdr": {
                    "devAddr": "0682dd3c",
                    "fCtrl": {
                        "adr": true,
                        "adrAckReq": false,
                        "ack": false,
                        "fPending": false,
                        "classB": false
                    },
                    "fCnt": 92,
                    "fOpts": [
                        {
                            "cid": "LinkADRReq",
                            "payload": {
                                "channelMaskAck": true,
                                "dataRateAck": true,
                                "powerAck": true
                            }
                        }
                    ]
                },
                "fPort": 10,
                "frmPayload": [
                    {
                        "bytes": "AjiaH+iM"
                    }
                ]
            },
            "mic": "3a6224d6"
        }
    },

sslupsky · August 15, 2019, 4:12pm

Application log output

[  53999760] level=V msg="packet size: 6 bytes" data="0x63, 0x0, 0x0, 0x62, 0x0, 0x0"
[  54009785] level=E msg="LoRaWAN: Error sending confirmed LPP packet, error=-9, size=6"
[  54040754] level=V msg="packet size: 15 bytes" data="0x63, 0x0, 0x0, 0x62, 0x0, 0x0, 0x61, 0x0, 0xF7, 0x63, 0x0, 0x1, 0x60, 0x0, 0x6"
[  54042158] level=V msg="LoRaWAN: Confirmed LPP packet sent 15 bytes"
[  54118793] level=V msg="Heartbeat Tick"
[  54238769] level=V msg="Heartbeat Tick"
[  54358743] level=V msg="Heartbeat Tick"
[  54478719] level=V msg="Heartbeat Tick"
[  54598694] level=V msg="Heartbeat Tick"
[  54599644] level=V msg="packet size: 6 bytes" data="0x63, 0x0, 0x1, 0x62, 0x0, 0x0"
[  54600741] level=V msg="LoRaWAN: Confirmed LPP packet sent 6 bytes"

sslupsky · August 15, 2019, 4:46pm

I think I have figured out what is going on here. If the module doesn't receive the ACK, then the LoRaWAN stack will retry according to the mcpsReq.Req.Confirmed.NbTrials. In the case of the AT_Slave firmware, this is set to 8. So, the mystery packet exchange must be the stack asking the server if the packet is confirmed and the server responding to the request.

Thus, it appears to me that in order to trigger the retry, you need to do another send.

sslupsky · August 15, 2019, 8:45pm

I think there is a problem with the confirmed packet ACK's. From what I can see so far, the module AT_Slave firmware sends the "+ACK" string to the UART any time it receives something from a downlink. My expectation was that this message is only sent when the module receives a LoRaWAN ACK. Here is the code:

                    if( ( RadioEvents != NULL ) && ( RadioEvents->RxDone != NULL ) )
                    {
                        RadioEvents->RxDone( RxTxBuffer, SX1276.Settings.LoRaPacketHandler.Size, SX1276.Settings.LoRaPacketHandler.RssiValue, SX1276.Settings.LoRaPacketHandler.SnrValue );
                        PRINTF( "+ACK\r" );
                        //PRINTF("+RECV=");
                    }

I am not certain yet I understand fully all of the implications of this but I think this sheds some light on the issue reported here. Moreover, I think I understand now why sending another packet generates a +ACK since it is not really a LoRaWAN ACK that causes it. Recall from the earlier discussion that waitResponse() receives the +ACK string from the module even when the downlink packet's ACK bit is set to false. This mistakenly causes you to think that the packet was received by the server when in fact that conclusion cannot be made.

I will post this to github.

system · May 7, 2021, 11:53am