Occasionally drops packets

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

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.

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.

At which SF?

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;
 }

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?

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.

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?

See also github issues:

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"
        }
    },

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"
        }
    },

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"
        }
    },

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"

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.

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.