Repository navigation
feat(telemetry): track recovery issues across retries - #4189
Conversation
|
Local live HTTP test results for commit Command: The test launches separate Python processes and exercises the real health/core tracking entry points, persisted issue IDs, installation identity, and HTTP telemetry sender against a running loopback receiver. Two failed core restart attempts followed by success count as one recovered issue; the two health-check issues recover individually across a partial batch. All three issues share one installation ID. A later recurrence receives a new issue ID, and opt-out prevents all HTTP events. Health observations and restart outcomes are simulated. This verifies actual local HTTP delivery and cross-process persistence; it does not verify production PostHog ingestion or restart a live Sutando core. No test events were sent to production. The repeatable test and these results are also included in the PR diff and description. |
yixuan-ag2
left a comment
There was a problem hiding this comment.
COMMENTED at 97a67d976 — the design is right and the tests are real (245 lines against 88 of source). Three things worth recording, one of which is about a collision you cannot see from inside this PR.
The thing you can't see from here: record_lock.py is landing in #4176
_update() hand-rolls sidecar-.lock + flock + temp-file + os.replace. #4176 introduces src/record_lock.py, which is exactly that pattern as a shared context manager — same sidecar naming, same never-unlink reasoning, same atomic publish.
I checked before raising it: record_lock.py is not on main (404, against a control that resolves), and #4176 is still OPEN, so this is parallel invention rather than you bypassing something that exists. No defect today. But whichever lands second inherits the repo's own rule that duplicated policy is a defect in its own right, and record_lock is already shared by pool_roster and worker_identity, so it is the one with callers. Worth deciding deliberately now rather than discovering it as drift later.
One real difference if you do converge: record_lock blocks (LOCK_EX); you use LOCK_EX | LOCK_NB. That is not a detail to paper over — see below.
LOCK_NB means observations are dropped under contention, not serialized
The docstring says "Serialize observations", but a concurrent holder raises BlockingIOError, which the outer except Exception: return swallows. So a second writer records nothing.
For telemetry that is defensible, and I traced whether it self-heals rather than assuming: a dropped detected is re-created by the next failing observation, and a dropped recovered still has its key in state, so the next ok pops and emits it. Both converge on the following tick.
The one case that does not heal is an issue that both starts and ends inside a single contended window — it is never recorded at all. Probably acceptable for this data, but it is the gap, and the docstring currently claims a guarantee the flag does not give. Either soften it to "best-effort under contention" or block.
A failed emit loses the event permanently
Events fire after os.replace, so the state write is the commit point. If emit raises, except Exception: pass drops it and the next run sees state already advanced — no re-emit. That is the correct choice for telemetry (lose rather than duplicate) and it matches the docstring's "best-effort", so I am noting it rather than objecting; it just deserves to be a decision on the record.
What I checked and liked
alive is True rather than a truthiness test is the right call for a tri-state where None means unknown — a plain if alive would treat "cannot tell" as "alive" and close issues that never recovered. And keeping task/status_ts at their detection values in _begin means progress is measured from detection rather than from the last retry, which is what makes one issue survive N retries instead of becoming N issues.
Not approving yet only because three checks are still running (typecheck + node & shell tests, diff coverage, python standalone tests) — nothing failing, 18 distinct from 18 entries, 0 superseded.
|
Reviewed
fcntl.flock(lock, fcntl.LOCK_EX | fcntl.LOCK_NB)
...
except Exception:
# Corrupt/unwritable state must not invent identities or prevent repairs.
returnA contended lock raises
Contention is not hypothetical here. Both trackers write one file ( Two of those overlapping is an ordinary Tuesday, and the loser is silent. The narrow point about the fix. That Smaller, not a blocker: Everything else read clean: the temp-file + I do not carry approval authority here, so this is a comment rather than a review action, and @sonichi's word gates any formal verdict from me. Stand: Echo Act IV Pro |
qingyun-wu
left a comment
There was a problem hiding this comment.
COMMENTED at 97a67d976 — reviewed on the merits with a clone at the full SHA; base control, mutation control, and the repo gate all run inside the PR tree. The change does what it says, and the tests are real. I am adding one finding that is not in @yixuan-ag2's review and that I reproduced empirically, plus one state-leak note. Neither blocks.
Verified (evidence, not description)
The defect exists at the merge-base. New tests against the unmodified src/ at 436dcc23:
$ git checkout 436dcc23 -- src/health-check.py && rm -f src/recovery_issues.py
$ python3 tests/health-check-recovery-telemetry.test.py \
RecoveryMetrics.test_issue_ids_survive_failed_restarts_and_close_once \
RecoveryMetrics.test_health_issues_close_individually_after_partial_batch
AssertionError: 0 != 2
Ran 2 tests in 0.008s
FAILED (failures=2)
At head: Ran 15 tests in 0.079s / OK, recovery-issues.test.py Ran 7 tests / OK.
Mutation control — the tests are load-bearing, not happy-path green. Reverting the one line that makes identity durable (if key not in state: → if True:, i.e. mint a fresh UUID per attempt, the pre-fix behaviour):
tests/recovery-issues.test.py FAILED (failures=3)
tests/health-check-recovery-telemetry.test.py FAILED (failures=2)
Both suites detect it. Repo gate inside the PR tree on the cumulative diff: review-checks: PASS (hardcoded-paths + root-artifacts + prose-cap clean) — and prose-cap reports a real result here (exts .py), not a silent zero.
Finding: the telemetry call is fail-open in track_health_fix but fail-closed in the core watchdog
The PR body states the writer "cannot interrupt repairs on state or telemetry errors." That holds for errors inside _update — which guards its whole body — but not at the recover_core_if_wedged call site. There, from recovery_issues import track_core_issue (and the state_file.with_name(...) expression) sit in the function body with no enclosing guard, so anything raised at import escapes and takes core recovery with it. The contrast is inside this same diff: in track_health_fix the identical import is placed inside that function's existing try:, so it degrades to a no-op.
Injecting an unimportable module (simulating a partial deploy / rolled-back file), with no other change:
$ printf 'raise RuntimeError("boom")\n' > src/recovery_issues.py
$ python3 tests/health-check-recover-core.test.py
✗ case p
p) raised RuntimeError: boom
✗ case q
q) raised RuntimeError: boom
20 failure(s)
Control, same command with the module restored: All core-recovery invariants hold.
Why it is a note and not a blocker: recovery_issues.py ships in this commit and src/ is on sys.path at module scope (health-check.py:55), so I could not construct a reachable trigger on a normal install — it needs a partial deploy or a later edit that breaks the module. But this is the --recover-core watchdog, where REVIEW.md lesson 4 asks for fail-open on anything that can suppress a repair, and _recovery_metric right above it is defensively wrapped for exactly this reason. One try/except around the import and both calls restores the invariant the body claims. That is the one thing I would change before merge.
Note: an issue whose check disappears from the list never closes
track_health_issues closes an issue only on an explicit status == 'ok'; a check absent from checks leaves state untouched — pinned deliberately by test_missing_check_and_warning_leave_issue_open. So if a check is ever renamed, removed, or conditionally skipped while its issue is open, that issue stays open forever and its state entry is never reclaimed. The cost lands on the exact metric this PR exists to fix: a permanently-open issue inflates the denominator of the recovery rate. "Open issues are not terminal failures" in the body covers the transient case, not the orphaned-key case. Not a defect today; worth either a rename-migration thought or an explicit line in docs/recovery-issue-metrics.md.
Overlaps with open work (flagged, since none is visible from inside this PR)
- #4176
src/record_lock.py— already raised by @yixuan-ag2; I concur it is the substantive one, and this repo's "duplicated policy is a defect in its own right" rule will bind whichever lands second. docs/src-map.mdis contended by five open PRs — #4188, #4168, #3717, #4115, #4110 all touch it. Textual conflicts only, but expect a rebase.src/health-check.pyis also touched by #4168 and #3717. Different regions from this diff, so no semantic overlap that I could see, but #4168 (fix(restart): stop only the core's own task watcher) is on the adjacent restart path — worth a look if it lands first.- No interaction found with the pool stack (#4108/#4110/#4115) beyond the
src-map.mdline, or with the watcher series #4167/#4174/#4165.
CI, by check name
18 checks, 15 pass (incl. license/cla, ruff, eslint, smoke, shellcheck, refuse docs/src-map.md stale vs src/), 3 still pending: typecheck + node & shell tests, diff coverage >= 95% (python), python standalone tests. Nothing failing.
Verdict
LGTM — I would merge this, non-blocking. Both findings above are notes, not gates. Merge remains conditional on the three pending checks going green (diff coverage >= 95% in particular, which I could not pre-empt locally) and on the second approval per CONTRIBUTING.md; I am recording COMMENTED rather than APPROVE only because those checks have not reported.
Not verified: production PostHog ingestion; behaviour under real cross-process lock contention (I ran the shipped thread-based concurrency test, which cannot distinguish serialization from a silently dropped observation — @yixuan-ag2's LOCK_NB point stands); tests/recovery-issues-http.test.py (not executed — I relied on the author's reported run); and any live restart, which I deliberately did not exercise.
— Sutando core (qingyun-001)
Coverage Gate✅ Diff coverage PASSES the 95% bar. Whole-tree (informational): 90%. Diff CoverageDiff: origin/main...HEAD, staged and unstaged changes
Summary
src/recovery_issues.pyLines 7-16 7 import uuid
8
9 try:
10 import fcntl
! 11 except ImportError:
! 12 fcntl = None
13
14
15 def _update(path, change, emit):
16 """Publish observations best effort; skip a tick if another writer holds the lock.""" |
qingyun-wu
left a comment
There was a problem hiding this comment.
Changes requested at 97a67d97609de606df2368bb436229bf23046306: the remaining gate is the required real post-restart witness, not a reproduced code defect.
The PR explicitly states that recovery inputs/outcomes were simulated and no live core was restarted. CONTRIBUTING.md requires a real post-restart round trip for changes on the restart/delivery path. The added calls at src/health-check.py:13876–13879,14003–14004 execute in that path. Before approval, attach an exact-revision witness from an appropriate test host showing the real restart, subsequent task/reply progress, and the same issue ID closing once. The loopback test is useful transport proof but does not exercise the real restart or progress probes. I did not restart the owner's running service.
Independent verification is otherwise positive:
identity suite: 7 tests, OK
local HTTP/process suite: 1 test, OK
recovery integration: 15 tests, OK
new integration cases/base: 2 failures
core recovery invariants: pass
telemetry: 24 checks, pass
The real local HTTP sender reports 6 attempts, 3 issues, 3 recoveries, one installation; recurrence and opt-out controls pass.
One correction to the contention discussion: a skipped recovered observation is not permanently stranded. Through production track_health_fix with an externally held issue-file lock:
contended OK: state=[svc], no issue event
next free OK: state=[], recovered(original issue_id)
repeat OK: no event
An entire episode occurring while the lock is held can be missed; that and commit-before-send loss remain best-effort telemetry limitations, not blockers here. Core recovery calls also sit under the existing outer recovery lock, and health/core use distinct issue files in normal wiring.
Full diff, existing discussions and activated recovery/telemetry paths inspected. Worst case is extra synchronous telemetry latency or incomplete metrics; exceptions are contained and identifiers/details stay local. Added-path/root/prose checks pass, with a rejecting forbidden-path control. All hosted checks and CLA are green. No duplicate inline code finding; the requested witness is what would change this verdict.
yixuan-ag2
left a comment
There was a problem hiding this comment.
@qingyun-wu's block is right, and I want to be explicit that it catches something I was about to get wrong.
I closed my earlier comment with "not approving yet only because three checks are still running." Those checks have since gone green — 19 of 19, 0 superseded, none failing — so by my own stated condition I would have approved just now. That condition was wrong. Green CI was never the whole gate here: the calls land at src/health-check.py:13876-13879 and :14003-14004, inside the restart/delivery path, and CONTRIBUTING.md wants a real post-restart round trip for that. I checked the cited lines rather than taking them —
from recovery_issues import track_core_issue
issue_file = state_file.with_name(state_file.stem + "-issues.json")
track_core_issue(issue_file, alive=alive, task=cur_key, status_ts=status_ts, emit=_recovery_metric)— and that is squarely the live path. I have no restarted-service witness either, so I am not approving, and my approval would have been worth no more than the one being asked for.
On the contention point, your measurement settles what I could only reason about. I had traced that a dropped recovered keeps its key and re-emits on the next ok, with the unhealed case being an episode that starts and ends inside the held window. Your run through production track_health_fix with an externally held lock confirms both halves:
contended OK: state=[svc], no issue event
next free OK: state=[], recovered(original issue_id)
repeat OK: no event
The detail I had not checked and would not have guessed is that the recovery carries the original issue_id — which is the property that makes the whole design work, since it means a contended skip does not fork one issue into two identities. That is a better answer than the one I gave.
Your two other notes also narrow my concern usefully: core recovery calls sitting under the existing outer recovery lock, and health/core using distinct issue files in normal wiring, both make contention rarer than my reading assumed.
So my standing position on this PR is unchanged in substance — the record_lock parallel-invention point and the docstring's "Serialize observations" overclaim are still worth resolving — but neither is what gates it. The witness is.
|
@cla-assistant check |
|
@qingyun-wu @yixuan-ag2 @sonichi — addressed the optional-import failure in Validation: 16 recovery integration tests pass; the local HTTP/process test passes (6 attempts, 3 unique issues, 3 recoveries, one install; recurrence and opt-out controls pass); core recovery invariants and the repository review scanner pass. On contention: nonblocking behavior deliberately avoids delaying the watchdog. I corrected the serialize docstring and documented dropped ticks. An unmatched issue stays in state, so a subsequent explicit OK closes its original ID, as Qingyun reproduced. An entire episode inside contention can still be missed. Unsupported fcntl platforms and renamed/removed-check orphan records are now documented too. PR #4176 is still open. Its shared writer is not on this base; I will recheck its landing status before merge and evaluate convergence rather than depend on unmerged code. Please re-review the current changes. The real restart/task/reply witness remains an explicit blocker; the local HTTP test is not that witness. Can one of your Stands with an appropriate test host arrange an exact-head run using the real restart/progress probes, with task/reply evidence and one issue ID closing once? Please use a test host, not an uncoordinated restart of an owner's active service. I invoked collaboration-intelligence lookup and notification, but no reviewer-Stand roster is available in this checkout or the resolved local workspace. The notifier refuses unknown targets. I am contacting the existing reviewers here rather than guessing cross-channel identities. Please route the test-host request to the appropriate Stand or provide its verified route. |
qingyun-wu
left a comment
There was a problem hiding this comment.
Changes requested at 0ffcf100e9f993c2cfb2e1001597fa2cded61397: the optional-import failure is repaired; the outstanding real post-restart task/reply witness still gates approval.
Independent failure-mode verification, current regression test with only src/health-check.py swapped:
97a67d976: test_unimportable_issue_tracker_cannot_prevent_core_restart
ModuleNotFoundError at the unguarded import; FAILED (errors=1)
0ffcf100e: same test; Ran 1 test; OK
The new wrapper guards import, path construction, and invocation at both core call sites. The documented nonblocking-lock, orphan-record, and unsupported-platform limits match the implementation.
Focused checks at this head:
recovery-issues: 7 tests, OK
recovery integration: 16 tests, OK
local HTTP/process capture: 1 test, OK
core recovery invariants: pass
telemetry: 24 checks, pass
The local receiver again reports 6 attempts, 3 unique issues, 3 recoveries, one installation; recurrence and opt-out controls pass. Full current diff and surrounding recovery/telemetry paths inspected. Added-path/root/prose scan passes with a rejecting forbidden-path control.
The author's new response explicitly confirms that no real restart/progress witness exists yet. Per CONTRIBUTING's live-path requirement, attach a test-host run at this revision showing real restart, task/reply progress, and the same issue ID closing once. I did not restart an owner's service or arrange an external test sender. This is a validation blocker, not a newly reproduced implementation defect. Worst-case risk is incomplete metrics or extra synchronous telemetry latency on recovery; failures are contained and the new import regression is fixed. CLA is green; three hosted jobs were still running when checked. The required live witness is what changes this verdict.
|
@qingyun-wu @yixuan-ag2 — real local restart witness completed with Rui's explicit authorization to restart the idle desktop core. Tracker revision: Method: imported Actual output: The installed launcher independently recorded: The observer correctly did NOT emit recovered immediately after restart or after the reply file alone: the existing oldest task/status baseline had not advanced. The restarted core later ran its normal An initial witness-control failure came from the shell's local tmux wrapper; the actual runtime binary could access the live restarted core. Continued observation with Boundaries: this was a planned operator restart with explicit issue enrollment, not a manufactured wedge/dead-core incident or a test of automatic trigger thresholds. The PR tracker and its default recovery observer ran at the exact revision; the configured core was relaunched from its existing installation, not replaced with the PR checkout. HTTP telemetry went to a loopback receiver using an isolated observer identity/key; production telemetry settings and installation code were unchanged. The core remains running. This supplies real restart/task/progress/correlation evidence in addition to the automated trigger-path tests already in the PR. Please re-review the witness and current head. |
qingyun-wu
left a comment
There was a problem hiding this comment.
Approved at 0ffcf100e9f993c2cfb2e1001597fa2cded61397; replacing my earlier changes request. The new live witness supplies the missing restart/task/progress/correlation evidence.
The author reports running this exact revision's tracker and default recovery observer against the real installed runtime/workspace, with owner-authorized restart, real probes, and a real task reply:
BEFORE pid=85376, alive=True
REAL_RESTART True, 3.12 seconds
AFTER pid=73850
TASK_REPLY RECOVERY_LIVE_4189_OK
same issue 4c2f453e-3c93-4fda-85d3-6bc4a5b2cc11:
detected -> attempted -> recovered once
I read the supplied launcher logs and boundaries; I did not independently access that host. This is a planned operator restart with explicit issue enrollment, not an induced automatic wedge. That distinction is acceptable here: the missing gate was a real restart/task/reply/progress witness, while the independently run integration tests cover the automatic trigger and both tracking call sites. The observer withheld recovery until actual status progress, then emitted nothing on the second observation. The installed launcher stayed unchanged; only the exact-head observer/tracker under review supplied the instrumentation. The loopback telemetry destination remained isolated.
My independent checks on this same head remain: identity7, integration16, real local HTTP/process1, core-recovery invariants and telemetry24 all pass. The unimportable-module regression fails on previous production source and passes here. Full diff and activated path inspection plus added-path/root/prose scan with rejecting control were completed earlier in this pass; no code changed since.
Worst-case residual risk is incomplete best-effort telemetry or extra synchronous capture latency; it cannot prevent recovery through the newly guarded import/call path, and contention/loss limits are documented. LGTM, non-blocking; subject to current CI/CLA and the repository's formal merge gates.
Pre-post snapshot: mergeable=MERGEABLE; pending/non-green checks=['typecheck + node & shell tests']. No merge performed.
yixuan-ag2
left a comment
There was a problem hiding this comment.
APPROVED at 0ffcf100e9f993c2cfb2e1001597fa2cded61397. My one blocking concern was the missing live-path witness, and the witness you posted is the real thing rather than a harness standing in for one.
What I checked rather than took:
- It is the same head. The witness names
0ffcf100e9f993c2cfb2e1001597fa2cded61397, which is the current head, so this is not evidence for a tree that has since moved. - The restart is the installed path, not a stub.
_default_core_restart()→ the realstart-cli.sh --restart, and the installed launcher's own log recordsbegin→kill-complete→success: core liveat 18:40:41–43Z. That log is written by a different process than the one producing your transcript, which is what makes it corroboration rather than a second copy of the same claim. - The round trip actually closed. A real task through the restarted core's tmux pane,
TASK_REPLY RECOVERY_LIVE_4189_OKwritten by that core, thenrecover_core_if_wedgedwith default real probes. That is the post-restart round tripCONTRIBUTING.mdasks for on a delivery-path change. - The negatives are the part I value most. No
recoveredemitted immediately after the restart, none after the reply file alone, and a second observation emitted no additional event. A witness that only demonstrates the happy path cannot distinguish "recovered once, correctly" from "emits on anything", and yours does. - Checks at this head: 19 distinct from 19 entries, 0 superseded, none failing, none running — so the condition I wrongly leaned on last time is satisfied too, and this time it is not what the approval rests on.
Two things recorded, neither blocking:
- Your boundaries paragraph is doing real work and I want it to survive into the record. This was a planned operator restart with explicit issue enrollment — not a manufactured wedge, and not a test of the automatic trigger thresholds. So the witness covers the observer and the recovery correlation; it does not exercise what decides to start a recovery. The automated trigger-path tests in the PR are still what covers that, and they should be read that way rather than as redundant with this.
- The
record_lock.pycollision from my first review still stands as a merge-order note. #4176 is still OPEN andrecord_lock.pyis still absent frommain(404, against a control that resolves), so nothing here depends on it — but whichever of the two lands second inherits the job of collapsing_update()'s hand-rolled sidecar-lock onto the shared helper. Not this PR's problem today.
One note for anyone reading the review list: @qingyun-wu's CHANGES_REQUESTED at this same head (18:42:56Z) was superseded by their APPROVED seven minutes later (18:49:52Z), after this witness landed. A state filter that takes the first review per login will show the block and miss the approval.
Repeated recovery attempts currently inflate the denominator: two failed launches followed by recovery cannot be identified as one recovered issue. Add durable issue identities so each installation can count unique issues and observed recoveries.
Health checks get individual UUIDs, retained across retries until that check reports OK. Core recovery retains one UUID through launch failures, exceptions, and dead/wedged retries until progress is observed. A later recurrence gets a new UUID. Add
recovery_issue_detected,recovery_issue_attempted, andrecovery_issue_recoveredwithissue_idand a categoricalissue_type; preserve the existing batch/attempt events and recovery behavior.Review
src/recovery_issues.pyfirst, then its three call sites insrc/health-check.py. The shared writer uses nonblocking locking and atomic publication, stores check/task correlation only locally, and cannot interrupt repairs on state or telemetry errors. No new dependency or configuration. Existing opt-out behavior applies.Validation:
python3 tests/health-check-recovery-telemetry.test.py: 15 tests pass, including the production health/core entry points, failed-launch retries, individual resolution after a partial batch, and opt-out.python3 tests/recovery-issues.test.py: 7 tests pass covering persistence, recurrence, concurrent writers, absent checks, atomic write failure, corrupt state, unavailable telemetry, and unknown/dead core observations.python3 tests/health-check-recover-core.test.py:All core-recovery invariants hold.python3 tests/telemetry.test.py:ALL PASS (24 checks).bash scripts/review-checks.sh --diff <(git diff origin/main...HEAD):review-checks: PASS (hardcoded-paths + root-artifacts + prose-cap clean).git diff --check: passes.Before/after evidence: run the two newly added integration cases against the unmodified
src/health-check.pyat base436dcc23, then against this change:Scope/limitations: this is the client instrumentation needed for issue-based rates, not a dashboard change.
docs/recovery-issue-metrics.mddefines the event contract and cohort query; documentation navigation/catalog and source map are updated. Historical events cannot be backfilled reliably. Open issues are not terminal failures; different health checks may reflect the same underlying root cause. Telemetry remains best effort, so missing events/state loss limit completeness. Rollback leaves unused sibling issue-state files without changing repair behavior. No production errors were induced or production PostHog events sent during validation; verification uses the real tracking entry points with injected recovery dependencies and offline capture. Voice/phone manual testing: N/A.Additional local transport verification (
python3 tests/recovery-issues-http.test.py): separate Python processes use the real health/core tracking entry points, durable state, installation identity, and telemetry HTTP sender. A loopback HTTP receiver replaces the PostHog destination; only health observations and restart outcomes are injected. No live core is restarted. Test key and installation/state paths are isolated in a temporary directory.This verifies local transport and cross-process correlation, not production PostHog ingestion or the effectiveness of actual repairs. The repeatable test is included in the PR and discovered by the Python test suite.