I have 2 x RAK7289V2, 8 channel gateways set up about 5m apart from each other for testing. Frequencies are EU868. I’m using v 4.6.2 of the Gateway Mesh on both, and 4.11.0 for Chirpstack LNS.
Relayed uplinks from my devices (SEEED and Actility trackers) are working fine, but the downlinks are giving a Tx Ack error: TOO_EARLY.
Too early to enqueue packet, downlink_id: 485566528, counter_us: 13410874, current_counter_us: 15015194
Assuming that counter_us is the calculated time to send the downlink, and current_counter_us is the current counter time, the packets are consistently about 1.6 secs too late for the calculated time. Looking at the timestamps on the logs, the relay gateway is receiving the mesh downlink in < 1 sec, which would tend to rule out a network delay issue.
Having said that, I looked at joey’s post with a similar problem using US freqs, and he appeared to resolve it with a combination of increasing the RX1 delay and dropping the mesh data rate to DR4. I’ve tried setting a RX1 delay to 3, and then 5 secs (using device profiles in Chirpstack, and allowing direct uplinks to the Border gateway for the RX1 delay command to propagate), but still get approx 1.6 secs difference between counter and current_counter, which is not what I’d expect if the issue was related to network and relay delays.
Not sure what else to try.
Here are log snippets for a downlink from both gateways:
Border:
Mon Jan 20 15:44:51 2025 user.info chirpstack-mqtt-forwarder[2923]: Received message, topic: eu868/gateway/0016c001f136d8b8/command/down, qos: AtMostOnce
Mon Jan 20 15:44:51 2025 user.info chirpstack-mqtt-forwarder[2923]: Received downlink command, downlink_id: 2978223115, topic: eu868/gateway/0016c001f136d8b8/command/down
Mon Jan 20 15:44:51 2025 user.info chirpstack-mqtt-forwarder[2923]: Sending downlink frame, downlink_id: 2978223115
Mon Jan 20 15:44:51 2025 user.info chirpstack-gateway-mesh[2860]: Downlink command received - [downlink_id: 2978223115 - [freq: 867100000, power: 16, mod: [LORA - sf: 10, bw: 125000], timing: [DELAY: 5], [freq: 869525000, power: 29, mod: [LORA - sf: 12, bw: 125000], timing: [DELAY: 6]]
Mon Jan 20 15:44:51 2025 user.info chirpstack-gateway-mesh[2860]: Sending downlink frame as relayed downlink, downlink_id: 2978223115, mesh_packet: [Downlink hop_count: 1, uplink_id: 1, relay_id: f136ce98, mic: a165a395]
Mon Jan 20 15:44:51 2025 user.info chirpstack-gateway-mesh[2860]: Sending mesh frame - [downlink_id: 2978223115 - [freq: 868100000, power: 16, mod: [LORA - sf: 7, bw: 125000], timing: [IMMEDIATELY]]]
Mon Jan 20 15:44:51 2025 user.info chirpstack-concentratord-sx1302[2669]: Enqueueing immediate packet, downlink_id: 2978223115, current_counter_us: 869121829
Mon Jan 20 15:44:51 2025 user.info chirpstack-concentratord-sx1302[2669]: Item tracked, band: [label: M, freq_min: 868000000, freq_max: 868600000, dc_max: 1.00%], freq: 868100000, tx_power_eirp: 16, start_counter_us: 870121829, end_counter_us: 870205829, duration: 84ms
Mon Jan 20 15:44:51 2025 user.debug chirpstack-concentratord-sx1302[2669]: Packet enqueued, downlink_id: 2978223115, count_us: 870121829
Mon Jan 20 15:44:51 2025 user.info chirpstack-gateway-mesh[2860]: Enqueue acknowledged, downlink_id: 2978223115
Mon Jan 20 15:44:51 2025 user.info chirpstack-mqtt-forwarder[2923]: Received ack, items: ["OK", "IGNORED"], downlink_id: 2978223115
Mon Jan 20 15:44:51 2025 user.info chirpstack-mqtt-forwarder[2923]: Sending ack event, downlink_id: 2978223115, topic: eu868/gateway/0016c001f136d8b8/event/ack
Mon Jan 20 15:44:51 2025 user.debug chirpstack-concentratord-sx1302[2669]: Processing u-blox NAV-TIMEGPS
Mon Jan 20 15:44:51 2025 user.debug chirpstack-concentratord-sx1302[2669]: Processing NMEA RMC
Mon Jan 20 15:44:51 2025 daemon.info hostapd: phy0-ap0: STA 3c:22:fb:1a:55:16 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Mon Jan 20 15:44:52 2025 user.info chirpstack-concentratord-sx1302[2669]: Scheduled packet for TX, downlink_id: 2978223115, count_us: 870121829, freq: 868100000, bw: 125000, mod: LoRa, dr: SF7
Relay:
Mon Jan 20 15:44:52 2025 user.info chirpstack-concentratord-sx1302[2588]: Frame received, uplink_id: 703945869, count_us: 15002924, freq: 868100000, bw: 125000, mod: LoRa, dr: SF7, ftime_received: false, ftime_ns: 0
Mon Jan 20 15:44:52 2025 user.info chirpstack-gateway-mesh[3493]: Mesh frame received - [uplink_id: 703945869, freq: 868100000, rssi: -63, snr: 9.5, mod: [LORA - sf: 7, bw: 125000]]
Mon Jan 20 15:44:52 2025 user.info chirpstack-gateway-mesh[3493]: Unwrapping relayed downlink, downlink_id: 485566528, mesh_packet: [Downlink hop_count: 1, uplink_id: 1, relay_id: f136ce98, mic: a165a395]
Mon Jan 20 15:44:52 2025 user.info chirpstack-gateway-mesh[3493]: Sending downlink frame - [downlink_id: 485566528 - [freq: 867100000, power: 16, mod: [LORA - sf: 10, bw: 125000], timing: [DELAY: 5]]
Mon Jan 20 15:44:52 2025 user.info chirpstack-concentratord-sx1302[2588]: Enqueueing timestamped packet, downlink_id: 485566528, counter_us: 13410874, current_counter_us: 15015194
Mon Jan 20 15:44:52 2025 user.warn chirpstack-concentratord-sx1302[2588]: Too early to enqueue packet, downlink_id: 485566528, counter_us: 13410874, current_counter_us: 15015194
Mon Jan 20 15:44:52 2025 user.err chirpstack-gateway-mesh[3493]: Handle mesh event error: Tx Ack error: TOO_EARLY
Mon Jan 20 15:44:52 2025 user.debug chirpstack-concentratord-sx1302[2588]: Processing u-blox NAV-TIMEGPS
Mon Jan 20 15:44:52 2025 user.debug chirpstack-concentratord-sx1302[2588]: Processing NMEA RMC
