Skip to content

fix(coordinator): re-arm the self-telemetry interval on failure - #335

Open
pfmos wants to merge 1 commit into
meshcore-dev:mainfrom
pfmos:fix/self-telemetry-retry-storm
Open

fix(coordinator): re-arm the self-telemetry interval on failure#335
pfmos wants to merge 1 commit into
meshcore-dev:mainfrom
pfmos:fix/self-telemetry-retry-storm

Conversation

@pfmos

@pfmos pfmos commented Sep 3, 2026

Copy link
Copy Markdown

Problem

get_self_telemetry() sends the four-byte "self" form of CMD_SEND_TELEMETRY_REQ — opcode plus three reserved bytes, no pub key (meshcore_py/commands/device.py). Firmware answers it; MyMesh.cpp splits the command by frame length and has an explicit len == 4 self branch.

A non-firmware companion need not. An openHop virtual companion up to and including 1.1.1 requires the 36-byte contact form and rejects the short frame:

# openhop_core/companion/frame_server.py
if len(data) < 35:
    self._write_err(ERR_CODE_ILLEGAL_ARG)
    return

_last_self_telemetry_update advanced only in the success branch, so against such a node the interval gate never re-armed. The configured interval collapsed to the coordinator tick and the request was re-sent on every cycle, forever, each one logged at ERROR.

Measured on a live instance against an openHop companion, from the repeater's own frame log over 30 minutes:

Opcode Command Count Cadence Result
0x27 len=4 SEND_TELEMETRY_REQ (self) 357 ~5.0 s refused, every time
0x14 len=1 GET_BATT_AND_STORAGE 357 ~5.0 s ok
0x0a len=1 SYNC_NEXT_MESSAGE 37 ~48 s ok
0x38 len=2 GET_STATS 15 ~2 min ok

The configured interval was 300 s. Half of every companion frame the integration sent was a request that could not succeed, and it produced roughly 17k ERROR-tier log lines a day.

Change

Re-arm the interval on failure. The interval gates attempts, not successes, so the attempt is recorded before it is issued. A failure now waits the configured interval exactly as a success does. Behaviour against a node that answers normally is unchanged.

Level the log by whether a retry could ever help. Failures route through a new _log_self_telemetry_error, following the existing _log_get_msg_error pattern. An error code meaning the node can never satisfy the request (ERR_CODE_ILLEGAL_ARG, ERR_CODE_UNSUPPORTED_CMD) is reported once at WARNING, naming the cause and the remedy, then demoted to DEBUG. Every other failure keeps ERROR on every occurrence. A success clears the flag, so a genuine later regression is reported afresh.

Together: a node that cannot answer produces one actionable WARNING instead of ~17k ERRORs a day, and stops consuming a request slot every tick.

Note on the other side of this

openHop already fixed its half — 3513bab, "answer the self form of telemetry requests", 16 Jul 2026 — but it is on dev only, not in any tag, and dev is ~340 commits ahead of main. Until that ships, released openHop builds still reject the frame. This change is also worth having independently: it makes any peer that refuses any optional command degrade quietly instead of hammering it.

Tests

tests/test_self_telemetry_retry.py, following test_get_msg_error_log_level.py: the helper is AST-extracted from production source and exercised directly, since coordinator.py cannot be imported whole under the conftest stubs.

  • unsupported code warns once, then demotes to DEBUG
  • ERR_CODE_UNSUPPORTED_CMD treated the same way
  • other payloads (including None) keep ERROR
  • structural guard: no assignment to _last_self_telemetry_update may sit inside the try that issues the request — this fails on the pre-change source and passes after, so it pins the actual bug rather than the symptom
  • a success must clear the reported flag

Verified locally: the 5 new tests pass, and the collectible suite is unchanged versus clean HEAD (104 passed vs 99, same 32 failures and 10 collection errors, all pre-existing TypeError: unsupported operand type(s) for | from PEP 604 syntax on the local Python 3.9 — CI runs a newer interpreter).

`get_self_telemetry()` sends the four-byte "self" form of
CMD_SEND_TELEMETRY_REQ (opcode plus three reserved bytes, no pub key).
Firmware answers it (MyMesh.cpp: `CMD_SEND_TELEMETRY_REQ && len == 4`),
but a non-firmware companion need not: an openHop virtual companion up
to and including 1.1.1 requires the 36-byte contact form and rejects the
short frame with ERR_CODE_ILLEGAL_ARG.

`_last_self_telemetry_update` advanced only in the success branch, so
against such a node the interval gate never re-armed. The configured
interval collapsed to the coordinator tick and the request was re-sent
every cycle, forever, each one logged at ERROR.

Measured on a live instance against an openHop companion: 357 requests
in 30 minutes (~5 s apart) on a 300 s setting -- half of every companion
frame the integration sent, none able to succeed -- and roughly 17k
ERROR-tier log lines a day.

The interval gates attempts, not successes, so record the attempt before
issuing it. A failure now waits the configured interval like a success
does; behaviour on a node that answers normally is unchanged.

Also route failures through `_log_self_telemetry_error`, following the
existing `_log_get_msg_error` pattern: an error code meaning the node can
never satisfy the request (ILLEGAL_ARG, UNSUPPORTED_CMD) is reported once
at WARNING naming the cause and the remedy, then demoted to DEBUG. Every
other failure keeps ERROR on every occurrence, and a success clears the
flag so a genuine later regression is reported afresh.

Tests AST-extract the production helper as `test_get_msg_error_log_level`
does, and add a structural guard asserting no assignment to
`_last_self_telemetry_update` sits inside the request `try` block.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant