diff --git a/CHANGELOG.md b/CHANGELOG.md index 187230a..73f6da7 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/modules/message_handler.py b/modules/message_handler.py index 34ca080..7699891 100644 --- a/modules/message_handler.py +++ b/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 diff --git a/tests/test_message_handler.py b/tests/test_message_handler.py index cf56b8b..1a24ce5 100644 --- a/tests/test_message_handler.py +++ b/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