Skip to content

Stale pipeline tracker from unclosed kitchen silently disables step-completion marking — false DEPENDENCY UNMET aborts pipeline; _fmt_run_skill drops error field #4293

Description

@Trecek

Incident

The remediation pipeline for #4291 (kitchen c40ff8ac-2a21-4aed-bd23-f8c97c7c3563, autoskillit v0.10.882, run dir remediation-20260718-192507-037270, 2026-07-18 ~19:25–19:45 local) aborted at the review_approach step with an apparent opaque "tool-level failure" — routed on_failure: release_issue_failureescalate_stop, releasing the issue with the fail label. The rectify step had succeeded seven seconds earlier (session b38c02c9, 1214 s, success: true, exit_code: 0, 2-part plan produced).

No skill session was ever spawned for review_approach: no session record, no no_session_* directory, no output artifacts. The MCP server denied the run_skill call pre-flight. The raw envelope (preserved only in the transcript's mcpMeta.structuredContent, invisible to the orchestrator model):

{"success": false, "is_error": true, "error": "DEPENDENCY UNMET: Step 'review_approach' requires ['rectify'] to complete first. Pipeline 'c40ff8ac-2a21-4aed-bd23-f8c97c7c3563': {'rectify': 'pending'}."}

Root Cause — two co-defects

Defect A: stale pipeline tracker silently disables step-completion marking

  • open_kitchen auto-creates {project_dir}/.autoskillit/temp/pipeline_tracker/{kitchen_id}.json (_auto_init_pipeline_tracker, src/autoskillit/server/tools/tools_kitchen.py:330-383; introduced in 1e2670ec7 Server-authoritative payload delivery for open_kitchen output cap #4259, 2026-07-14).
  • Tracker cleanup exists only in _close_kitchen_handler (tools_kitchen.py:533-540). The previous kitchen that day (fb9097f4, 17:13–19:02, issues review-pr: subagent prompts omit annotated diff → findings return line:null → inline comments dropped #4289/Rectify: Inline Content in Subagent Prompts #4292) was never closed — its conversation ended via CLI /exit at 19:23:07 local with zero close_kitchen calls in the transcript (18f10c72-8e73-40d8-9fd0-af8607319aaa.jsonl), seconds before the new kitchen auto-initialized its own tracker — so its tracker file survived.
  • Marking a step complete is done exclusively by the client-side PostToolUse hook src/autoskillit/hooks/pipeline_step_post_hook.pyrecord_pipeline_step supports only init/status ops (tools_pipeline_tracker.py:108), and run_skill never writes step status server-side.
  • The hook resolves its target tracker via discover_single_tracker_order_id (src/autoskillit/hooks/_hook_utils.py:21-30), which returns "" unless exactly one *.json exists in the tracker dir. With two files present (stale fb9097f4…json + live c40ff8ac…json — both directly observed on disk), the hook silently exits (pipeline_step_post_hook.py:70-72) without marking anything.
  • Result: rectify stayed "pending" despite succeeding; the server-side check _check_pipeline_deps (src/autoskillit/server/tools/tools_execution.py:190-241) then correctly denied review_approach against wrong state. The tracker's only dependency edge is {"review_approach": ["rectify"]} — which is why the pipeline failed at exactly this step and nowhere earlier.
  • Additional silently-degraded surface: fleet/_checkpoint_bridge.py:31 (checkpoint_from_tracker) derives resume checkpoints from tracker complete statuses — with the recorder disabled, no step is ever complete, so checkpoint derivation yields nothing and fleet resume degrades silently for any run in this state.

Enforcement asymmetry (the design flaw): _check_pipeline_deps scopes trackers by kitchen_id (other-kitchen files are invisible to it), while the recorder hook scopes by "exactly one file in the directory" (any kitchen). The stale file is invisible to the enforcer but fatal to the recorder. Notably, 1e2670ec7 did harden the check-time server layer against multi-tracker ambiguity (fail-closed; “REQ-070” is a PR-narrative label, not a code artifact; enforced by tests/server/test_pipeline_tracker.py:335 test_kitchen_scoped_fallback_requires_order_id_with_multiple_pipelines) but left the record-time hook layer (and the advisory guards/pipeline_step_guard.py) silently fail-open — an incomplete application of its own design pattern within a single commit.

Defect B: _fmt_run_skill drops the error field, blinding the orchestrator

The PostToolUse formatter pretty_output_hook rewrote the MCP output via updatedMCPToolOutput. _fmt_run_skill (src/autoskillit/hooks/formatters/_fmt_execution.py:41-108) renders session_id/exit_code/needs_retry/retry_reason/result/stderr but never data["error"] — in either the pipeline or interactive branch. The deny envelope has none of the rendered fields, so the orchestrator model received exactly:

run_skill: FAIL [FAIL]
exit_code:
needs_retry: False

Blinded, it classified an actionable, deterministic state error as an opaque tool-level failure and aborted per recipe routing. Sibling formatter _fmt_test_check (_fmt_execution.py:185-187) renders error correctly — the family applies the pattern inconsistently. This completes the defect family of #3963 (d29a2999c, "_fmt_generic Silent Truncation of Dispatch-Critical Structured Data — PART A ONLY"), whose PART B was never done and excluded run_skill.

Key Evidence

  • Raw deny envelope: orchestrator transcript afa37add-ac21-4083-af6a-d6baed769b1f.jsonl line 67, mcpMeta.structuredContent (quoted above); the model-visible tool_result is the contentless 3-line text; line 68 is the pretty_output_hook rewrite attachment.
  • Two tracker files on disk in .autoskillit/temp/pipeline_tracker/: fb9097f4….json (mtime 19:02, its run_skill steps complete — proving the hook works when its file is alone) and c40ff8ac….json (mtime 19:23, every step pending — hook disabled for the entire run).
  • No "--- Pipeline Tracker ---" banner in rectify's rewritten output (the hook emits one on successful marking; visible in the fb9097f4 pipeline's outputs).
  • Quota guard ruled out: quota_events.jsonl shows approved at 02:44:54Z, 52% utilization vs 85% threshold, for the review-approach call.
  • Recipe wiring ruled out: remediation.yaml:316-333 passes ${{ context.plan_path }} (part_a) — the designed single-plan-path contract; call args verified well-formed in the transcript.
  • feat: replace output_budget_guard with lossless shell capture (#4286) #4288/Rectify: Inline Content in Subagent Prompts #4292 regressions ruled out: Rectify: Inline Content in Subagent Prompts #4292 touches none of the implicated files. feat: replace output_budget_guard with lossless shell capture (#4286) #4288 does modify tools_execution.py and tools_kitchen.py, but its hunks are confined to run_cmd's subprocess-capture logic and an unrelated OutputBudgetPolicyHookPayload TypedDict — it never touches _check_pipeline_deps, _auto_init_pipeline_tracker, or _close_kitchen_handler (function-level exclusion, verified from the diff hunk headers).

Remediation Requirements (proposed approaches)

  1. Make step-completion server-authoritative: run_skill already knows step_name, kitchen_id, and the adjudicated result — mark completion server-side on success, demoting the hook to the cosmetic banner. Removes the client-side single point of silent failure and the scoping asymmetry; matches the ingredient-locks pattern (server authoritative, hook supplemental). Caveat (post-filing validation): server-side marking must replicate the hook's step-name canonicalization (_SUFFIX_RE = r"-\d+$", pipeline_step_post_hook.py:25,74 — folds retried invocations like review-2 onto one entry) and gate on the adjudicated result (success true, not needs_retry) so retries, resumes, and multi-part loops don't mark steps complete prematurely.
  2. Fix tracker lifecycle: prune/archive stale trackers at open_kitchen/_auto_init_pipeline_tracker time. Caveat (post-filing validation): fleet dispatch trackers are keyed by dispatch_id, not kitchen_id (fleet/_api.py passes order_id=dispatch_id and sets AUTOSKILLIT_DISPATCH_ID), and the tracker schema has no liveness/lease field (only kitchen_id/pipeline_id/steps/dependencies/initialized_at) — pruning must read each tracker's internal kitchen_id field (never infer from the filename) and needs a defined liveness rule (e.g., initialized_at age plus an active-dispatch check) before deleting anything. Close-only cleanup is structurally insufficient — kitchens demonstrably end without close_kitchen.
  3. Guarantee failure-envelope fidelity through formatting: _fmt_run_skill (both branches) must render data["error"]; audit all _fmt_* renderers against the {success, is_error, error} envelope shape; add an invariant test that any error field survives every rewrite path.
  4. Make the deny actionable: include recovery guidance in DEPENDENCY UNMET (e.g., verify with record_pipeline_step(op="status"); state may be stale) and/or add explicit sous-chef routing for it — today neither sous-chef SKILL.md nor _prompts.py mentions it.
  5. Regression tests: two-tracker hook scenario; open→no-close→open lifecycle; deny-envelope formatter fidelity; end-to-end rectify → review_approach handoff using the real recipe template and tracker.

Related Issues

Post-Filing Adversarial Validation (2026-07-18)

Two independent adversarial passes (fact-refutation + gap analysis) ran after filing; every piece of evidence they cited was then re-verified firsthand against the actual files and logs.

Survived line-by-line verification: all file:line citations; the raw mcpMeta deny envelope and pretty_output_hook rewrite attachment (transcript lines 67/68); the single tracker-status write site (pipeline_step_post_hook.py:101 — repo-wide grep); the quota approved event (52% vs 85%, 02:44:54Z); commit attributions (8c821e006, 1e2670ec7, d29a2999c with no PART B follow-up); the on-disk two-tracker state; and the enforcement asymmetry (_active_order_ids_for_kitchen filters on the internal kitchen_id field, tools_execution.py:165-186).

Alternative mechanism ruled out: hooks receive the original tool_response independently — pretty_output_hook is registered in a separate matcher group from pipeline_step_post_hook (hooks.json:239-268), and empirically the fb9097f4 pipeline's hook parsed raw JSON successfully while pretty_output_hook was active. The recorder did not fail on parsing; it failed on tracker discovery.

Corrections applied in place above: #4288 exclusion restated at function level; “REQ-070” marked as PR-narrative label; test-gap claim corrected (the multi-tracker unit test exists — the real gaps are the cross-layer integration and deny-envelope formatter fidelity); fleet-aware caveats added to remediation proposals 1–2; checkpoint_from_tracker added as an affected surface; /exit-without-close_kitchen evidence added for the stale tracker's origin.

Investigation

Prior investigation completed interactively. See below for root cause analysis.

Investigation: review_approach "Tool-Level Failure" in Remediation Pipeline for Issue #4291

Date: 2026-07-18
Scope: Why the remediation pipeline (kitchen c40ff8ac-2a21-4aed-bd23-f8c97c7c3563, autoskillit v0.10.882, run dir /home/talon/projects/autoskillit-runs/remediation-20260718-192507-037270) failed at the review_approach step with a tool-level failure immediately after a successful rectify step
Mode: Standard (7 parallel subagents + extensive first-person verification)

Summary

The review_approach step never launched a skill session. The MCP server denied the run_skill call with a structured error — DEPENDENCY UNMET: Step 'review_approach' requires ['rectify'] to complete first. Pipeline 'c40ff8ac-…': {'rectify': 'pending'} — even though rectify had succeeded seconds earlier. Two independent defects combined: (1) a stale pipeline-tracker file from a previous, never-closed kitchen made the client-side step-completion hook's single-tracker discovery ambiguous, so it silently never marked rectify complete; and (2) the pretty-output formatter dropped the error field of the deny envelope, so the orchestrator saw only run_skill: FAIL [FAIL] with no diagnostic and routed to on_failure: release_issue_failureescalate_stop instead of recovering. The root cause is a coherence gap: the server and the hook use different rules to decide "which tracker file applies," and the only component that can mark a step complete is the client-side hook, which fails silent.

Root Cause

Primary defect — stale tracker file disables step-completion marking.

  • open_kitchen auto-initializes a pipeline tracker at {project_dir}/.autoskillit/temp/pipeline_tracker/{kitchen_id}.json (_auto_init_pipeline_tracker, src/autoskillit/server/tools/tools_kitchen.py:330-383, introduced 2026-07-14 in 1e2670ec7 / Server-authoritative payload delivery for open_kitchen output cap #4259).
  • The tracker directory is only cleaned in _close_kitchen_handler (tools_kitchen.py:481, rmtree at :533-540). The previous kitchen that day (fb9097f4, ran 17:13–19:02, issues review-pr: subagent prompts omit annotated diff → findings return line:null → inline comments dropped #4289/Rectify: Inline Content in Subagent Prompts #4292) was never closed, so its tracker file survived.
  • Marking a step complete is done exclusively by the client-side PostToolUse hook src/autoskillit/hooks/pipeline_step_post_hook.py — the record_pipeline_step MCP tool only supports init and status ops (src/autoskillit/server/tools/tools_pipeline_tracker.py:108), and run_skill itself never writes step status.
  • The hook resolves which tracker to update via discover_single_tracker_order_id (src/autoskillit/hooks/_hook_utils.py:21-30), which returns "" unless there is exactly one *.json in the tracker dir. With two files present (fb9097f4…json stale + c40ff8ac…json live — both directly observed on disk), the hook exits silently at pipeline_step_post_hook.py:70-72 without marking anything.
  • Result: rectify stayed "pending" in c40ff8ac…json despite succeeding (its session record shows success: true, exit_code: 0).

Enforcement asymmetry (the latent design flaw). The server-side dependency check _check_pipeline_deps (src/autoskillit/server/tools/tools_execution.py:190-241) scopes the tracker by kitchen_id (kitchen-scoped fallback; other-kitchen files are invisible to it), while the hook scopes by "exactly one file in the directory" (any kitchen). The stale file is therefore invisible to the enforcer but fatal to the recorder — the two components disagree about what makes a tracker ambiguous. The deny at review_approach was the first (and only) dependency edge in the tracker: dependencies == {"review_approach": ["rectify"]} (directly observed), which is why the pipeline sailed through every earlier step and failed exactly here.

Amplifying defect — formatter destroys the error message. The PostToolUse formatter pretty_output_hook (hooks/formatters/pretty_output_hook.py) rewrote the MCP output via updatedMCPToolOutput. Its run_skill renderer _fmt_run_skill (src/autoskillit/hooks/formatters/_fmt_execution.py:41-108) renders session_id, exit_code, needs_retry, retry_reason, result, stderr — but never data["error"], in either the pipeline or interactive branch. The deny envelope {"success": false, "is_error": true, "error": "DEPENDENCY UNMET: …"} has none of the rendered fields, so the orchestrator model received exactly:

run_skill: FAIL [FAIL]
exit_code:
needs_retry: False

The raw envelope (with the full DEPENDENCY UNMET text) is preserved only in the transcript's mcpMeta.structuredContent — which the model does not see. Blinded, the orchestrator classified this as an opaque tool-level failure and followed the recipe route on_failure: release_issue_failureregister_clone_failureescalate_stop. Note the deliberate irony: the deny message itself contains the exact state ({'rectify': 'pending'}) that would have enabled recovery.

Affected Components

  • src/autoskillit/hooks/pipeline_step_post_hook.py:67-77 — sole writer of step complete status; silently no-ops when tracker discovery is ambiguous [SUPPORTED]
  • src/autoskillit/hooks/_hook_utils.py:21-30 (discover_single_tracker_order_id) — "exactly one tracker file" heuristic; returns "" with 2 files present [SUPPORTED]
  • src/autoskillit/server/tools/tools_execution.py:190-241 (_check_pipeline_deps) — kitchen-scoped dependency enforcement that denied the call [SUPPORTED]
  • src/autoskillit/server/tools/tools_kitchen.py:330-383 (_auto_init_pipeline_tracker) — unconditionally creates a per-kitchen tracker at open_kitchen (since Server-authoritative payload delivery for open_kitchen output cap #4259, 2026-07-14) [SUPPORTED]
  • src/autoskillit/server/tools/tools_kitchen.py:481,533-540 (_close_kitchen_handler) — the only tracker cleanup point; unclosed kitchens leak trackers [SUPPORTED]
  • src/autoskillit/hooks/formatters/_fmt_execution.py:41-108 (_fmt_run_skill) — drops the error field of failure envelopes in both pipeline and interactive branches [SUPPORTED]
  • src/autoskillit/server/tools/tools_pipeline_tracker.py (record_pipeline_step) — only init/status ops; no server-side path to mark completion [SUPPORTED]
  • src/autoskillit/hooks/guards/pipeline_step_guard.py — advisory PreToolUse guard sharing the same ambiguous single-tracker discovery; silently no-ops under the same conditions (latent, not causal here) [SUPPORTED]
  • src/autoskillit/recipes/remediation.yaml:316-333 (review_approach step) — wiring is correct and not at fault; ${{ context.plan_path }} (part_a) is the designed single-plan-path contract [SUPPORTED]

Data Flow

  1. open_kitchen (19:23) → _auto_init_pipeline_tracker writes c40ff8ac….json (all steps pending, deps {review_approach: [rectify]}) into {project_dir}/.autoskillit/temp/pipeline_tracker/ — alongside the stale fb9097f4….json (last touched 19:02).
  2. run_skill(skill=rectify, step_name="rectify", model="fable") (19:25:38) → quota guard approved (46% utilization) → session b38c02c9 runs 1214 s → returns success: true (19:44:47).
  3. PostToolUse hooks fire on the rectify result: quota post-check passes; pipeline_step_post_hook reads tool_input.step_name="rectify", finds no order_id (not a fleet dispatch), falls to directory discovery → two tracker files → "" → silent exit; rectify never marked. The tell: the final rewritten output contains no --- Pipeline Tracker --- banner (the hook emits one on success — visible in the earlier fb9097f4 pipeline where it worked).
  4. run_skill(skill=review-approach, step_name="review_approach", plan path = …part_a.md) (19:44:54) → quota guard approved (52%) → server _check_pipeline_deps: no order_id → kitchen-scoped fallback → reads c40ff8ac….jsonrectify: pendingdeny with DEPENDENCY UNMET before any session spawn (no session record, no no_session_* dir, no review-approach artifacts — all confirmed absent).
  5. pretty_output_hook rewrites the envelope to run_skill: FAIL [FAIL] / exit_code: / needs_retry: False — the error text is dropped.
  6. Orchestrator, seeing zero diagnostics and needs_retry: False, follows on_failure: release_issue_failureregister_clone_failureescalate_stop. Pipeline aborts; issue released with fail label.

Test Gap Analysis

  • [Corrected by post-filing validation] The multi-tracker silent no-op is unit-tested: tests/hooks/test_pipeline_step_post_hook.py:159 (test_order_id_discovery_skipped_when_multiple_trackers, added in the same commit 1e2670ec7 that introduced the code) asserts exit 0, empty stdout, and both trackers left pending — the behavior is enshrined as intended fail-open. The actual gaps: (a) no cross-layer integration test that record-time fail-open × check-time enforcement produces a false DEPENDENCY UNMET; (b) formatter fidelity — tests/infra/test_pretty_output_formatters.py covers run_skill failure-with-retry and gate_error shapes but never the bare {success:false, is_error:true, error} deny envelope.
  • No lifecycle test for tracker leakage. Nothing asserts that an unclosed kitchen's tracker cannot poison the next kitchen — cleanup exists only in _close_kitchen_handler, and no test covers open→(no close)→open.
  • No formatter test for the deny-envelope shape. Tests cover _fmt_run_skill for SkillResult-shaped payloads; none feeds {"success": false, "is_error": true, "error": …} (the shape produced by _check_pipeline_deps, _check_ingredient_locks, and kin) and asserts the error text survives formatting.
  • Slice coverage without composition (from the test-coverage subagent): tests/server/test_run_skill_locks.py covers lock denials; tests/server/test_tools_execution_input_gates.py covers input contracts; tests/server/test_review_approach_input_contract.py covers the plan-path gate; tests/recipe/test_bundled_recipes_pipeline_structure.py:231-243 covers step metadata — but no test exercises the real rectify → review_approach handoff end-to-end (real recipe template, real tracker, real hook), which is precisely where this failure lived.
  • Dependency-enforcement tests don't cover the recorder side. Server-side _check_pipeline_deps denial is tested (tests/server/test_run_skill_pipeline_deps.py, including the multi-pipeline fail-closed branch via test_kitchen_scoped_fallback_requires_order_id_with_multiple_pipelines), but only single-tracker scenarios exist for the recording pathway; that marking reliably ran before enforcement is assumed, not asserted. The complete/enforce split (client hook writes, server reads) has no integration test.

Similar Patterns

  • Dual client/server enforcement done right: ingredient locks are enforced server-side in run_skill (_check_ingredient_locks, tools_execution.py:118-162) with the ingredient_lock_guard hook as supplemental defense (guards/AGENTS.md). Step-dependency tracking inverted this: the server enforces, but only the client-side hook records — making the client hook a single point of silent failure for a server-enforced invariant.
  • Fail-open hook philosophy: guards deliberately fail open on malformed input (guards/AGENTS.md "Fail-Mode Contract"). pipeline_step_post_hook extends fail-open to ambiguity of target selection, which here converts a bookkeeping uncertainty into a downstream hard failure — fail-open at the recorder became fail-closed at the enforcer.
  • Formatter information loss precedent: d29a2999c "[FIX] Rectify: _fmt_generic Silent Truncation of Dispatch-Critical Structured Data — PART A ONLY ([FIX] Rectify: _fmt_generic Silent Truncation of Dispatch-Critical Structured Data — PART A ONLY #3963)" fixed the same defect family (pretty-output rewriting destroying decision-critical data) in _fmt_generic; _fmt_run_skill's error-drop is an unfixed sibling, while _fmt_test_check (_fmt_execution.py:185-187) shows the correct pattern — it renders error. See Historical Context.

Design Intent Findings

  • Pipeline step tracker + dependency enforcement: Introduced in 8c821e006 (2026-05-31, Add pipeline step completion tracker with server-side dependency enforcement #3404) — server-side dependency enforcement with a client-side completion hook. Callers: _check_pipeline_deps in run_skill (enforcement), pipeline_step_post_hook (recording), record_pipeline_step (init/status). The design intent is to prevent steps running out of order; nothing in the mechanism anticipated multiple tracker files from sequential kitchens in one project dir.
  • Tracker auto-init at open_kitchen: Introduced in 1e2670ec7 (2026-07-14, Server-authoritative payload delivery for open_kitchen output cap #4259) — "self-arming" tracker creation requiring no LLM action, explicitly independent of record_pipeline_step's order-id resolution. This made tracker creation unconditional for every kitchen, which combined with close-only cleanup raised the stale-file collision probability from "requires explicit init" to "every consecutive unclosed kitchen."
  • Failure routing (on_failurerelease_issue_failureescalate_stop): Per rules_graph_routes.py:11-19 and docs/execution/orchestration.md:50-74, tool-level failures route via on_failure; hard logical failures are designed to abort for human intervention (shaped by 48df5ee43, [FIX] Rectify: Transient Provider Retry Policy Immunity #4264). The observed abort matched design — given the orchestrator's information. The design assumes the failure envelope carries enough context to classify; the formatter broke that assumption.
  • Quota guard (ruled out): hooks/guards/quota_guard.py denies with explicit sleep-and-retry instructions ("QUOTA WAIT REQUIRED") and logs every decision. quota_events.jsonl shows approved at 02:44:54Z (52% utilization, 85% threshold) for the review-approach call — the guard did not fire. [SUPPORTED]

Historical Context

Part C analysis (prior-fix comparison subagent) refined the recurrence assessment:

  • Stale-tracker defect — first occurrence, born of an intra-commit inconsistency. discover_single_tracker_order_id did not exist before 1e2670ec7 (Server-authoritative payload delivery for open_kitchen output cap #4259, 2026-07-14 — four days before the failure). That commit did explicitly reason about multi-tracker ambiguity, but only at the check-time server layer: REQ-070 documents a deliberate fail-closed deviation in _check_pipeline_deps (deny when a second tracker shares the kitchen_id and no explicit order_id), with dedicated tests (test_kitchen_scoped_fallback_requires_order_id_with_multiple_pipelines, test_open_kitchen_auto_init_multi_pipeline). The record-time hook layer (pipeline_step_post_hook.py) and the advisory guard (guards/pipeline_step_guard.py) received the same discovery helper without the fail-closed treatment — silent sys.exit(0) on ambiguity. The original tracker design (8c821e006, Add pipeline step completion tracker with server-side dependency enforcement #3404, 2026-05-31) never contemplated multiple tracker files because order_id was then always explicit. So: not a regression of a prior fix, but an incomplete application of the same design pattern within a single commit.
  • Formatter defect — first surfacing of a pre-existing gap; adjacent to, but not a recurrence of, [FIX] Rectify: _fmt_generic Silent Truncation of Dispatch-Critical Structured Data — PART A ONLY #3963. d29a2999c ([FIX] Rectify: _fmt_generic Silent Truncation of Dispatch-Critical Structured Data — PART A ONLY #3963) fixed silent truncation of dispatch-critical structured data in _fmt_generic (scope: dispatch_food_truck), explicitly labeled "PART A ONLY"; its stated PART B scope (get_pipeline_report, wait_for_ci, get_ci_status, fetch_github_issue) was never done (git log --grep=3963 shows no follow-up) and never included run_skill. _fmt_run_skill's pipeline branch has simply never rendered an error field — notably, sibling formatter _fmt_test_check does render error (_fmt_execution.py:185-187), proving the family knows the pattern and applies it inconsistently.
  • No prior investigation report, fix commit, or issue addresses stale tracker files or DEPENDENCY UNMET false positives (project-log mining found "tool-level failure" only as recipe documentation text). Same-day investigation reports (investigation_shell_capture_rm_rejection_2026-07-18_*.md, etc.) concern issue shell_capture_hook injects prohibited rm cleanup and blocks every exec_command #4291's own subject matter (the shell-capture hook), not this mechanism.

Systemic-pattern flag: while neither defect is a literal recurrence, both belong to documented, partially-remediated defect families — formatter information destruction (#3963, PART B abandoned) and single-commit asymmetric hardening (#4259, check side hardened, record side left soft). Consider running /rectify for architectural immunity rather than spot-fixing.

External Research

Not applicable — the failure is entirely internal to AutoSkillit's pipeline-tracker and hook-formatter mechanisms; no third-party library behavior is implicated. (Claude Code hook semantics for updatedMCPToolOutput were confirmed empirically from the session transcript rather than external docs.)

Supplementary First-Person Investigation (beyond the subagent sweep)

Performed hands-on after the subagent wave, at the user's request; this is where the root cause was actually pinned:

  1. Located the true orchestrator transcript. The initial evidence subagent searched the wrong window/session. First-person triage of ~/.claude/projects/-home-talon-projects-generic-automation-mcp/ by mtime + content grep identified afa37add-ac21-4083-af6a-d6baed769b1f.jsonl as the orchestrator conversation (9 hits for the run dir).
  2. Recovered the destroyed error from mcpMeta. The model-visible tool_result was the contentless FAIL [FAIL] text, but the transcript's mcpMeta.structuredContent (line 67) preserved the raw envelope with the full DEPENDENCY UNMET message — the single decisive piece of evidence, invisible to both the orchestrator model and any log-index query.
  3. Proved the hook rewrite. Line 68 is the hook_success attachment: pretty_output_hook emitted updatedMCPToolOutput with exactly the degraded text (command: …/_dispatch.py formatters/pretty_output_hook).
  4. Falsified the quota-guard hypothesis (my initial leading theory given rectify's 1.6M cache-read, 20-minute opus run): quota_events.jsonl shows approved at 52%/85% for the exact call.
  5. Observed the two-tracker state directly on disk, including the paired proof: the stale fb9097f4 tracker has its run_skill steps complete (hook worked when it was alone), while the live c40ff8ac tracker has every step pending (hook disabled the entire run). Also confirmed dependencies contains the single edge review_approach → [rectify].
  6. Traced every silent-exit branch of pipeline_step_post_hook and eliminated alternatives: step_name was present (verified in the tool_use input); hook cwd = /home/talon/projects/generic_automation_mcp (verified from the transcript record's cwd), matching the server's tracker dir; tracker files existed; therefore the bail point is the order-id discovery ambiguity (_hook_utils.py:28-30). (Residual micro-branch: if AUTOSKILLIT_DISPATCH_ID were somehow set, the hook would instead exit at the tracker_path.exists() check for a nonexistent {dispatch_id}.json — same outcome, no session evidence for this variant; NEEDS-EVIDENCE, immaterial to the conclusion.)
  7. Verified the formatter drops error in both branches by reading _fmt_execution.py:41-108 end to end — the deny envelope's only informative field is not in the renderer's vocabulary; _fmt_tool_exception does render error but only applies to tool_exception-subtyped payloads.
  8. Established the lifecycle hole: tracker cleanup exists solely in _close_kitchen_handler (rmtree, tools_kitchen.py:533-540); _auto_init_pipeline_tracker preserves its own kitchen's file idempotently but never prunes other kitchens' files.
  9. Timeline reconstruction from four independent sources (quota events, sessions.jsonl, tracker mtimes, transcript timestamps) — all consistent with the chain above; the 7-second gap between rectify success (02:44:47Z) and the deny (02:44:54Z) rules out slow-async explanations.
  10. Side observation (unresolved, NEEDS-EVIDENCE): the rectify call passed model: "fable", yet the session record shows configured_model and model_identifier = "opus[1m]", input_tokens: 39. No "fable" alias exists in CLAUDE_MODEL_ALIASES, config profiles, or anywhere in the repo; translate_model passes unknown names through to the CLI. How the session ended up recorded as opus[1m] (CLI-side aliasing, internal retry/escalation, or recording from a different layer) was not determined. It does not affect the root cause (rectify succeeded), but it is a genuine observability gap worth a follow-up look.

Scope Boundary

Investigated: orchestrator transcript (raw MCP payloads + hook attachments), quota guard event log, sessions.jsonl index, on-disk tracker state, run-directory artifacts, run_skill's full error-path map (26 paths), recipe wiring and contracts for rectify → review_approach, hook implementations (pipeline_step_post_hook, quota_guard, pretty_output_hook/_fmt_execution), tracker lifecycle (open_kitchen/close_kitchen), git history of all implicated mechanisms (#3404, #4259, #3963, #4288, #4292), and test coverage across tests/server/ and tests/recipe/.

Not yet explored: the model: "fable"configured_model: "opus[1m]" resolution path (execution/headless model-identity internals); Claude Code's exact chaining semantics when multiple PostToolUse hooks emit updatedMCPToolOutput (only one attachment was observed per result; whether a successful tracker banner would have survived pretty_output_hook is untested); fleet-dispatch tracker scoping (AUTOSKILLIT_DISPATCH_ID paths); whether the recipe's retries: 1 on review_approach should have produced a second attempt (moot here — the deny is deterministic, a retry would fail identically); why the fb9097f4 conversation never called close_kitchen.

Confidence Levels

  • Deny envelope DEPENDENCY UNMET … {'rectify': 'pending'} was the actual failure — SUPPORTED (raw transcript mcpMeta).
  • Formatter destroyed the error text before the orchestrator saw it — SUPPORTED (hook attachment + rendered tool_result + formatter source).
  • Two tracker files present during the run; hook's discovery returns "" for >1 file — SUPPORTED (on-disk state + _hook_utils.py:21-30).
  • Hook bail point was the discovery ambiguity (vs. the dispatch-id micro-branch) — SUPPORTED with a minor inference (no hook-side log exists; all preconditions verified independently).
  • Stale tracker existed because the previous kitchen was never closed — SUPPORTED (cleanup only in _close_kitchen_handler; fb9097f4 tracker present with 19:02 mtime).
  • Quota guard, model="fable", recipe wiring, feat: replace output_budget_guard with lossless shell capture (#4286) #4288/Rectify: Inline Content in Subagent Prompts #4292 regressions as causes — UNSUPPORTED / ruled out (guard approved; rectify succeeded; wiring correct; Rectify: Inline Content in Subagent Prompts #4292 touches no implicated file, and feat: replace output_budget_guard with lossless shell capture (#4286) #4288's hunks are confined to run_cmd capture logic and an unrelated TypedDict — function-level, not file-level, exclusion).
  • "fable"→"opus[1m]" recording mechanism — NEEDS-EVIDENCE (side observation only).

Recommendations

Approaches only — no code changes were made:

  1. Make step-completion server-authoritative. run_skill already knows step_name, the kitchen_id, and the adjudicated result; mark the step complete server-side on success (mirroring how _check_pipeline_deps reads state), demoting the hook's role to the cosmetic tracker banner. This eliminates the client-side single point of silent failure and the scoping asymmetry in one move, and matches the established ingredient-locks pattern (server authoritative, hook supplemental).
  2. Fix tracker lifecycle regardless of (1). At open_kitchen/_auto_init_pipeline_tracker time, prune or archive tracker files whose kitchen_id differs from the current kitchen (with care for legitimate fleet concurrency — only prune trackers with no active lease/session). Close-only cleanup is structurally insufficient because kitchens demonstrably end without close_kitchen.
  3. Guarantee failure-envelope fidelity through formatting. _fmt_run_skill (both branches) must render data["error"] when present; audit all _fmt_* renderers against the {success, is_error, error} envelope shape and add a formatter-level invariant test: "any envelope field named error survives every rewrite path." This completes the work [FIX] Rectify: _fmt_generic Silent Truncation of Dispatch-Critical Structured Data — PART A ONLY #3963 explicitly deferred (PART A ONLY).
  4. Make the deny actionable. Include recovery guidance in the DEPENDENCY UNMET message (e.g., "if the required step actually succeeded, verify with record_pipeline_step(op='status'); state may be stale") and/or teach the sous-chef rules an explicit DEPENDENCY UNMET routing distinct from generic tool-level failure — today neither sous-chef SKILL.md nor _prompts.py mentions it.
  5. Add the missing regression tests identified in Test Gap Analysis: two-tracker hook scenario; open→no-close→open lifecycle; deny-envelope formatter fidelity; end-to-end rectify → review_approach handoff using the real recipe template and tracker.
  6. Follow up on the model-identity observation (fable vs opus[1m]) as a separate, low-priority observability question.

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugExisting behavior is brokenin-progressIssue is being actively worked onrecipe:remediationRoute: investigate/decompose before implementation

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions