if NbTrans > 1, retransmitted unconfirmed uplinks are treated as errors

[TomSievers]

This issue is somewhat related to #502.

• The issue is present in the latest release.
• I have searched the issues of this repository and believe that this is not a duplicate.

What happened?

When viewing device data I suddenly saw that multiple errors were present. All of which were UPLINK_FCNT_RETRANSMISSION. After some investigation I found out that this happens when via a LinkADRReq the NbTrans gets set to a value greater than 1.

What did you expect?

I expected no uplink frame-count retransmission error events to be generated when inside the bounds of the NbTrans when a device is configured by the Network Server to retransmit uplinks a certain number of times.

Steps to reproduce this issue

Environment:

• Raspberry Pi 3 b+ running alpine-3.15.0 aarch64
• Docker version 20.10.11
• Latest Docker images for AS, NS and GB from dockerhub
• The follwing ADR plugin cross compiled for aarch64 with Go version 1.13.8

package main

import (
	"github.com/hashicorp/go-plugin"
	log "github.com/sirupsen/logrus"

	"github.com/brocaar/chirpstack-network-server/v3/adr"
)

// Type Handler is the ADR handler.
type Handler struct{}

// ID must return the plugin identifier.
func (h *Handler) ID() (string, error) {
	return "test-nb-trans", nil
}

// Name must return a human-readable name.
func (h *Handler) Name() (string, error) {
	return "Test NBTrans ADR plugin", nil
}

// Handle handles the ADR and returns the (new) parameters.
func (h *Handler) Handle(req adr.HandleRequest) (adr.HandleResponse, error) {
	resp := adr.HandleResponse{
		DR:           req.DR,
		TxPowerIndex: req.TxPowerIndex,
		NbTrans:      req.NbTrans,
	}

	if !req.ADR {
		return resp, nil
	}

	return adr.HandleResponse{
		DR:           req.DR,
		TxPowerIndex: req.TxPowerIndex,
		NbTrans:      2,
	}, nil
}

func main() {
	handler := &Handler{}

	pluginMap := map[string]plugin.Plugin{
		"handler": &adr.HandlerPlugin{Impl: handler},
	}

	log.Info("Starting ADR plugin")
	plugin.Serve(&plugin.ServeConfig{
		HandshakeConfig: adr.HandshakeConfig,
		Plugins:         pluginMap,
	})
}

• The following NS configuration

[postgresql]
dsn="postgres://chirpstack_ns:chirpstack_ns@postgresql/chirpstack_ns?sslmode=disable"

[redis]
url="redis://redis:6379"

[network_server]
net_id="000000"

[network_server.band]
name="EU868"

[network_server.network_settings]
  adr_plugins=["/etc/chirpstack-network-server/plugins/test-nb-trans"]

  [[network_server.network_settings.extra_channels]]
  frequency=867100000
  min_dr=0
  max_dr=5

  [[network_server.network_settings.extra_channels]]
  frequency=867300000
  min_dr=0
  max_dr=5

  [[network_server.network_settings.extra_channels]]
  frequency=867500000
  min_dr=0
  max_dr=5

  [[network_server.network_settings.extra_channels]]
  frequency=867700000
  min_dr=0
  max_dr=5

  [[network_server.network_settings.extra_channels]]
  frequency=867900000
  min_dr=0
  max_dr=5

[network_server.gateway.backend.mqtt]
server="tcp://mqtt:1883"

[join_server.default]
server="http://chirpstack-application-server:8003"

Steps:

1. Setup AS to communicate with NS inside docker
2. Create neccesary Service profile and add a gateway.
3. Add a device profile for an OTAA device in Class A with ADR algorithm "Test NBTrans ADR plugin"
4. Add a device which supports OTAA and LinkADR MAC commands.
5. Activate device and open LoRaWAN frames in application server
6. Wait until a LinkADR MAC commando is send.
7. Go to device data view and wait for an uplink to be send.
8. With SF7 it takes ~7 seconds until a retransmission occurs, this will be shown as a device error.

Device payloads of retransmissions

Retransmitted frame:
QOq8GgGACQABD/tOR7II8BPz574 at frequency: 868.3

Orignal frame:
QOq8GgGACQABD/tOR7II8BPz574 at frequency: 867.9

Part of log from relevant situation

time="2021-12-02T12:13:41.219094112+01:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=3133303745006100 uplink_id=e43e091e-760d-46ca-9e1e-3b3f0ce8bf40,
time="2021-12-02T12:13:41.425581907+01:00" level=info msg="uplink: frame(s) collected" ctx_id=08032566-7470-49c5-b1f4-71f5417e7642 mtype=UnconfirmedDataUp uplink_ids="[e43e091e-760d-46ca-9e1e-3b3f0ce8bf40]",
time="2021-12-02T12:13:41.440176813+01:00" level=info msg="sent uplink meta-data to network-controller" ctx_id=08032566-7470-49c5-b1f4-71f5417e7642 dev_eui=298e3672dfc61b40,
time="2021-12-02T12:13:41.442741181+01:00" level=info msg="pending mac-command deleted" cid=LinkADRReq ctx_id=08032566-7470-49c5-b1f4-71f5417e7642 dev_eui=298e3672dfc61b40,
time="2021-12-02T12:13:41.442972795+01:00" level=info msg="link_adr request acknowledged" ctx_id=08032566-7470-49c5-b1f4-71f5417e7642 dev_eui=298e3672dfc61b40 dr=5 enabled_channels="[0 1 2 3 4 5 6 7]" nb_trans=2 tx_power_idx=0,
time="2021-12-02T12:13:41.444248103+01:00" level=info msg="device gateway rx-info meta-data saved" ctx_id=08032566-7470-49c5-b1f4-71f5417e7642 dev_eui=298e3672dfc61b40,
time="2021-12-02T12:13:41.449037829+01:00" level=info msg="device-session saved" ctx_id=08032566-7470-49c5-b1f4-71f5417e7642 dev_addr=00de40b0 dev_eui=298e3672dfc61b40,
time="2021-12-02T12:13:41.485083664+01:00" level=info msg="finished client unary call" ctx_id=08032566-7470-49c5-b1f4-71f5417e7642 grpc.code=OK grpc.ctx_id=f04bfd1d-cfac-480d-91f1-777a4a67a47a grpc.duration=40.215927ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc,
time="2021-12-02T12:13:45.922235505+01:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=3133303745006100 uplink_id=de84e9ca-e337-4195-b596-06ea91a711ac,
time="2021-12-02T12:13:46.12879054+01:00" level=info msg="uplink: frame(s) collected" ctx_id=e9cb9d97-e8b0-4b34-a195-26a5ef24de3b mtype=UnconfirmedDataUp uplink_ids="[de84e9ca-e337-4195-b596-06ea91a711ac]",
time="2021-12-02T12:13:46.142001387+01:00" level=info msg="sent uplink meta-data to network-controller" ctx_id=e9cb9d97-e8b0-4b34-a195-26a5ef24de3b dev_eui=70b3d57ed004910f,
time="2021-12-02T12:13:46.142891541+01:00" level=info msg="device gateway rx-info meta-data saved" ctx_id=e9cb9d97-e8b0-4b34-a195-26a5ef24de3b dev_eui=70b3d57ed004910f,
time="2021-12-02T12:13:46.146590385+01:00" level=info msg="device-session saved" ctx_id=e9cb9d97-e8b0-4b34-a195-26a5ef24de3b dev_addr=01e40ad3 dev_eui=70b3d57ed004910f,
time="2021-12-02T12:13:46.188003547+01:00" level=info msg="finished client unary call" ctx_id=e9cb9d97-e8b0-4b34-a195-26a5ef24de3b grpc.code=OK grpc.ctx_id=672510c2-e797-47de-b31b-179da58228bb grpc.duration=44.372269ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc,
time="2021-12-02T12:13:47.226758858+01:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=3133303745006100 uplink_id=66a8271e-224a-4037-be20-8e204b776f06,
time="2021-12-02T12:13:47.433671443+01:00" level=info msg="uplink: frame(s) collected" ctx_id=9447f9fc-f114-41ef-abcb-26f3d6242221 mtype=UnconfirmedDataUp uplink_ids="[66a8271e-224a-4037-be20-8e204b776f06]",
time="2021-12-02T12:13:47.467260306+01:00" level=info msg="finished client unary call" ctx_id=9447f9fc-f114-41ef-abcb-26f3d6242221 grpc.code=OK grpc.ctx_id=a8b50f56-c01f-4836-9da6-0a3e0307229e grpc.duration=26.063884ms grpc.method=HandleError grpc.service=as.ApplicationServerService span.kind=client system=grpc,
time="2021-12-02T12:13:47.467653586+01:00" level=error msg="uplink: processing uplink frame error" ctx_id=9447f9fc-f114-41ef-abcb-26f3d6242221 error="get device-session error: frame-counter did not increment",
time="2021-12-02T12:13:57.821510538+01:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=3133303745006100 uplink_id=2f5889c8-c7d1-4a2c-952e-a2d1eafe778a,
time="2021-12-02T12:13:58.027830885+01:00" level=info msg="uplink: frame(s) collected" ctx_id=f994b709-7cca-4f84-ac88-ab7340580823 mtype=UnconfirmedDataUp uplink_ids="[2f5889c8-c7d1-4a2c-952e-a2d1eafe778a]",
time="2021-12-02T12:13:58.030528325+01:00" level=error msg="uplink: processing uplink frame error" ctx_id=f994b709-7cca-4f84-ac88-ab7340580823 error="get device-session error: object does not exist",
time="2021-12-02T12:14:08.134395992+01:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=3133303745006100 uplink_id=6d03f9b9-c646-494d-be5a-8c33b7d3f59e,

Your Environment

Component	Version
Application Server	v3.17.3
Network Server	v3.15.3
Gateway Bridge	v3.13.1
Hardware	Raspberry Pi 3 b+
OS	alpine-3.15.0 aarch64
Docker	20.10.11
Go	1.13.8

[errolt]

I'm running into this issue too. Does Unconfirmed uplink messages still get ACKed by the gateway? The issue I'm seeing is that my device sends an Unconfirmed Upload message to the server, once every 10 minutes, and all is well.
But if the gateway was off, or the device was out of range for a few messages, then the Unconfirmed uplink message isn't ACKed(because the frame counter has advanced and is higher than the server expects?) Then the device sends 3 Unconfirmed Uplink messages every 10 minutes.

The only way to get the device out of this 3 message re-transmission mode is to reset/join the device.

Can Chirpstack not re-acquire the frame counter if the counter sent by the device is HIGHER than expected?

Edit: looks like Chirpstack DOES resync after an hour or two? Never given it that long to resolve the issue by itself.