fix(message_handler): find NEW_CONTACT's advert by its timestamp, even mid-processing

Codex review follow-up. The RX handler cached an advert's RF entry only after awaiting _process_advertisement_packet, which can yield (geocoding), so a NEW_CONTACT handled meanwhile found nothing or an older advert. Adverts are now recorded in their own short cache (_advert_rf) before that await. The match also requires the advert timestamp to equal NEW_CONTACT's last_advert, so a delayed copy of an older advert no longer stands in for the newer one; without last_advert the most recent advert is used.

A failed or raising add releases its claim, so a later NEW_CONTACT for the same advert tries again.

CHANGELOG.md

@@ -38,7 +38,7 @@ semantic versioning.
 
 ### Fixed
 
-- A new contact's route comes from its own advert. NEW_CONTACT took the route, packet hash and signal data from whichever of the last ten received packets came first, usually a different node's message or advert, and wrote that route into the contact's `out_path` (sent to the radio with `auto_manage_contacts = bot`), the mesh graph and the observed paths. It now uses the first copy heard of the contact's latest advert, matched by public key, and leaves the mesh graph and observed paths to the advert packet itself, which already recorded them (a correct match was counted twice). With `auto_manage_contacts = bot`, a companion is still added to the radio once its advert has been tracked: the add was skipped whenever the packet hash had been seen before, which the correct hash always has.
+- A new contact's route comes from its own advert. NEW_CONTACT took the route, packet hash and signal data from whichever of the last ten received packets came first, usually a different node's message or advert, and wrote that route into the contact's `out_path` (sent to the radio with `auto_manage_contacts = bot`), the mesh graph and the observed paths. It now uses the first copy heard of the advert NEW_CONTACT reports, matched by public key and advert timestamp, and leaves the mesh graph and observed paths to the advert packet itself, which already recorded them (a correct match was counted twice). With `auto_manage_contacts = bot`, a companion is still added to the radio once its advert has been tracked: the add was skipped whenever the packet hash had been seen before, which the correct hash always has.
 - `gwx` (and `wx` with `weather_provider = openmeteo`) labels the current conditions by whether the sun is up at the location, using Open-Meteo's `is_day`. Before 06:00 the reply said "Tonight" next to today's high and low and a "Tomorrow" that was really the day after, so at 5:58 am it read like last night's forecast. Between midnight and sunrise it now says "Overnight", as NWS does; "Tonight" runs from sunset to midnight; and a dark 06:30 in October or a light 18:30 in June is no longer mislabeled. Clear skies at night show 🌙 instead of ☀️, in hourly forecasts too (each hour by its own `is_day`), and tomorrow's part names its weather ("🌫️Foggy", not just "🌫️") when it fits.
 - `wx hourly`, `gwx tomorrow`, `wx 5d`, `wx alerts` and other options given without a location now apply to the location the command falls back to (a custom default source, the sender's position, `default_city`, the bot's position); they showed the usage text, and `wx alerts` looked up a place called "alerts". A custom source named like an option (`custom.wxsim.hourly`) still answers as that source. `wx <place> alerts` stops when its first message is refused instead of sending the rest of the list. With `[Weather]` units and no `[Wx_Command]` override, `wx` also no longer logs a notice to move the unit settings into `[Wx_Command]` on every reply.
 - `wx tomorrow` (NOAA) fits its reply into one message. It ignored the length budget, so a day with long condition names ("Chance Showers And Thunderstorms" for both periods) went out as two messages. It now leaves out wind, the night period's first, and then the night period itself when that is what it takes. `gwx tomorrow` ignored its budget too; it now leaves out the precipitation amount, gusts, wind, the precipitation chance and then the description, in that order.

modules/message_handler.py

@@ -84,6 +84,9 @@ class MessageHandler:
         # Time-based cache for recent RF log data
         self.recent_rf_data: list[dict[str, Any]] = []
 
+        # Adverts heard on RF, recorded before any await so NEW_CONTACT can find its own
+        self._advert_rf: list[dict[str, Any]] = []
+
         # (public_key, packet_hash) of adverts NEW_CONTACT already added to the device
         self._new_contact_adds: dict[tuple[str, str], None] = {}
 
@@ -1541,6 +1544,9 @@ class MessageHandler:
                                     "rssi": payload.get("rssi") if "rssi" in payload else None,
                                     "hops": routing_info["path_length"],
                                 }
+                                self._remember_advert_rf(
+                                    decoded_packet, routing_info, packet_hash, signal_info, current_time
+                                )
                                 await self._process_advertisement_packet(decoded_packet, signal_info)
 
                     # Prefer library-provided scope fields (already parsed by meshcore-py).
@@ -4120,36 +4126,67 @@ class MessageHandler:
         contact_data["out_path_hash_mode"] = (pb >> 6) & 0x03
         contact_data["out_path_len"] = pb & 0x3F
 
-    def _find_advert_rf_data(self, public_key: str) -> dict[str, Any] | None:
-        """The cached RF entry of ``public_key``'s most recent ADVERT, or None.
+    def _remember_advert_rf(
+        self,
+        packet_info: dict[str, Any],
+        routing_info: dict[str, Any],
+        packet_hash: str | None,
+        signal_info: dict[str, Any],
+        current_time: float,
+    ) -> None:
+        """Record an advert heard on RF for handle_new_contact.
 
-        An ADVERT's payload starts with the sender's public key, so the match is
-        exact. Among the copies of that packet heard over different paths, the first
-        one is returned: the copy the device acted on.
+        Called before the advert is processed, which can yield, so a NEW_CONTACT
+        handled meanwhile still finds it. An ADVERT payload starts with the
+        sender's 32-byte public key and its 4-byte advert timestamp.
+        """
+        payload_hex = packet_info.get("payload_hex")
+        if not isinstance(payload_hex, str) or len(payload_hex) < 72:
+            return
+        try:
+            advert_timestamp = int.from_bytes(bytes.fromhex(payload_hex[64:72]), "little")
+        except ValueError:
+            return
+        self._advert_rf.append({
+            "timestamp": current_time,
+            "public_key": payload_hex[:64].lower(),
+            "advert_timestamp": advert_timestamp,
+            "routing_info": routing_info,
+            "packet_hash": packet_hash,
+            "snr": signal_info.get("snr"),
+            "rssi": signal_info.get("rssi"),
+        })
+        cutoff = current_time - self.rf_data_timeout
+        self._advert_rf = [entry for entry in self._advert_rf if entry["timestamp"] >= cutoff][-256:]
+
+    def _find_advert_rf_data(self, public_key: str, advert_timestamp: Any = None) -> dict[str, Any] | None:
+        """The first copy heard of ``public_key``'s advert, or None.
+
+        With ``advert_timestamp`` (NEW_CONTACT's ``last_advert``) only that advert
+        matches; without it, the most recent one. Copies of one advert heard over
+        different paths share its timestamp; the first is the one the device acted on.
         """
         if not public_key:
             return None
         key = public_key.lower()
         now = time.time()
         matches = [
-            data
-            for data in self.recent_rf_data
-            if data.get("routing_info")
-            and data.get("payload_type_int") == PayloadType.ADVERT.value
-            and (data.get("scope_payload_hex") or "").lower().startswith(key)
-            and now - data.get("timestamp", 0) < self.rf_data_timeout
+            entry
+            for entry in self._advert_rf
+            if entry["public_key"] == key and now - entry["timestamp"] < self.rf_data_timeout
         ]
+        if isinstance(advert_timestamp, int) and not isinstance(advert_timestamp, bool) and advert_timestamp > 0:
+            matches = [entry for entry in matches if entry["advert_timestamp"] == advert_timestamp]
+        elif matches:
+            newest = max(matches, key=lambda entry: entry["timestamp"])["advert_timestamp"]
+            matches = [entry for entry in matches if entry["advert_timestamp"] == newest]
         if not matches:
             return None
-        newest = max(matches, key=lambda d: d.get("timestamp", 0))
-        packet_hash = newest["routing_info"].get("packet_hash") or newest.get("packet_hash")
-        if not packet_hash:
-            return newest
-        copies = [
-            d for d in matches
-            if (d["routing_info"].get("packet_hash") or d.get("packet_hash")) == packet_hash
-        ]
-        return min(copies, key=lambda d: d.get("timestamp", 0))
+        return min(matches, key=lambda entry: entry["timestamp"])
+
+    def _release_new_contact_add(self, public_key: str, packet_hash: str | None) -> None:
+        """Let a later NEW_CONTACT for this advert try again after a failed add."""
+        self._new_contact_adds.pop((public_key, packet_hash or ""), None)
 
     def _claim_new_contact_add(self, public_key: str, packet_hash: str | None) -> bool:
         """False when a NEW_CONTACT for this advert packet already added the contact."""
@@ -4197,7 +4234,7 @@ class MessageHandler:
             # Only collect RSSI/SNR for zero-hop (direct) advertisements
             packet_hash = None
             try:
-                rf_entry = self._find_advert_rf_data(public_key)
+                rf_entry = self._find_advert_rf_data(public_key, contact_data.get("last_advert"))
                 if rf_entry:
                     routing_info = rf_entry["routing_info"]
 
@@ -4356,11 +4393,13 @@ class MessageHandler:
                                     contact_data, contact_name, public_key
                                 )
                                 if not ok:
+                                    self._release_new_contact_add(public_key, packet_hash)
                                     self.logger.warning(
                                         "Failed to add companion contact %s to device after managed add/retry",
                                         contact_name,
                                     )
                             except Exception as e:
+                                self._release_new_contact_add(public_key, packet_hash)
                                 self.logger.error("Error adding companion %s to device: %s", contact_name, e)
 
                             status = await self.bot.repeater_manager.get_contact_list_status()

tests/test_message_handler.py

@@ -2303,13 +2303,13 @@ def _companion_contact_payload() -> dict:
 
 
 def _advert_rf_entry(public_key: str, *, path_hex: str = "0102", path_length: int = 2,
-                     packet_hash: str | None = None, age: float = 0.0, payload_type: int = 4) -> dict:
-    """A cached RF entry for an ADVERT (payload type 4) from ``public_key``."""
+                     packet_hash: str | None = None, age: float = 0.0) -> dict:
+    """An advert from ``public_key`` as handle_new_contact's advert cache holds it."""
     import time as _time
     return {
         "timestamp": _time.time() - age,
-        "payload_type_int": payload_type,
-        "scope_payload_hex": public_key + "00" * 8,
+        "public_key": public_key,
+        "advert_timestamp": 1,
         "routing_info": {
             "path_hex": path_hex,
             "path_length": path_length,
@@ -2414,7 +2414,7 @@ class TestHandleNewContactAutoManage:
 
         bot, handler, rm, mesh = new_contact_env
         bot.config.set("Bot", "auto_manage_contacts", "bot")
-        handler.recent_rf_data = [_advert_rf_entry("ab" * 32, packet_hash="1122334455667788")]
+        handler._advert_rf = [_advert_rf_entry("ab" * 32, packet_hash="1122334455667788")]
         rm.track_contact_advertisement = AsyncMock(
             return_value=TrackAdvertResult(ok=True, duplicate_packet=True)
         )
@@ -2427,13 +2427,23 @@ class TestHandleNewContactAutoManage:
     async def test_bot_mode_two_events_for_one_advert_add_once(self, new_contact_env):
         bot, handler, rm, mesh = new_contact_env
         bot.config.set("Bot", "auto_manage_contacts", "bot")
-        handler.recent_rf_data = [_advert_rf_entry("ab" * 32, packet_hash="1122334455667788")]
+        handler._advert_rf = [_advert_rf_entry("ab" * 32, packet_hash="1122334455667788")]
         ev = _NewContactEvent(_companion_contact_payload())
         await handler.handle_new_contact(ev, None)
         await handler.handle_new_contact(_NewContactEvent(_companion_contact_payload()), None)
         assert rm.track_contact_advertisement.await_count == 2
         rm.add_companion_from_contact_data.assert_awaited_once()
 
+    async def test_bot_mode_failed_add_lets_the_next_event_retry(self, new_contact_env):
+        bot, handler, rm, mesh = new_contact_env
+        bot.config.set("Bot", "auto_manage_contacts", "bot")
+        rm.add_companion_from_contact_data = AsyncMock(side_effect=[False, True])
+        handler._advert_rf = [_advert_rf_entry("ab" * 32, packet_hash="1122334455667788")]
+        await handler.handle_new_contact(_NewContactEvent(_companion_contact_payload()), None)
+        await handler.handle_new_contact(_NewContactEvent(_companion_contact_payload()), None)
+        await handler.handle_new_contact(_NewContactEvent(_companion_contact_payload()), None)
+        assert rm.add_companion_from_contact_data.await_count == 2
+
     async def test_bot_mode_without_an_advert_packet_adds_every_time(self, new_contact_env):
         bot, handler, rm, mesh = new_contact_env
         bot.config.set("Bot", "auto_manage_contacts", "bot")

tests/test_message_handler_contact_path.py

@@ -149,7 +149,7 @@ class TestHandleNewContactAddContact:
     async def test_add_contact_receives_merged_path_from_rf_flood_event(self, companion_new_contact_setup):
         """Flood NEW_CONTACT (-1/-1) + RF routing with path_len_byte fixes hash_mode for add_contact."""
         bot, mh = companion_new_contact_setup
-        mh.recent_rf_data = [
+        mh._advert_rf = [
             {
                 "routing_info": {
                     "path_hex": "0102030405060708",
@@ -160,8 +160,8 @@ class TestHandleNewContactAddContact:
                 },
                 "snr": 13.5,
                 "timestamp": time.time(),
-                "payload_type_int": 4,
-                "scope_payload_hex": "a95b4becd36e185eae392d48f11825143d8505d9421a15c7d9f99bc51da70f66" + "00" * 8,
+                "public_key": "a95b4becd36e185eae392d48f11825143d8505d9421a15c7d9f99bc51da70f66",
+                "advert_timestamp": 1,
             }
         ]
 
@@ -195,7 +195,7 @@ class TestHandleNewContactAddContact:
     async def test_add_contact_uses_path_len_byte_for_two_byte_hops(self, companion_new_contact_setup):
         bot, mh = companion_new_contact_setup
         path_hex = "414243444546"  # 3 hops × 2 bytes = 6 bytes = 12 hex chars
-        mh.recent_rf_data = [
+        mh._advert_rf = [
             {
                 "routing_info": {
                     "path_hex": path_hex,
@@ -205,8 +205,8 @@ class TestHandleNewContactAddContact:
                     "path_byte_length": 6,
                 },
                 "timestamp": time.time(),
-                "payload_type_int": 4,
-                "scope_payload_hex": "b95b4becd36e185eae392d48f11825143d8505d9421a15c7d9f99bc51da70f66" + "00" * 8,
+                "public_key": "b95b4becd36e185eae392d48f11825143d8505d9421a15c7d9f99bc51da70f66",
+                "advert_timestamp": 1,
             }
         ]
 
@@ -234,11 +234,11 @@ class TestHandleNewContactAddContact:
         int(self._pack_path_byte(passed)).to_bytes(1, "little", signed=False)
 
 
-def _rf(public_key, path_hex, *, packet_hash, payload_type=4, age=0.0):
+def _rf(public_key, path_hex, *, packet_hash, advert_timestamp=1, age=0.0):
     return {
         "timestamp": time.time() - age,
-        "payload_type_int": payload_type,
-        "scope_payload_hex": public_key + "00" * 8,
+        "public_key": public_key,
+        "advert_timestamp": advert_timestamp,
         "routing_info": {
             "path_hex": path_hex,
             "path_length": len(path_hex) // 2,
@@ -282,9 +282,9 @@ class TestNewContactRouteSource:
     @pytest.mark.asyncio
     async def test_an_unrelated_packet_route_is_not_used(self, companion_new_contact_setup):
         bot, mh = companion_new_contact_setup
-        mh.recent_rf_data = [
-            _rf(self.OTHER, "a1a2a3", packet_hash="00aa00aa00aa00aa"),  # another node's advert
-            _rf(self.PK, "b1b2b3", packet_hash="00bb00bb00bb00bb", payload_type=5),  # a GRP_TXT
+        mh._advert_rf = [_rf(self.OTHER, "a1a2a3", packet_hash="00aa00aa00aa00aa")]  # another node's advert
+        mh.recent_rf_data = [  # a channel message heard just before
+            {"timestamp": time.time(), "payload_type_int": 5, "routing_info": {"path_hex": "b1b2b3", "path_length": 3}},
         ]
         passed = await self._added(bot, mh)
         assert passed["out_path"] == ""
@@ -295,7 +295,7 @@ class TestNewContactRouteSource:
     @pytest.mark.asyncio
     async def test_the_contact_advert_route_is_used_and_not_recorded_again(self, companion_new_contact_setup):
         bot, mh = companion_new_contact_setup
-        mh.recent_rf_data = [
+        mh._advert_rf = [
             _rf(self.OTHER, "a1a2a3", packet_hash="00aa00aa00aa00aa"),
             _rf(self.PK, "c1c2", packet_hash="00cc00cc00cc00cc"),
             _rf(self.OTHER, "a4a5", packet_hash="00dd00dd00dd00dd"),
@@ -311,8 +311,8 @@ class TestNewContactRouteSource:
     @pytest.mark.asyncio
     async def test_the_first_copy_of_the_newest_advert_is_used(self, companion_new_contact_setup):
         bot, mh = companion_new_contact_setup
-        mh.recent_rf_data = [
-            _rf(self.PK, "0f0f", packet_hash="0001000100010001", age=8.0),  # an older advert
+        mh._advert_rf = [
+            _rf(self.PK, "0f0f", packet_hash="0001000100010001", advert_timestamp=0, age=8.0),  # an older advert
             _rf(self.PK, "e1e2", packet_hash="0002000200020002", age=2.0),  # first copy heard
             _rf(self.PK, "e3e4e5", packet_hash="0002000200020002", age=1.0),  # a later copy
         ]
@@ -325,3 +325,38 @@ class TestNewContactRouteSource:
         mh.recent_rf_data = [_rf(self.PK, "c1c2", packet_hash="00cc00cc00cc00cc", age=60.0)]
         passed = await self._added(bot, mh)
         assert passed["out_path"] == ""
+
+
+    @pytest.mark.asyncio
+    async def test_the_advert_named_by_last_advert_is_used(self, companion_new_contact_setup):
+        """A delayed copy of an older advert does not stand in for the one NEW_CONTACT is about."""
+        bot, mh = companion_new_contact_setup
+        mh._advert_rf = [
+            _rf(self.PK, "a1a1", packet_hash="000a000a000a000a", advert_timestamp=1, age=5.0),
+            _rf(self.PK, "b2b2", packet_hash="000b000b000b000b", advert_timestamp=2, age=3.0),
+            _rf(self.PK, "a3a3", packet_hash="000a000a000a000a", advert_timestamp=1, age=1.0),  # delayed copy
+        ]
+        event = MagicMock()
+        event.payload = {**_flood_contact(self.PK), "last_advert": 2}
+        await mh.handle_new_contact(event)
+        assert bot.meshcore.commands.add_contact.await_args[0][0]["out_path"] == "b2b2"
+
+
+class TestAdvertSeenBeforeProcessing:
+    @pytest.mark.asyncio
+    async def test_new_contact_handled_during_advert_processing_finds_the_advert(self, message_handler):
+        """The advert is recorded before _process_advertisement_packet yields."""
+        mh = message_handler
+        pk = "e7" * 32
+        payload_hex = pk + (1234).to_bytes(4, "little").hex() + "00" * 70
+        seen = {}
+
+        async def _process(packet_info, signal_info):
+            seen["entry"] = mh._find_advert_rf_data(pk, 1234)
+
+        mh._process_advertisement_packet = _process
+        routing_info = {"path_hex": "0102", "path_length": 2, "packet_hash": "00ee00ee00ee00ee"}
+        mh._remember_advert_rf({"payload_hex": payload_hex}, routing_info, "00ee00ee00ee00ee", {"snr": 5.0}, time.time())
+        await mh._process_advertisement_packet({}, {})
+        assert seen["entry"]["routing_info"]["path_hex"] == "0102"
+        assert mh._find_advert_rf_data(pk, 999) is None