Monitoring message delay and missing down messages (ACK)

gbr · August 8, 2022, 3:19pm

How do you monitor how long it takes to process a message for a single device or whether ACK down messages are missing? We use the ConfirmedUplink-feature and if the delay from the sensor to the network server reaches the rx1_delay setting (1s), no ACK-down message is sent out. It would be nice if there were some numbers in prometheus, e.g. a 99th percentile of receive window times or a record of slow devices. The goal would be to see if the distance to rx1_delay is too small and whether there is a risk, if the network delay increases in the future, that ACKs cannot be sent.
a possible small change would be if there is some logging that network delay was too high and ACK message is not sent out properly. Currently we only see missing ACK messages in the live dashboard (errors does not occur, we only can see, that after a confirmed uplink is received, no downlink is added in the same second, so automatic monitoring is currently not possible).

brocaar · August 9, 2022, 9:28am

I believe these kind of errors are already exposed? Have you checked the error event type? (Event types - ChirpStack open-source LoRaWAN<sup>®</sup> Network Server)

gbr · August 9, 2022, 10:37am

Thanks! We will check the events, currently we ignore all non-up events.
Should these errors be part of the statistical data, like the gateway transmission chart or in the prometheus data from the networkserver?

gbr · August 9, 2022, 2:15pm

We have changed the topic subscription but currently we only receive up-events (e.g. chirpstack.34.device.[deveui].event.up). The gateway bridge is deployed to the cloud. If we add delay (>750ms) to the udp packets from LoRa gateway to the bridge, no error occur and no ACK message is sent out as reply.

gbr · August 9, 2022, 7:59pm

The code part is probably here: https://github.com/brocaar/chirpstack-network-server/blob/476afac3ec0d911443da1c60b21847312ba1ad15/internal/downlink/data/data.go#L800
It is possible that timeout handling is not catched and ACK message is skipped too? How can we debug this, should we add debug messages and build a new package by our self? Are there any other simpler approaches?
EDIT: in addition I saw that all amqp/integration messages are logged too. Our log backup contains only some rare errors, which can also be seen in the gateway transmission chart
EDIT2: because we have many sensors with missing ACK messages, the log must be full of errors

gbr · August 11, 2022, 3:43pm

More results:
it seems that the code block from above is never reached for our class a sensors.
the gateway bridge (in the cloud) receives the downlink, but will not send the downlink message back to the redis stream. From network server perspective probably all is working fine.
we are now analyzing the bridge code to see in which situations the message is not added to the redis device message stream. Probably an error handling for this case is missing because the bridge should send such errors back to the network server.

gbr · August 11, 2022, 9:04pm

Sorry for spamming
We missed that there are ack mqtt messages. On networkserver side those ack-messages are only printed out as a successful message “backend/gateway: downlink tx acknowledgement received”

github.com

brocaar/chirpstack-network-server/blob/69ba076612497423362937db898b424544174205/internal/backend/gateway/mqtt/backend.go#L327

      
        
            		if err != nil {
            			log.WithError(err).WithFields(log.Fields{
            				"key":         key,
            				"downlink_id": downlinkID,
            			}).Error("gateway/mqtt: acquire lock error")
            		}
            
            
		return
            	}
            
            
	log.WithFields(log.Fields{
            		"gateway_id":  gatewayID,
            		"downlink_id": downlinkID,
            	}).Info("backend/gateway: downlink tx acknowledgement received")
            	b.downlinkTXAckChan <- ack
            }
            
            
func (b *Backend) onConnected(c paho.Client) {
            	log.Info("backend/gateway: connected to mqtt server")
            
            
	mqttConnectCounter().Inc()

We have added debug logging to this place and if downlink ack message is missing, the ack message contains “TOO_EARLY” in the error field. But it seems that this error will not be processed further.

gbr · August 12, 2022, 5:54am

we tracked it down to

github.com

brocaar/chirpstack-network-server/blob/69ba076612497423362937db898b424544174205/internal/downlink/ack/ack.go#L183

      
        
            				return err
            			}
            		}
            
            
		return nil
            	}
            }
            
            
func forApplicationPayload(funcs ...func(*ackContext) error) func(*ackContext) error {
            	return func(ctx *ackContext) error {
            		if len(ctx.DownlinkFrame.DevEui) == 0 || ctx.MACPayload == nil || ctx.MACPayload.FPort == nil || *ctx.MACPayload.FPort == 0 {
            			return nil
            		}
            
            
		for _, f := range funcs {
            			if err := f(ctx); err != nil {
            				return err
            			}
            		}
            
            
		return nil

FPort is always nil in our case so all messages will be ignored. Why is the FPort relevant for sending the error to the AS?

gbr · August 16, 2022, 10:03am

@brocaar should we raise a bug for this topic? probably 1 or 2 different topics.
fport is always null also if downlink ACK message is sent out successfully. I found other fport=null examples from other users in the forum (e.g. Device sends ConfirmedUp but no UnconfirmedDown is initiated)
So fport check here and at https://github.com/brocaar/chirpstack-network-server/blob/69ba076612497423362937db898b424544174205/internal/downlink/ack/ack.go#L499 are wrong and/or fport must be set elsewhere also on ACK messages

brocaar · August 16, 2022, 1:38pm

This code block checks if the downlink was an application payload (thus fPort > 0), which is not the case. In your case it is a mac-layer only downlink.

To summarize the issue, I think this describes it:

In case a mac-layer downlink (for example an ACK of a confirmed uplink) can not be scheduled by the gateway (e.g. too late / early), these errors are not included in the statistics and logs.

Is that correct?

gbr · August 16, 2022, 1:47pm

Thanks for clarifying! yes, mac layer downlink errors are missing (stats, logs, integration events)

gbr · August 26, 2022, 9:13pm

I tried to fix the problem: https://github.com/brocaar/chirpstack-network-server/pull/596