From ce68e7ab7ea7c1be37001e60b886bb52811bb79e Mon Sep 17 00:00:00 2001 From: agessaman Date: Wed, 5 Aug 2026 19:01:23 -0700 Subject: [PATCH] fix(neighbors): close three gaps in the cycle guards Follow-up to 7cffe1d; all three confirmed against meshcore 2.3.8. Charge the node-wide cooldown for the transmission, not the result. last_neighbors_publish is stamped only by a cycle that completes, so a discover request whose acknowledgement was lost spent the airtime and left the clock at zero -- another sender could immediately start a second round. The service now stamps last_neighbors_attempt before the request, and the command rations on whichever stamp is later. A cycle that bails out before touching the radio still records nothing, so retries stay possible. Restore the contact path when req_regions_sync returns None. send_anon_req gives up early when change_contact_path reports an error -- which is also what a lost acknowledgement for an applied path change looks like -- and that return skips the library's own reset_path. req_regions_sync collapses it to None, previously treated as a plain no-response. On the common "neighbour did not answer" path the extra reset is a redundant device command: no airtime, idempotent, and it re-syncs the contact cache. Stop reporting a rejected restore as a success. reset_path returns an ERROR event for a device rejection or its own response timeout rather than raising, so the helper logged "restored flood path" either way and hid a contact left pinned to zero-hop. It now inspects the event and warns with the reason. --- docs/packet-capture.md | 19 ++++-- modules/commands/neighbors_command.py | 14 ++-- modules/neighbors_discovery.py | 60 +++++++++++++--- .../service_plugins/packet_capture_service.py | 13 ++++ tests/commands/test_neighbors_command.py | 19 +++++- tests/unit/test_neighbors_discovery.py | 68 ++++++++++++++++++- tests/unit/test_packet_capture_neighbors.py | 32 +++++++++ 7 files changed, 203 insertions(+), 22 deletions(-) diff --git a/docs/packet-capture.md b/docs/packet-capture.md index f9de305..0129d39 100644 --- a/docs/packet-capture.md +++ b/docs/packet-capture.md @@ -410,9 +410,12 @@ whole mesh rather than to one requester: trigger asks — scheduler or command — so two discover rounds can never collect into each other's window. - **The 15-minute cooldown is per node, not per sender.** It is measured from the - last cycle that produced a result (including the scheduler's), so users cannot - take turns and keep the radio discovering continuously. A cycle that bailed out - without transmitting (radio down, unsupported build) does not start the clock. + last cycle that reached the radio, whichever trigger started it — including the + scheduler's, and including a cycle that failed after the discover request went + out, since a lost acknowledgement spends the airtime just the same. Users + therefore cannot take turns and keep the radio discovering continuously. A + cycle that bailed out *before* transmitting (radio down, unsupported build) + does not start the clock, so a retry stays possible. ### Region scopes are opt-in, and why @@ -428,9 +431,13 @@ It defaults to **false** for two reasons specific to running inside the bot: no stored path the meshcore library reaches zero-hop by calling `change_contact_path()` and then `reset_path()` — temporarily rewriting that contact's path on the device. Those two calls are not paired by a - `try`/`finally` upstream, so a request cut short in between would leave the - contact pinned to zero-hop and every later message to it sent direct-only; - `modules/neighbors_discovery.py` restores the path itself when that happens. + `try`/`finally` upstream, and one error path returns between them, so a request + cut short — or one whose path change was applied but not acknowledged — would + leave the contact pinned to zero-hop and every later message to it sent + direct-only. `modules/neighbors_discovery.py` restores the path itself in each + of those cases, and warns if the device rejects the restore (which it reports + as an error event rather than an exception), since that contact's routing is + then wrong until something else fixes it. With it off, the snapshot reports every neighbour it heard with empty `scopes` and `status: responded`. Enable it on a bench radio first. diff --git a/modules/commands/neighbors_command.py b/modules/commands/neighbors_command.py index bf3ec1d..4acf439 100644 --- a/modules/commands/neighbors_command.py +++ b/modules/commands/neighbors_command.py @@ -92,13 +92,19 @@ class NeighborsCommand(BaseCommand): def _shared_cooldown_remaining(self, service: Any) -> float: """Seconds left before *any* sender may trigger another cycle. - Keyed off the service's own "last cycle that produced a result" stamp, so - a cycle the scheduler ran counts too, and a cycle that bailed out without - transmitting (radio down, unsupported build) does not. + Measured from the last cycle that reached the radio, whichever trigger + started it — including the scheduler's, and including a cycle that failed + after the discover request went out. A lost acknowledgement spends the + airtime just the same, so charging only for completed cycles would let a + second sender start another round immediately. A cycle that bailed out + before transmitting (radio down, unsupported build) does not count. """ if self.cooldown_seconds <= 0: return 0.0 - last = getattr(service, 'last_neighbors_publish', 0) or 0 + last = max( + getattr(service, 'last_neighbors_publish', 0) or 0, + getattr(service, 'last_neighbors_attempt', 0) or 0, + ) return max(0.0, self.cooldown_seconds - (time.time() - last)) async def execute(self, message: MeshMessage) -> bool: diff --git a/modules/neighbors_discovery.py b/modules/neighbors_discovery.py index 3ba370a..19670ad 100644 --- a/modules/neighbors_discovery.py +++ b/modules/neighbors_discovery.py @@ -332,27 +332,60 @@ def _contact_has_no_path(meshcore: Any, pubkey: str) -> bool: return contact.get("out_path_len", CONTACT_NO_PATH) == CONTACT_NO_PATH +def _event_error_reason(event: Any) -> Optional[str]: + """The failure reason when *event* is an ERROR event, else None. + + Device commands report a rejection -- and their own response timeout -- as an + ERROR event rather than an exception, so a returned event has to be inspected + before the command can be called successful. + """ + if event is None or getattr(event, "type", None) != EventType.ERROR: + return None + payload = getattr(event, "payload", None) + if isinstance(payload, dict): + reason = payload.get("reason") or payload.get("error") + if reason: + return str(reason) + return "error" + + async def _restore_flood_path(meshcore: Any, pubkey: str, - logger: logging.Logger) -> None: + logger: logging.Logger) -> bool: """Put a contact back to "no path" after an interrupted scope request. ``send_anon_req`` sets the zero-hop path and restores it *after* the send, - with no ``try``/``finally``. If our budget cuts the request off in between, - the contact stays pinned to zero-hop on the device and every later message - to it is sent direct-only, so we repair it here instead. + with no ``try``/``finally``, and one of its error paths returns between the + two. Either way the contact stays pinned to zero-hop on the device and every + later message to it is sent direct-only, so we repair it here instead. + + Returns True when the device confirmed the reset. A failure is worth a + warning rather than a retry: the operator needs to know that contact's + routing is wrong, and hammering an unresponsive device does not help. """ try: - await meshcore.commands.reset_path(pubkey) - logger.info( - f"Neighbors: restored flood path for {pubkey[:12]} after an " - f"interrupted scope request" - ) + event = await meshcore.commands.reset_path(pubkey) except Exception as exc: logger.warning( f"Neighbors: could not restore the flood path for {pubkey[:12]} " f"after an interrupted scope request ({exc}); it may be left " f"pinned to zero-hop on the device" ) + return False + + reason = _event_error_reason(event) + if reason is not None: + logger.warning( + f"Neighbors: the device rejected the flood-path restore for " + f"{pubkey[:12]} ({reason}); it may be left pinned to zero-hop, " + f"so messages to it will be sent direct-only" + ) + return False + + logger.info( + f"Neighbors: restored flood path for {pubkey[:12]} after an " + f"interrupted scope request" + ) + return True def _restore_flood_path_detached(meshcore: Any, pubkey: str, @@ -479,6 +512,15 @@ async def collect_scopes( entry.status = STATUS_TIMEOUT if debug: logger.debug(f"Neighbors: no scope response from {entry.pubkey[:12]}") + # One of those collapsed failures is send_anon_req giving up because + # change_contact_path returned an error -- which it also does when the + # device *applied* the zero-hop path but its acknowledgement was lost. + # That returns before the library's own reset_path, so repair it here + # too. On the far more common "neighbour just did not answer" path the + # library has already restored the path and this is a redundant device + # command: no airtime, idempotent, and it re-syncs the contact cache. + if pinned_to_zero_hop: + await _restore_flood_path(meshcore, entry.pubkey, logger) continue entry.scopes = str(scopes).strip() diff --git a/modules/service_plugins/packet_capture_service.py b/modules/service_plugins/packet_capture_service.py index 29470cf..38bd60f 100644 --- a/modules/service_plugins/packet_capture_service.py +++ b/modules/service_plugins/packet_capture_service.py @@ -377,6 +377,10 @@ class PacketCaptureService(BaseServicePlugin): self.neighbors_discover_failures = 0 self.neighbors_topic_warned: set[int] = set() self.last_neighbors_publish = self._load_neighbors_state() + # When a cycle last reached the radio, whether or not it produced a + # result. Callers that ration airtime need this rather than + # last_neighbors_publish, which a failed cycle never stamps. + self.last_neighbors_attempt = 0.0 # Single-flight across every trigger (scheduler, command, future callers): # two overlapping cycles would collect into each other's discover window # and double the airtime. asyncio is single-threaded, so a plain flag set @@ -2288,6 +2292,15 @@ class PacketCaptureService(BaseServicePlugin): def session_intact() -> bool: return self.meshcore is session and self.bot.connected + # Stamp the attempt before the request, not after the cycle: from here on + # the discover broadcast may go out and spend airtime even if we never + # learn that it did (a lost acknowledgement fails the cycle without + # stamping last_neighbors_publish). Rate limiting has to charge for the + # transmission, not for the result. In-memory on purpose — this rations + # requests within a run, while last_neighbors_publish is the persisted + # schedule state. + self.last_neighbors_attempt = time.time() + entries = await discover_neighbors( self.meshcore, cfg, self_pubkey, self.logger, debug=self.debug, still_valid=session_intact, diff --git a/tests/commands/test_neighbors_command.py b/tests/commands/test_neighbors_command.py index 2923737..58804f2 100644 --- a/tests/commands/test_neighbors_command.py +++ b/tests/commands/test_neighbors_command.py @@ -14,15 +14,16 @@ from tests.conftest import mock_message def make_service(*, neighbors_enabled=True, summary=None, hang=False, raises=None, cycle_budget=5.0, last_publish=0.0, - cycle_active=False): + last_attempt=0.0, cycle_active=False): """A stand-in for PacketCaptureService's neighbors surface.""" service = types.SimpleNamespace() service.neighbors_enabled = neighbors_enabled service.neighbors_config = types.SimpleNamespace( discover_window=60.0, cycle_budget=cycle_budget ) - # 0.0 == "no cycle has ever produced a result", so nothing is on cooldown. + # 0.0 == "no cycle has ever run", so nothing is on cooldown. service.last_neighbors_publish = last_publish + service.last_neighbors_attempt = last_attempt service.neighbors_cycle_active = cycle_active service.calls = 0 @@ -230,6 +231,20 @@ async def test_the_cooldown_applies_across_senders(command_mock_bot): assert command._cycle_task is None +async def test_a_failed_cycle_still_starts_the_cooldown(command_mock_bot): + """The discover broadcast may have gone out even when the cycle failed, so a + second sender must not be able to transmit another round immediately.""" + service = make_service(last_publish=0.0, last_attempt=time.time() - 60) + command, sent = make_command(command_mock_bot, service) + + result = await command.execute( + mock_message(content="neighbors", is_dm=True, sender_id="SomeoneElse") + ) + assert result is True + assert sent == ["cooldown_active minutes=14"] + assert service.calls == 0 + + async def test_the_cooldown_expires(command_mock_bot, message): service = make_service(last_publish=time.time() - (NeighborsCommand.cooldown_seconds + 1), summary={"ok": True, "queried": 0, "recorded": 0, "attempted": 0}) diff --git a/tests/unit/test_neighbors_discovery.py b/tests/unit/test_neighbors_discovery.py index 3cf26d1..9b78e07 100644 --- a/tests/unit/test_neighbors_discovery.py +++ b/tests/unit/test_neighbors_discovery.py @@ -42,10 +42,11 @@ class FakeRadio: """Delivers DISCOVER_RESPONSE events synchronously from the send call.""" def __init__(self, responses=None, *, send_result="ok", scopes="DEN,APRS", - flood_scope="SEA"): + flood_scope="SEA", reset_result="ok"): self.responses = responses or [] self.send_result = send_result self.scopes = scopes + self.reset_result = reset_result self.handler = None self.subscribed = 0 self.unsubscribed = 0 @@ -77,6 +78,12 @@ class FakeRadio: async def _reset_path(self, pubkey): self.reset_path_calls.append(pubkey) + if self.reset_result == "raise": + raise RuntimeError("serial write failed") + if self.reset_result == "error": + # How the library reports a device rejection, and its own response + # timeout: an ERROR event, not an exception. + return FakeEvent(EventType.ERROR, {"reason": "timeout"}) return FakeEvent(EventType.OK, {}) def subscribe(self, event_type, callback): @@ -545,6 +552,65 @@ async def test_unknown_contact_needs_no_repair(tiny_budget): assert radio.reset_path_calls == [] +async def test_a_collapsed_send_error_restores_a_pinned_contact(): + """req_regions_sync returns None for a send_anon_req error too. + + One of those errors is change_contact_path failing *after* the device applied + the zero-hop path (a lost acknowledgement), which returns before the library's + own reset_path — so None cannot be assumed to mean "the path was restored". + """ + cfg = nb.NeighborsConfig(collect_scopes=True, scope_gap=0) + radio = FakeRadio(scopes=None) + radio.add_contact(KEY_A, out_path_len=-1) + entries = [nb.NeighborEntry(pubkey=KEY_A, snr=1.0, heard_at=0.0)] + await nb.collect_scopes(radio, entries, cfg, LOGGER) + assert entries[0].status == nb.STATUS_TIMEOUT + assert radio.reset_path_calls == [KEY_A] + + +async def test_no_response_needs_no_repair_without_a_known_contact(): + """Nothing was mutated, so nothing may be sent to the device.""" + cfg = nb.NeighborsConfig(collect_scopes=True, scope_gap=0) + radio = FakeRadio(scopes=None) + entries = [nb.NeighborEntry(pubkey=KEY_A, snr=1.0, heard_at=0.0)] + await nb.collect_scopes(radio, entries, cfg, LOGGER) + assert radio.reset_path_calls == [] + + +@pytest.mark.parametrize("reset_result,expected", [ + ("error", "rejected the flood-path restore"), + ("raise", "could not restore the flood path"), +]) +async def test_a_failed_restore_is_reported_as_a_failure(caplog, reset_result, expected): + """reset_path reports a rejection as an ERROR event, not an exception. + + Logging success there would hide a contact left pinned to zero-hop. + """ + cfg = nb.NeighborsConfig(collect_scopes=True, scope_gap=0) + radio = FakeRadio(scopes=None, reset_result=reset_result) + radio.add_contact(KEY_A, out_path_len=-1) + entries = [nb.NeighborEntry(pubkey=KEY_A, snr=1.0, heard_at=0.0)] + + with caplog.at_level(logging.WARNING, logger=LOGGER.name): + await nb.collect_scopes(radio, entries, cfg, LOGGER) + + assert radio.reset_path_calls == [KEY_A] + assert expected in caplog.text + assert "restored flood path" not in caplog.text + + +async def test_a_confirmed_restore_is_reported_as_success(caplog): + cfg = nb.NeighborsConfig(collect_scopes=True, scope_gap=0) + radio = FakeRadio(scopes=None) + radio.add_contact(KEY_A, out_path_len=-1) + entries = [nb.NeighborEntry(pubkey=KEY_A, snr=1.0, heard_at=0.0)] + + with caplog.at_level(logging.INFO, logger=LOGGER.name): + await nb.collect_scopes(radio, entries, cfg, LOGGER) + + assert "restored flood path" in caplog.text + + async def test_successful_request_leaves_the_restore_to_the_library(): """The library's own reset_path runs on the happy path; ours must not double up.""" cfg = nb.NeighborsConfig(collect_scopes=True, scope_gap=0) diff --git a/tests/unit/test_packet_capture_neighbors.py b/tests/unit/test_packet_capture_neighbors.py index 8a0d863..6d920fc 100644 --- a/tests/unit/test_packet_capture_neighbors.py +++ b/tests/unit/test_packet_capture_neighbors.py @@ -144,6 +144,7 @@ def build_service(ini: str, *, db_manager=None, radio=None, connected=True): service.neighbors_discover_failures = 0 service.neighbors_topic_warned = set() service.last_neighbors_publish = service._load_neighbors_state() + service.last_neighbors_attempt = 0.0 service.neighbors_cycle_active = False service.debug = False # global_iata deliberately not overridden: it comes from the ini, so tests can @@ -646,6 +647,37 @@ async def test_concurrent_cycles_are_refused(db_manager, monkeypatch): assert service.neighbors_cycle_active is False +async def test_a_failed_cycle_still_records_the_attempt(db_manager, caplog, no_sleep): + """A lost acknowledgement spends the airtime without completing the cycle. + + last_neighbors_publish stays unset in that case, so callers that ration + airtime need the attempt stamp or another sender could transmit immediately. + """ + radio = FakeRadio([]) + + async def failing(filter_bits, prefix_only=True, tag=None): + return FakeEvent(EventType.ERROR, {"reason": "no_event_received"}) + + radio.commands.send_node_discover_req = failing + service = build_service(BASE_INI, db_manager=db_manager, radio=radio) + service.mqtt_enabled = False + + summary = await service.run_neighbors_cycle() + assert summary["ok"] is False + assert service.last_neighbors_publish == 0 + assert service.last_neighbors_attempt > 0 + + +async def test_a_cycle_that_never_transmits_records_no_attempt(db_manager): + """Refusing before the radio is touched must not lock out a retry.""" + service = build_service(BASE_INI, db_manager=db_manager, radio=None) + service.mqtt_enabled = False + + summary = await service.run_neighbors_cycle() + assert summary["ok"] is False + assert service.last_neighbors_attempt == 0.0 + + async def test_the_guard_is_released_when_a_cycle_fails(db_manager, no_sleep): radio = FakeRadio([])