mirror of
https://github.com/agessaman/meshcore-bot.git
synced 2026-08-14 22:50:18 +00:00
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.
This commit is contained in:
+13
-6
@@ -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.
|
||||
|
||||
@@ -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:
|
||||
|
||||
@@ -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()
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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})
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -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([])
|
||||
|
||||
|
||||
Reference in New Issue
Block a user