fix(correlation): find the channel message's own RF row, not the newest (#255)

Verifying a channel message against the RF cache only ever checked the row
strategy 4 returned — the most recent packet heard. That assumes the RF log row
and the decoded CHAN event for one reception arrive back to back with nothing in
between. On a dense mesh they do not: a repeater's echo of the very same packet
is routinely logged in the gap.

The reporter's message was heard directly (SNR 13.25, 0 hops) and again via
repeater f0 185 ms later (SNR 12.0, 1 hop). Both rows carry packet hash
392926C85DCB87D0, but the check saw only the echo, disagreed on path length and
SNR, and left the route unresolved — so the bot withheld a path it had decoded
correctly and answered "No path information available in current message". The
reporter's own observation that MultiTest still reported paths is the tell:
multitest reads recent_rf_data directly and never consults the match tag, so the
radio data was there the whole time.

The cache is now searched for the row the payload matches rather than testing
just the newest one. #80's guarantee is unchanged — a route is still only ever
attributed on a positive match, never on recency — so this widens where the
check looks, not what it accepts. When more than one row matches they must
resolve to a single non-empty packet hash, which is only true of receptions of
one packet; two unrelated packets that happen to agree on all three fields stay
a fallback. A debug line now names the case where the newest row was not the
message's packet, so this failure mode is visible in logs rather than silent.

Side effect worth knowing: SNR and RSSI now come from the message's own
reception too. The reporter's message was logged at SNR 12.0 / RSSI -10, the
echo's figures, when its actual reception was 13.25 / -32.

Five tests cover it, including a reproduction built from the issue's log. Three
fail on the current code; the other two pin behaviour the fix must not break —
newest-wins among receptions of one packet, and scope_eligible_only still
filtering the search so the scope correlation cannot be handed an ineligible row.

CHANGELOG.md

@@ -8,6 +8,22 @@ semantic versioning.
 
 ### Fixed
 
+- `path` no longer answers "No path information available in current message" on a
+  busy mesh (#255). Verifying a channel message against the RF cache only ever
+  checked the newest row, which assumes the RF log row and the decoded CHAN event
+  for one reception arrive back to back with nothing in between. On a dense mesh
+  they do not: a repeater's echo of the very same packet is routinely logged in the
+  gap. The reporter's message was heard directly (`SNR 13.25`, 0 hops) and again via
+  repeater `f0` 185 ms later (`SNR 12.0`, 1 hop); both rows carry packet hash
+  `392926C85DCB87D0`, but the check saw only the echo, disagreed on path length and
+  SNR, and left the route unresolved — so the bot withheld a path it had decoded
+  correctly. The cache is now searched for the row the payload matches instead of
+  testing just the most recent one. Rows that agree must resolve to a single packet
+  hash, so two unrelated packets that happen to agree stay a fallback and #80's
+  guarantee is unchanged: a route is still only ever attributed on evidence. SNR and
+  RSSI now come from the message's own reception too, rather than from whichever
+  packet was heard last.
+
 - MQTT brokers no longer flap in a reconnect storm (#248). Three things stacked up.
   First, the packet-capture watchdog ran `client.reconnect()` from its own thread
   every 30 seconds whenever `is_connected()` was false — which includes every moment

modules/message_handler.py

@@ -1540,11 +1540,21 @@ class MessageHandler:
 
         # A channel message has no packet prefix or pubkey to match on, so everything
         # above lands on the most-recent-packet fallback. The decoded payload carries
-        # its own copies of fields the RF row also has, though, so the fallback can be
-        # checked rather than assumed.
+        # its own copies of fields the RF row also has, though, so the cache can be
+        # searched for this message's own packet rather than assuming the newest row.
         if recent_rf_data is not None and not rf_data_is_correlated(recent_rf_data):
-            if self._rf_data_matches_chan_payload(recent_rf_data, payload):
-                recent_rf_data = {**recent_rf_data, RF_MATCH_KEY: RF_MATCH_PAYLOAD}
+            verified = self._find_rf_row_matching_chan_payload(
+                payload, scope_eligible_only=scope_eligible_only
+            )
+            if verified is not None:
+                if verified.get("packet_prefix") != recent_rf_data.get("packet_prefix"):
+                    self.logger.debug(
+                        "Most recent RF row %s is not this message's packet (a later "
+                        "reception of another packet); the payload matches %s instead",
+                        (recent_rf_data.get("packet_prefix") or "?")[:16],
+                        (verified.get("packet_prefix") or "?")[:16],
+                    )
+                recent_rf_data = {**verified, RF_MATCH_KEY: RF_MATCH_PAYLOAD}
                 self.logger.debug(
                     "Verified RF row %s against the channel payload (GRP_TXT, path_len=%s, "
                     "SNR=%s); treating it as this message's packet",
@@ -1555,6 +1565,48 @@ class MessageHandler:
 
         return recent_rf_data
 
+    def _find_rf_row_matching_chan_payload(
+        self, payload: dict[str, Any] | None, *, scope_eligible_only: bool = False
+    ) -> dict[str, Any] | None:
+        """Return the cached RF row this channel message was received on, or None.
+
+        Checking only the newest row assumes the RF log row and the decoded CHAN
+        event for one reception arrive back to back with nothing in between. On a
+        dense mesh they do not: a repeater's echo of the very same packet is
+        routinely logged in the gap, so the newest row is that echo — a different
+        path length and a different measured SNR — and the message loses its route
+        even though its own row is sitting in the cache (#255). Search the cache
+        instead, and let _rf_data_matches_chan_payload decide which row is ours.
+
+        Two rows can only both match when they are receptions of the same packet
+        (same hash) that also agree on path length and SNR; anything else is
+        ambiguous and keeps the fallback tag, because a guess is what #80 cost.
+        """
+        if not payload:
+            return None
+
+        matches = [
+            row
+            for row in self.recent_rf_data
+            if self._rf_data_matches_chan_payload(row, payload)
+            and (not scope_eligible_only or self._is_rf_data_scope_eligible(row))
+        ]
+        if not matches:
+            return None
+
+        if len(matches) > 1:
+            hashes = {row.get("packet_hash") for row in matches}
+            if len(hashes) != 1 or not all(hashes):
+                self.logger.debug(
+                    "%d cached RF rows agree with the channel payload across %d packet(s); "
+                    "leaving the route unresolved rather than guessing",
+                    len(matches),
+                    len(hashes),
+                )
+                return None
+
+        return max(matches, key=lambda row: row["timestamp"])
+
     def _rf_data_matches_chan_payload(
         self, rf_data: dict[str, Any] | None, payload: dict[str, Any] | None
     ) -> bool:
@@ -1573,6 +1625,10 @@ class MessageHandler:
         a checked hypothesis. SNR is the discriminating one: it is the measured
         value of a single reception, quantised to 0.25 dB, so an unrelated packet
         matching all three is improbable rather than merely unlikely.
+
+        _find_rf_row_matching_chan_payload applies this to every cached row rather
+        than only the newest, so a repeater echo logged in between cannot displace
+        the message's own row (#255).
         """
         if not rf_data or not payload:
             return False

tests/test_message_handler.py

@@ -2426,3 +2426,95 @@ class TestChannelPayloadCorrelation:
         assert result[RF_MATCH_KEY] == RF_MATCH_PAYLOAD
         assert RF_MATCH_KEY not in row
         assert RF_MATCH_KEY not in handler.recent_rf_data[0]
+
+    def test_repeater_echo_does_not_displace_the_message_row(self, handler):
+        """#255: on a dense mesh a repeater's echo of the same packet is logged
+        between the reception and its CHAN event, so the newest row is the echo —
+        different path length, different measured SNR. The message's own row is
+        still in the cache and must be the one that is matched."""
+        heard = self._row(
+            timestamp=time.time() - 0.2,
+            packet_prefix="35e01500595cdf2fd7e580897cdae64a",
+            snr=13.25,
+            rssi=-32,
+            routing_info={"path_length": 0, "path_nodes": [], "packet_hash": "392926C85DCB87D0"},
+            packet_hash="392926C85DCB87D0",
+        )
+        echo = self._row(
+            packet_prefix="30f61501f0595cdf2fd7e580897cdae6",
+            snr=12.0,
+            rssi=-10,
+            routing_info={"path_length": 1, "path_nodes": ["F0"], "packet_hash": "392926C85DCB87D0"},
+            packet_hash="392926C85DCB87D0",
+        )
+        chan = {**self.CHAN, "SNR": 13.25, "path_len": 0}
+
+        handler.rf_data_timeout = 15.0
+        handler.message_timeout = 10.0
+        handler.enhanced_correlation = False
+        handler.recent_rf_data = [heard, echo]
+        result = asyncio.run(
+            handler._correlate_channel_message_rf_data(
+                None, "", chan, scope_eligible_only=False, extended_timeout=30.0
+            )
+        )
+
+        assert result[RF_MATCH_KEY] == RF_MATCH_PAYLOAD
+        assert rf_data_is_correlated(result) is True
+        assert result["packet_prefix"] == "35e01500595cdf2fd7e580897cdae64a"
+        # SNR/RSSI come from the message's own reception, not the echo's.
+        assert result["snr"] == 13.25
+        assert result["rssi"] == -32
+
+    def test_same_packet_heard_twice_alike_takes_the_newest(self, handler):
+        older = self._row(timestamp=time.time() - 0.2, packet_prefix="aa" * 16)
+        newer = self._row(packet_prefix="bb" * 16)
+        result = self._correlate(handler, [older, newer])
+        assert result[RF_MATCH_KEY] == RF_MATCH_PAYLOAD
+        assert result["packet_prefix"] == "bb" * 16
+
+    def test_two_packets_agreeing_is_ambiguous_and_stays_a_fallback(self, handler):
+        """Different packets that happen to agree on all three fields are a
+        coincidence, not evidence; #80 is what taking the guess cost."""
+        other = self._row(packet_hash="0123456789ABCDEF")
+        other["routing_info"] = {"path_length": 0, "packet_hash": "0123456789ABCDEF"}
+        result = self._correlate(handler, [self._row(timestamp=time.time() - 0.2), other])
+        assert result[RF_MATCH_KEY] == RF_MATCH_FALLBACK
+        assert rf_data_is_correlated(result) is False
+
+    def test_matching_rows_without_a_hash_are_ambiguous(self, handler):
+        rows = [
+            self._row(timestamp=time.time() - 0.2, packet_hash=None),
+            self._row(packet_hash=None),
+        ]
+        result = self._correlate(handler, rows)
+        assert result[RF_MATCH_KEY] == RF_MATCH_FALLBACK
+
+    def test_search_respects_scope_eligibility(self, handler):
+        """The scope correlation asks for TC_FLOOD rows usable for HMAC matching, so
+        the search must not hand back an ineligible row just because it matches."""
+        from modules.enums import RouteType
+
+        matching_but_ineligible = self._row(timestamp=time.time() - 0.2)
+        eligible_but_unmatched = self._row(
+            snr=-7.5,  # disagrees with the payload
+            packet_prefix="cc" * 16,
+            route_type_int=int(RouteType.TRANSPORT_FLOOD.value),
+            transport_code1=18583,
+            scope_payload_hex="ca37f40824e44f7c",
+        )
+        assert handler._is_rf_data_scope_eligible(eligible_but_unmatched) is True
+        assert handler._is_rf_data_scope_eligible(matching_but_ineligible) is False
+
+        handler.rf_data_timeout = 15.0
+        handler.message_timeout = 10.0
+        handler.enhanced_correlation = False
+        handler.recent_rf_data = [matching_but_ineligible, eligible_but_unmatched]
+        result = asyncio.run(
+            handler._correlate_channel_message_rf_data(
+                None, "", self.CHAN, scope_eligible_only=True, extended_timeout=30.0
+            )
+        )
+
+        assert result[RF_MATCH_KEY] == RF_MATCH_FALLBACK
+        assert result["packet_prefix"] == "cc" * 16