f60c6735 - Fix OTel span_id fingerprint leak and hub push gap in knock - #52
f60c6735 - Fix OTel span_id fingerprint leak and hub push gap in knock#52Danswar wants to merge 35 commits into
Conversation
A W3C span_id (16 hex chars) fell under the existing _HEX redaction threshold (20+ chars) and leaked into stack_sig(), so the same recurring error got a different fingerprint on every occurrence and never deduped. trace_id (32 hex chars) was already caught by _HEX; only span_id needed a targeted fix.
… scan cycle. cmd_knock's scan loop wrote new/enriched activity rows locally but never called into the hub-push path; _sync_once() only ran on websocket (re)connect or in response to an inbound hub message, so a stable idle connection left local writes unpushed indefinitely. Extracted the scan cycle into _knock_scan_cycle() and call _sync_once() at the end of it when the device is paired.
…ash guard. Import Callable from collections.abc instead of typing and parametrize it, matching every other run_argv/runner callback signature in this codebase. Give mark_pushed() the same monotonic guard mark_origin() already has, so a concurrent push from cmd_knock and cmd_sync --follow cannot regress the push cursor. Catch the bare SystemExit _sync_once() raises on a malformed hub pull response at the new knock call site, so a bad response logs and continues instead of killing the daemon.
…line. README.md and DESIGN.md described the knock daemon's poll list without mentioning the hub push added at the end of each paired cycle. Also assert on the actual stderr text in the malformed-pull-response regression test, matching the existing test_knock_daemon_polls_usage pattern, instead of only checking that SystemExit doesn't propagate.
_sync_once() pushes then pulls; the doc lines describing the new per-cycle hub call said only 'push', underselling what actually happens. Also update DESIGN.md's operator checklist (the second description of what agent init's daemon does) to match the contract table, and rename a test to use the same verb as its sibling.
…ursor TOCTOU. Hub.request let a raw json.JSONDecodeError leak out on a malformed 2xx body instead of raising HubError like every other hub-communication failure. _sync_once then assumed a successful pull always returns a dict with well-formed events, so a None response or an event missing origin_device_id/origin_seq raised a bare AttributeError/KeyError that the new SystemExit catch in _knock_scan_cycle could not see - the exact crash-the-daemon failure mode that catch was meant to close. Both are now validated the same way the existing 'pull response missing events' check already works: a controlled die() that the caller's except clause catches. Also make the OTel trace_id/span_id redaction case-insensitive and add a traceparent header rule, and add a comment documenting why the mark_pushed/mark_origin cursor guard's residual cross-process race is accepted rather than locked (ledger_event is append-only and the hub treats repeated events as idempotent, so the worst case is a redundant push, not data loss).
…onsistently. The prior guard only checked pulled is a dict and each event has origin_device_id/origin_seq before calling apply_remote(). Everything downstream - apply_remote's own indexing of table/op/row_id/payload/ occurred_at, int(origin_seq) on a possibly non-numeric value, and apply_replica_row's indexing of the same fields on snapshot rows - was still unguarded, so a malformed-but-well-typed hub response could still raise a raw KeyError/TypeError/ValueError past every catch clause. Validate the full required field set for both events and snapshot rows up front, and raise HubError instead of calling die() for every malformed-response case in this function: HubError is already caught by both cmd_knock's _knock_scan_cycle and cmd_sync --follow's reconnect loop, so this closes the daemon-crash risk in both callers instead of just the one this PR added, without touching either loop's except clause.
_sync_once no longer raises bare SystemExit for any malformed-response check (everything is HubError now), so _knock_scan_cycle's except clause no longer needs to list SystemExit - and the leftover listing left a stale regression test documenting a contract that no longer applies. Narrowed the catch and rewrote the test around HubError. Also: int(event["origin_seq"]) validated the value but never wrote it back into the event dict, so a numeric-string origin_seq from the hub (passes int() cleanly) would still reach _insert_event_idempotent's plain Python != comparison as a string, raising a false-positive 'origin_seq gap' error for a genuinely valid sequence number. The event dict is now rebuilt with the coerced int before apply_remote().
…ield at a time. int(event["origin_seq"]) didn't catch OverflowError on an out-of-range float (JSON parses 1e309 as inf, and int(inf) overflows) and silently accepted a bool or a fractional float as a valid sequence number. Reject both explicitly and catch OverflowError alongside the existing TypeError/ValueError. Field presence was validated, but not the shape of nested values - a payload whose "type" is unhashable (e.g. a list) makes Store._maybe_wake's frozenset membership check raise a raw TypeError from deep inside apply_remote, a shape no single prior fix anticipated. Rather than keep chasing individual shapes, wrap apply_remote/mark_origin and apply_replica_row in a broad except-Exception-to-HubError safety net: HubError/StoreError are SystemExit subclasses so they pass through unchanged, everything else unexpected now becomes a catchable, logged HubError instead of an uncaught crash. Also parametrized the field-presence regression tests per field (matching the existing tests/test_jobs.py pattern) instead of dropping several fields at once, and added a call-order assertion proving sync runs after every scan, not just alongside them.
…g the crash. The broad exception safety net converted a malformed payload.type into a HubError every cycle, but since the event never actually persists (the exception rolls back apply_remote's transaction before mark_origin runs), the hub keeps re-serving the same event forever - an infinite, silently-logged retry wedge that looks like routine transient-error handling. _maybe_wake/_maybe_work and the wake=False branches in apply_remote/apply_replica_row now guard the frozenset membership check with isinstance(typ, str) first, so a malformed type is simply treated as not-a-wake-type and the event still applies normally. The safety net stays in place for shapes that genuinely can't be fixed at their root. Also added the missing test for the snapshot-row exception safety net (only the event-row one was covered).
…ore path. cmd_restore applies hub-returned own_events through apply_remote(wake=False), which materializes them into row_data under this device's own origin_device_id - so own-origin rows are not exclusively written by trusted local code. pending_work()'s EXECUTABLE_ACTIVITY_TYPES membership check had the same unguarded pattern already fixed elsewhere in _maybe_wake/_maybe_work: a malformed type from a corrupted restore response would crash the whole knock daemon on its next scan cycle. Same isinstance(typ, str) guard, same fix.
cmd_restore consumes the identical hub-data shape as _sync_once (events with origin_device_id/origin_seq/table/op/row_id/payload/ occurred_at, snapshot rows for inbox/pings) but received none of this PR's hardening: no dict-shape check on the restore body, no per-event field validation or origin_seq coercion before apply_remote (a numeric-string origin_seq deterministically raised a false-positive "origin_seq gap" error for the very first restored event, the exact defect class _sync_once was hardened against), no per-row field validation before apply_replica_row. Extracted the shared validation into _coerce_pull_event/_check_pull_row (raising an internal _PullShapeError), used by both _sync_once (converts to HubError) and cmd_restore (converts to die(), the appropriate convention for a one-shot CLI command) instead of duplicating the checks. cmd_restore had no test coverage at all before this; new tests/test_restore.py covers the hardening plus one happy-path test.
…g overclaim. Mirror the per-field @pytest.mark.parametrize pattern already used for the equivalent _sync_once tests, instead of dropping several fields at once - a future accidental narrowing of _PULL_EVENT_FIELDS/ _PULL_ROW_FIELDS to any single one of them is now caught here too. Also corrected a regression test's docstring: _sync_once's internal _hub_from_store() call can in principle still raise a bare SystemExit if pairing were revoked between _knock_scan_cycle's cached check and the _sync_once call, but no code path anywhere in this repo clears hub_url/device_token once set - confirmed write-once, only ever set by cmd_pair. Not reachable today; noted as a future concern instead of claimed impossible.
… paths. Mirror the _sync_once tests that already exercise these: a non-list inbox/pings value, and a payload containing something json.dumps can't serialize. Both were untested on the restore side even though cmd_restore now shares the same validation and safety-net code.
The regexes only matched logfmt key=value. Three independent reviews across this PR's history (two different vendor families) flagged that a span_id in any other real OTel log shape - JSON (span_id:...), key: value, or a quoted value with = - still fell under _HEX's 20-char floor and leaked into the dedup fingerprint unredacted, the exact class of bug this PR exists to fix. Capture the label/separator/quote prefix and substitute only the value, so the redacted line still reads naturally in whatever format it came in.
…efix. Five of the seven new shape assertions only checked that the raw trace/span id value was gone, not that the label/separator/quote prefix survived the substitution intact - a regression dropping the capture group (subbing the whole match instead of just the value) would still have passed. Added the missing prefix-preserving assertion for each shape.
…fixture. The optional-quote group in the OTel regexes didn't match a backslash-escaped quote, so a span_id inside an escaped nested-JSON shape (e.g. Docker's json-file log driver wrapping an application's JSON log line) still leaked past the fix, the same defect class this PR closes elsewhere. The quote groups now accept an optional leading backslash. Also documented the new redaction scope in DESIGN.md (it only mentioned the -configured secret/PII redaction, not the always-on OTel id stripping), and fixed cmd_restore's happy-path test to use a genuine own-device origin for its own_events fixture instead of a foreign one, matching what its docstring already claimed and DESIGN.md's own/foreign distinction.
…anch. test_cmd_restore_accepts_a_numeric_string_origin_seq still used a foreign origin_device_id for an own_events entry - the prior round's fix only caught the other instance in this file. Also: apply_remote/apply_replica_row's wake=False branches (the only mode cmd_restore ever uses) each have their own inline isinstance(typ, str) guard against a non-string payload type, mirroring _maybe_wake's guard on the wake=True path. The wake=True guard has sync-side regression tests; this one had none - a regression that reintroduced the unguarded check only in the wake=False branch would have stayed green everywhere except real restore runs.
…ercion. Same recurring pattern: the sync side had a parametrized regression test proving _coerce_pull_event rejects a bad origin_seq (bool, fractional float, overflow float, garbage string); the restore side only had the acceptance-side sibling for a valid numeric string, never a test proving restore actually rejects a bad one.
…ers. Field presence was checked but not payload's type or op's value. A non-dict payload or an unrecognized op used to pass _coerce_pull_event/ _check_pull_row untouched: apply_remote/apply_replica_row would commit it as-is (_maybe_wake/_maybe_work both already return early on a non-dict payload without raising, so the broad except-Exception backstop never fires), and the corruption would only surface later - on every future store.rows()/store.row() call for that whole table, not at write time. Store._write_in_txn already enforces both constraints for this device's own local writes; the hub-pull/restore path must not be laxer. Mirrors that same validation. Also added the missing traceparent JSON/quoted-value/escaped-JSON test coverage - the regex already supported those shapes, only the test coverage was asymmetric with trace_id/span_id.
… entry point. _coerce_pull_event/_check_pull_row checked payload/op but not table against OWNED_TABLES, unlike Store._write_in_txn's own validation for local writes. Lower severity than the payload/op gap (no known-table read gets poisoned, since _maybe_wake/_maybe_work/_upsert_row treat table as an opaque string), but a real asymmetry: an unrecognized table value would be durably committed as an orphaned row nothing ever reads back. Fixed in both validators. More importantly: _run_sync_ws_session's incoming "subscription" frame handler applied rows straight to store.apply_replica_row, validated only by isinstance(row, dict) and a truthy "table" - never through _check_pull_row. That's a third live entry point (after _sync_once and cmd_restore) for the exact bug this PR closed elsewhere: a non-dict payload doesn't raise anywhere in apply_replica_row/_upsert_row, so it would be committed as-is and only fail later, on every future read of that whole table. Now routes through the same shared validator. Also: cmd_restore's snapshot loop validated and applied each row in the same iteration, so an earlier valid row could already be committed before a later malformed one triggered die() - unlike _sync_once's snapshot handling, which validates the full batch before applying any of it. Split into two passes to match. Fixed a pre-existing test whose minimal row fixture (missing most required fields) no longer reached the mocked apply_replica_row it was actually testing, now that row validation runs first - the test mocks apply_replica_row directly to simulate a StoreConnectionError, so the row's shape was never meant to matter; given it a fully valid shape.
…strings. event["table"] not in OWNED_TABLES (a frozenset) requires table to be hashable - the exact bug class already fixed five times elsewhere in this PR for payload["type"] (isinstance(typ, str) guards in store.py). A JSON-decoded list/dict for table raised a raw TypeError that no caller's except clause caught, crashing the knock daemon, the sync --follow daemon, or the restore command depending on which entry point received it. Same isinstance(table, str) guard, same fix, now applied everywhere OWNED_TABLES is checked. Also corrected two docstrings/comments that overclaimed Store._write_in_txn already rejects a non-dict payload for local writes - it only validates table and op, not payload's type. Left _write_in_txn itself unchanged: local writes are this codebase's own trusted, code-constructed payloads, not externally-supplied hub data, so the risk this PR's validators guard against doesn't apply there.
…w's updated_at. An event in the events/own_events list is documented (DESIGN.md) as always this device's own history - foreign data only ever arrives as row snapshots - but nothing enforced that: a hub response could assert a foreign origin_device_id and it would be applied unchanged. Also validate updated_at is a non-empty string; an empty value passed the previous presence-only check, stored fine on first insert, and only broke a later legitimate update to that row with a raw timestamp cast error. Adds a regression test for cmd_restore's validate-all-then-apply-all snapshot batching (mirrored for _sync_once) proving a batch with one invalid row among valid ones commits nothing.
…t's non-empty. A non-empty but bogus value (e.g. a garbage string) passed the previous check the same way an empty one used to, hitting the identical stuck-row failure mode: stored as-is on first insert, only breaking a later legitimate update via a raw timestamp cast error. Parse it with datetime.fromisoformat, matching the existing precedent in watch.py. Also fixes a docstring in the new mixed-batch restore test that had the row order backwards.
…ix a docstring.
str.replace("Z", "+00:00") only normalized the uppercase form, but RFC 3339
permits lowercase z just as validly - a standards-conformant timestamp
using it was falsely rejected as invalid. Use a case-insensitive regex
instead. Also corrects a docstring that overstated apply_replica_row's
same-device guard as rejecting a row, when it actually skips it silently
and carves out an exception for ping rows.
…t row's updated_at is. occurred_at was presence-checked only. apply_remote writes it into row_data.updated_at too (via _materialize), so a bogus value was the same unvalidated-timestamp gap already closed on the row side - just not yet on the event side.
…g lambda. _knock_scan_cycle's run_argv parameter is typed Callable[[list[str]], Completed]; three new tests passed a lambda returning None instead, breaking both the declared type contract and the runner-double convention every other test in this repo already follows.
…nt loop into validate-all-then-apply-all. A pathologically nested JSON body still overflows CPython's C-accelerated decoder's own recursion guard, raising RecursionError rather than JSONDecodeError - not covered by Hub.request's existing except tuple, letting a malformed hub response crash the caller the same way this method already prevents for other decode failures. Separately, the events loop in cmd_restore/_sync_once validated and applied each event in the same iteration, so a batch with a valid event before an invalid one durably committed the valid one before dying on the invalid one - the identical partial-apply bug the snapshots loop was already split into two passes to fix, just never mirrored on the event side.
…rsionError paths, row_id/origin_device_id, and restore's session ordering. Hub._detail() (used to build the error message for a >= 400 response) and the live websocket message loop each had their own separate JSON-decode call that never picked up the RecursionError fix already applied to Hub.request's success path. row_id (both events and snapshot rows) and a snapshot row's origin_device_id were the only fields in the whole pull-shape validation family still presence-checked only, unlike every sibling field - closing that gap. cmd_restore's snapshot-apply loop was missing the sessions-first ordering _sync_once already has; apply_replica_row's wake=False branch depends on the parent session row already being present to correctly attribute ownership of session mail.
…new RecursionError test deterministic. The sessions-first sort added to cmd_restore's snapshot-apply loop was based on an incorrect premise: the "parent session" row DESIGN.md bundles with inbox mail is the sender's session (the activity's own session_id), not the recipient session apply_replica_row's wake path actually checks ownership of via _owns_session(to_session) - and that recipient session, being this device's own, can only ever arrive via own_events (which always fully precedes snapshot processing), never via the replica-row path at all regardless of ordering. Reverting rather than keeping harmless code with a false justification. Separately, the new websocket RecursionError regression test relied on a real 1,000,000-character nested JSON string actually overflowing CPython's C decoder - both interpreter/platform-dependent and, since the fake websocket only ever yields one frame, unable to distinguish "RecursionError was caught" from any other path reaching the same fallthrough. Replaced with a deterministic json.loads monkeypatch, matching the equivalent test in test_hub.py.
…md_restore mirror was reverted. No comment or history anywhere justifies it, and the same mechanism that disproved the cmd_restore copy applies identically here: apply_replica_row unconditionally skips any row this device itself owns regardless of position, so a device's own session row can only ever arrive via own_events (which fully precedes snapshot processing in both functions), never via this replica-row path - independent of whether wake is True or False, and independent of which of inbox/pings/subscriptions it came from.
…rd length. _OTEL_SPAN_ID required exactly 16 hex chars, leaving a malformed or non-conformant span_id of 17-19 chars unredacted - it falls between that exact match and the generic _HEX fallback's 20-char floor. The label match already does the real specificity work here, so matching whatever hex value actually follows it is both simpler and closes the gap; applied the same change to trace_id and traceparent for consistency.
…agent knock. README.md and DESIGN.md's own daemon-installation paragraph already mention it; the CLI-surface catalog entry was the one place still missing it.
…_restore and _sync_once. Events were fully validated and applied - a complete phase including the store writes and origin-cursor advance - before snapshot validation even began. A malformed snapshot paired with well-formed events in the same response let those events durably commit before dying on the snapshot - the same partial-apply bug already fixed twice (once within the events list, once within the snapshots list), recurring one level up between the two lists themselves. Also drops an unused monkeypatch parameter from two existing websocket subscription tests.
The round-11 fix's comment said "every event and snapshot is validated above before either is applied" - true only for shape validation. Semantic checks (an origin_seq gap, a foreign row-ownership conflict) can only be evaluated against live store state at apply time, inside each item's own transaction, so a shape-valid batch can still partially commit before a later semantic conflict is discovered. Scoped the comment accurately instead of overclaiming; full atomicity would need one transaction spanning the whole apply loop, tracked separately as a bigger change than a validation fix.
|
EN: DE: |
|
EN: The final scope also includes substantial validation of hub pull/restore responses, beyond the two original fixes. During conflict resolution, preserve and check compatibility with the newer job/store and CLI changes on develop, and keep the fingerprint and synchronization regression coverage. Existing green CI and the author's review summary describe the current PR head; they do not establish correctness of the eventual conflict resolution. |
EN:
Fixes two bugs found while live-testing the error-catching bot against real production API logs: a W3C
span_idwas leaking into the dedup fingerprint hash, and newly-created local activity could sit unpushed to the hub indefinitely. Fixing the second bug required calling the hub-pull/restore path more often than before, which surfaced a series of gaps in how that path handles a malformed or adversarial hub response — field shapes, timestamp formats, event ownership, and batch-apply ordering are now all validated, with a broad safety net for anything still unanticipated. Both original bugs and every hardening gap found along the way are fixed with regression tests; full suite passes.DE:
Behebt zwei Fehler, die beim Live-Test des Fehler-Erfassungs-Bots gegen echte Produktions-API-Logs gefunden wurden: Eine W3C-
span_idsickerte in den Dedup-Fingerprint-Hash, und neu erstellte lokale Aktivität konnte unbegrenzt ungepusht zum Hub bleiben. Die Behebung des zweiten Fehlers erforderte, den Hub-Pull/Restore-Pfad häufiger als zuvor aufzurufen, was eine Reihe von Lücken offenlegte, wie dieser Pfad mit einer fehlerhaften oder böswilligen Hub-Antwort umgeht — Feldformen, Zeitstempel-Formate, Event-Eigentümerschaft und die Anwendungsreihenfolge von Batches sind jetzt geprüft, mit einem breiten Sicherheitsnetz für alles noch Unvorhergesehene. Beide ursprünglichen Fehler und jede unterwegs gefundene Härtungslücke sind mit Regressionstests behoben; die volle Suite ist grün.Details
Fix 1 — OTel
span_idleaks into the dedup fingerprint (src/agent_cli/errors.py)redact()already contains_HEX = re.compile(r"\b[a-fA-F0-9]{20,}\b"), which already redacts a 32-character OTeltrace_id(32 ≥ 20). A W3Cspan_idis exactly 16 hex characters — under that 20-char floor — so it passed throughredact()unredacted and survivedstack_sig()'s normalization, landing raw in the SHA-256 input. Two log lines for the same recurring error, differing only by a fresh randomspan_idper occurrence, produced two different fingerprints instead of one row with an incrementing count.Verified against a real-world case: the same client-side error hit the same account/route 4 times in 7 minutes and got 4 different fingerprints instead of one row with
count=4.Added targeted, labeled regexes (
_OTEL_TRACE_ID,_OTEL_SPAN_ID, case-insensitive, plus_OTEL_TRACEPARENTfor the W3Ctraceparentheader) applied insideredact(), rather than lowering_HEX's threshold — a blanket threshold change risks redacting unrelated short hex tokens elsewhere in a log line. Each regex captures the label/separator/optional-quote prefix and matches whatever hex value actually follows it (not a fixed standard length, so a malformed or non-conformant id doesn't slip through), covering logfmt, colon, JSON, quoted-value, and escaped-JSON shapes alike, substituting only the value so the line still reads naturally in whatever format it came in._HEX,stack_sig(),_UUID, and_DIGITSare unchanged. DESIGN.md §21.2 documents that this redaction runs separately from the$AGENT_HOME-configured secret/PII redaction.New tests:
redact()-level assertions that trace/span ids are stripped across every shape and length, and an end-to-end test proving two synthetic lines with the same service/class/message but different trace/span ids dedupe into oneerror.seenrow with an incrementing count viascan_errors, instead of creating a second row.Fix 2 — new local activity isn't pushed to the hub until something else triggers a sync (
src/agent_cli/main.py)_sync_once(store)is the only function that pushes locally-pending events to the hub. It was called only once per websocket (re)connection attempt incmd_sync's reconnect loop, and inside the live websocket session in response to an inbound hub message — never in response to a local write.cmd_knock's scan loop (which creates/enricheserror.seenand other activity rows) never touched the hub-push path at all, so on a stable, idlesync --followconnection a freshly created local row could sit unpushed indefinitely.Extracted the scan-cycle body (previously inline inside
cmd_knock's polling block) into_knock_scan_cycle(store, run_argv)and added a call to_sync_once(store)at the end of it, gated on the device being paired.Hardening the hub-pull/restore path (
src/agent_cli/main.py,src/agent_cli/store.py,src/agent_cli/hub.py)Calling
_sync_oncefrom a new place meant it now runs far more often against a hub response this client can't fully trust the shape of — the same is true ofagent restore, which shares the identical data shape but had no hardening at all before this PR. Both are now covered by a shared pair of validators (_coerce_pull_event/_check_pull_row), each converting a shape error toHubError(retryable, for the background daemon paths) ordie()(fail loud, for the one-shot CLI command a human is watching):tableis one this client actually owns,payloadis an object,opisinsert/update/delete,row_idand (for rows)origin_device_idare non-empty strings,occurred_at/updated_atactually parse as a timestamp (any RFC 3339 form, not a fixed standard length or case), andorigin_seqis coerced to a genuine whole number (rejecting a bool, a fractional value, or an out-of-range value). Without this, a malformed field wouldn't raise at write time at all — it would commit as-is and only surface later, on some future read of that whole table or a later conflicting write to that same row.origin_device_idmust match this device's own id: DESIGN.md's sync contract is "own events, gapless" — foreign-origin data arrives as row snapshots, never as an event — so a pulled/restored event claiming a foreign origin is itself a malformed response, not a normal case to accept.isinstance/truthy check.Hub.requestconverts an invalid-JSON response body — including one so deeply nested it overflows the JSON decoder's own recursion guard — intoHubErrorinstead of letting a raw exception escape; the same fix is applied everywhere else a response body gets JSON-decoded (the HTTP-error detail path, the live websocket message loop).typefield being unhashable trips afrozensetmembership check several calls deep insidestore.py), and chasing every possible malformed shape one field at a time doesn't converge.store.apply_remote/apply_replica_roware each wrapped in a narrowexcept Exception → raise HubErroras a backstop —HubError/StoreErrorareSystemExitsubclasses, notExceptionsubclasses, so they pass through unaffected; anything else unanticipated becomes a catchable, loggedHubErrorinstead of an uncaught crash.mark_pushed()now has the same monotonic guard its siblingmark_origin()already had, so two concurrent callers can't regress the push cursor backwards.Verification:
python3 -m pytest tests/ -q→ full suite passes.