chirpstack / chirpstack-mqtt-forwarder

ChirpStack MQTT Forwarder is a forwarder which can be installed on the gateway to forward LoRa data over MQTT.
MIT License
21 stars 12 forks source link

Unreliable delivery of command exec event for commands whose duration exceeds keep_alive_interval setting #57

Closed nicolas-juteau closed 1 month ago

nicolas-juteau commented 1 month ago

Steps to reproduce:

  1. Use a keep_alive_interval setting of 30 seconds (or leave it default)
  2. Configure a command that will execute the following script (simulates a "long" command execution duration):
#!/bin/bash

date_start=$(date)
logger -s -t long-cmd "*** Command started at ${date_start}"
echo "Executing something take takes some time..."
# Sleep at least twice the keep_alive_interval
sleep 60
echo "Execution done"
date_end=$(date)
logger -s -t long-cmd "*** Command ended at ${date_end}"
exit 0
  1. Subscribe to the event topic to grab the GatewayCommandExecResponse
  2. Execute the command and inspect system logs. Notice the MQTT error.
2024-07-05T11:15:01.194451-04:00 mtcdt chirpstack-mqtt-forwarder[3475]: Received message, topic: us915_0/gateway/<EUI>/command/exec, qos: AtMostOnce
2024-07-05T11:15:01.196462-04:00 mtcdt chirpstack-mqtt-forwarder[3475]: Received gateway command exec command, exec_id: 7, topic: us915_0/gateway/<EUI>/command/exec
2024-07-05T11:15:01.198534-04:00 mtcdt chirpstack-mqtt-forwarder[3475]: Executing command, command: long_cmd, executable: long_cmd.sh
2024-07-05T11:15:01.329021-04:00 mtcdt long-cmd: *** Command started at Fri Jul  5 11:15:01 EDT 2024
2024-07-05T11:16:01.459910-04:00 mtcdt long-cmd: *** Command ended at Fri Jul  5 11:16:01 EDT 2024
2024-07-05T11:16:01.470366-04:00 mtcdt chirpstack-mqtt-forwarder[3475]: Sending gateway command exec event, exec_id: 7, topic: us915_0/gateway/<EUI>/event/exec
2024-07-05T11:16:01.516236-04:00 mtcdt chirpstack-mqtt-forwarder[3475]: MQTT error, error: Mqtt state: Io error: Custom { kind: ConnectionAborted, error: "connection closed by peer" }
2024-07-05T11:16:02.756458-04:00 mtcdt chirpstack-mqtt-forwarder[3475]: Subscribing to command topic, topic: us915_0/gateway/<EUI>/command/+
2024-07-05T11:16:02.758077-04:00 mtcdt chirpstack-mqtt-forwarder[3475]: Sending conn state, topic: us915_0/gateway/<EUI>/state/conn
  1. Sometimes, the GatewayCommandExecResponse will be correctly delivered, sometimes not (very random). This only occurs when the command execution duration exceeds the configured keep_alive_interval setting.
brocaar commented 1 month ago

Thanks for reporting, the above commit fixes this issue.