Implementation Plan: Pipeline Observability — Quota Guard Logging and Per-Step Elapsed Time

[Trecek]

Summary

This PR implements two related pipeline observability improvements from issue #302 (combining #218 and #65):

1. Quota guard event logging (feat: Add quota guard observability to diagnostic logging system #218): Instruments hooks/quota_check.py to write a structured event to quota_events.jsonl at every decision point (approved, blocked, cache_miss, parse_error), giving operators a diagnostic trail for quota-guard activity.

2. Per-step elapsed time in token summary (feat: report per-step elapsed time in token summary #65): Surfaces the elapsed_seconds field already stored in TokenEntry through two rendering paths: the _fmt_get_token_summary formatter in pretty_output.py (what operators see inline during pipeline runs) and _format_token_summary in tools_status.py (what write_telemetry_files writes to token_summary.md).

Architecture Impact

Data Lineage Diagram

%%{init: {'flowchart': {'nodeSpacing': 50, 'rankSpacing': 70, 'curve': 'basis'}}}%%
flowchart LR
    %% CLASS DEFINITIONS %%
    classDef cli fill:#1a237e,stroke:#7986cb,stroke-width:2px,color:#fff;
    classDef stateNode fill:#004d40,stroke:#4db6ac,stroke-width:2px,color:#fff;
    classDef handler fill:#e65100,stroke:#ffb74d,stroke-width:2px,color:#fff;
    classDef phase fill:#6a1b9a,stroke:#ba68c8,stroke-width:2px,color:#fff;
    classDef newComponent fill:#2e7d32,stroke:#81c784,stroke-width:2px,color:#fff;
    classDef output fill:#00695c,stroke:#4db6ac,stroke-width:2px,color:#fff;
    classDef detector fill:#b71c1c,stroke:#ef5350,stroke-width:2px,color:#fff;

    %% ── QUOTA GUARD LINEAGE ── %%
    subgraph QuotaInputs ["Quota Guard Inputs"]
        QCACHE["quota_cache.json<br/>━━━━━━━━━━<br/>utilization: float<br/>resets_at: str|null<br/>fetched_at: ISO ts"]
        HCFG["hook_config.json<br/>━━━━━━━━━━<br/>threshold: float<br/>cache_max_age: int<br/>cache_path: str"]
    end

    subgraph QuotaHook ["● quota_check.py (PreToolUse)"]
        QDECIDE["decision logic<br/>━━━━━━━━━━<br/>compare utilization<br/>vs threshold"]
        QRESOLVE["★ _resolve_quota_log_dir()<br/>━━━━━━━━━━<br/>XDG / macOS / default<br/>AUTOSKILLIT_LOG_DIR env"]
        QWRITE["★ _write_quota_event()<br/>━━━━━━━━━━<br/>event: approved|blocked<br/>|cache_miss|parse_error"]
    end

    subgraph QuotaArtifacts ["★ New Diagnostic Artifacts"]
        QLOG[("quota_events.jsonl<br/>━━━━━━━━━━<br/>append-only JSONL<br/>at log root")]
    end

    %% ── TOKEN ELAPSED LINEAGE ── %%
    subgraph TokenSource ["Token Source (unchanged)"]
        HEADLESS["headless.py<br/>━━━━━━━━━━<br/>token_log.record(<br/>  step_name,<br/>  elapsed_seconds)"]
        TOKENTRY["TokenEntry<br/>━━━━━━━━━━<br/>elapsed_seconds: float<br/>input_tokens, output_tokens<br/>invocation_count"]
    end

    subgraph TokenSurfaces ["Token Summary Surfaces"]
        GETTOK["get_token_summary<br/>━━━━━━━━━━<br/>JSON: steps[].elapsed_seconds<br/>(already present in output)"]
        PRETTYOUT["● _fmt_get_token_summary<br/>━━━━━━━━━━<br/>pretty_output.py<br/>Markdown-KV render"]
        FMTTOKEN["● _format_token_summary<br/>━━━━━━━━━━<br/>tools_status.py<br/>markdown render"]
    end

    subgraph TokenArtifacts ["Updated Artifacts"]
        PRETTYRENDER["● pretty_output render<br/>━━━━━━━━━━<br/>★ + t:{elapsed:.1f}s<br/>per step line"]
        TOKENMD["● token_summary.md<br/>━━━━━━━━━━<br/>★ + elapsed_seconds:<br/>per step section"]
    end

    %% QUOTA FLOWS %%
    QCACHE -->|"read: utilization,<br/>resets_at"| QDECIDE
    HCFG -->|"read: threshold,<br/>cache_max_age"| QDECIDE
    QDECIDE -->|"decision outcome"| QWRITE
    QRESOLVE -->|"log dir path"| QWRITE
    QWRITE -.->|"append JSON line"| QLOG

    %% TOKEN FLOWS %%
    HEADLESS -->|"record(step, elapsed)"| TOKENTRY
    TOKENTRY -->|"to_dict() all 7 fields"| GETTOK
    GETTOK -->|"steps[].elapsed_seconds"| PRETTYOUT
    GETTOK -->|"steps[].elapsed_seconds"| FMTTOKEN
    PRETTYOUT -.->|"★ renders elapsed"| PRETTYRENDER
    FMTTOKEN -.->|"★ renders elapsed"| TOKENMD

    %% CLASS ASSIGNMENTS %%
    class QCACHE,HCFG cli;
    class TOKENTRY,GETTOK stateNode;
    class QDECIDE,QRESOLVE,QWRITE handler;
    class HEADLESS phase;
    class PRETTYOUT,FMTTOKEN newComponent;
    class QLOG,TOKENMD,PRETTYRENDER output;
    class TOKENTRY stateNode;

Loading

Color Legend:

Color	Category	Description
Dark Blue	Input	Data source files (cache, config)
Teal	State	In-memory token log and JSON output
Orange	Handler	Quota decision + event write logic
Purple	Phase	headless.py session executor
Green	Modified	Existing formatters updated to emit elapsed
Dark Teal	Artifacts	Write-only outputs (JSONL log, markdown files)

Operational Diagram

%%{init: {'flowchart': {'nodeSpacing': 50, 'rankSpacing': 70, 'curve': 'basis'}}}%%
flowchart TB
    %% CLASS DEFINITIONS %%
    classDef cli fill:#1a237e,stroke:#7986cb,stroke-width:2px,color:#fff;
    classDef stateNode fill:#004d40,stroke:#4db6ac,stroke-width:2px,color:#fff;
    classDef handler fill:#e65100,stroke:#ffb74d,stroke-width:2px,color:#fff;
    classDef phase fill:#6a1b9a,stroke:#ba68c8,stroke-width:2px,color:#fff;
    classDef output fill:#00695c,stroke:#4db6ac,stroke-width:2px,color:#fff;
    classDef newComponent fill:#2e7d32,stroke:#81c784,stroke-width:2px,color:#fff;

    subgraph Config ["CONFIGURATION"]
        direction LR
        ENVCACHE["AUTOSKILLIT_QUOTA_CACHE<br/>━━━━━━━━━━<br/>quota cache path override"]
        ENVLOG["AUTOSKILLIT_LOG_DIR<br/>━━━━━━━━━━<br/>log root override<br/>(XDG_DATA_HOME fallback)"]
        HOOKCFG["hook_config.json<br/>━━━━━━━━━━<br/>threshold: 90.0<br/>cache_max_age: 300s<br/>cache_path"]
    end

    subgraph Hooks ["HOOKS (Claude Code Lifecycle)"]
        direction TB
        QHOOK["● quota_check.py<br/>━━━━━━━━━━<br/>PreToolUse on run_skill<br/>approve / block decision"]
        PHOOK["● pretty_output.py<br/>━━━━━━━━━━<br/>PostToolUse on all MCP tools<br/>reformats JSON → Markdown-KV"]
    end

    subgraph MCP ["MCP TOOLS (Status & Telemetry)"]
        direction TB
        GETTOK["get_token_summary<br/>━━━━━━━━━━<br/>ungated, inline<br/>JSON: steps[].elapsed_seconds"]
        WRITETELE["write_telemetry_files<br/>━━━━━━━━━━<br/>kitchen-gated<br/>output_dir: str"]
        TOKTOOL["● tools_status.py<br/>━━━━━━━━━━<br/>_format_token_summary<br/>adds elapsed_seconds: line"]
    end

    subgraph Observability ["OBSERVABILITY OUTPUTS (Write-Only)"]
        direction TB
        QLOG["★ quota_events.jsonl<br/>━━━━━━━━━━<br/>append-only JSONL at log root<br/>event: approved|blocked|<br/>cache_miss|parse_error"]
        PRETTYRENDER["● inline token render<br/>━━━━━━━━━━<br/>step x{n} [in:X out:X cached:X t:N.Ns]<br/>Claude's tool response view"]
        TOKENMD["● token_summary.md<br/>━━━━━━━━━━<br/>## step_name<br/>- elapsed_seconds: N<br/>atomic write"]
    end

    subgraph Querying ["OPERATOR QUERY PATTERNS"]
        direction TB
        JQQUERY["jq 'select(.event==\"blocked\")'<br/>━━━━━━━━━━<br/>quota_events.jsonl<br/>filter blocked events"]
        JQCOUNT["jq -r '.event' | sort | uniq -c<br/>━━━━━━━━━━<br/>event type distribution"]
    end

    %% CONFIG → HOOKS %%
    ENVCACHE -->|"cache path"| QHOOK
    ENVLOG -->|"log root"| QHOOK
    HOOKCFG -->|"threshold, cache_max_age"| QHOOK

    %% HOOKS → OUTPUTS %%
    QHOOK -.->|"★ _write_quota_event() appends"| QLOG
    PHOOK -->|"_fmt_get_token_summary route"| PRETTYRENDER

    %% MCP → HOOK INTERACTION %%
    GETTOK -->|"JSON response → PostToolUse"| PHOOK
    GETTOK -->|"steps[].elapsed_seconds"| TOKTOOL
    WRITETELE --> TOKTOOL
    TOKTOOL -.->|"atomic write"| TOKENMD

    %% OPERATOR QUERIES %%
    QLOG -.->|"operator queries"| JQQUERY
    QLOG -.->|"operator queries"| JQCOUNT

    %% CLASS ASSIGNMENTS %%
    class ENVCACHE,ENVLOG,HOOKCFG phase;
    class QHOOK,PHOOK handler;
    class GETTOK,WRITETELE,TOKTOOL stateNode;
    class QLOG,TOKENMD,PRETTYRENDER output;
    class JQQUERY,JQCOUNT cli;

Loading

Color Legend:

Color	Category	Description
Purple	Config	Configuration sources (env vars, hook config file)
Orange	Hooks	Claude Code lifecycle hooks (PreToolUse, PostToolUse)
Teal	MCP Tools	Status and telemetry MCP tool handlers
Dark Teal	Outputs	Write-only observability artifacts
Dark Blue	Querying	Operator query patterns and diagnostic commands

Closes #302

Implementation Plan

Plan file: /home/talon/projects/autoskillit-runs/impl-302-20260310-073833-386833/temp/make-plan/pipeline_observability_plan_2026-03-10_120000.md

Token Usage Summary

Token Summary

implement

• input_tokens: 20233
• output_tokens: 499703
• cache_creation_input_tokens: 1532389
• cache_read_input_tokens: 99527456
• invocation_count: 16

audit_impl

• input_tokens: 7600
• output_tokens: 134323
• cache_creation_input_tokens: 520444
• cache_read_input_tokens: 3863375
• invocation_count: 13

open_pr

• input_tokens: 925
• output_tokens: 73212
• cache_creation_input_tokens: 247356
• cache_read_input_tokens: 4293763
• invocation_count: 4

retry_worktree

• input_tokens: 45
• output_tokens: 22321
• cache_creation_input_tokens: 111687
• cache_read_input_tokens: 3405410
• invocation_count: 1

make_plan

• input_tokens: 44
• output_tokens: 69854
• cache_creation_input_tokens: 121021
• cache_read_input_tokens: 2735054
• invocation_count: 1

review_pr

• input_tokens: 8568
• output_tokens: 166539
• cache_creation_input_tokens: 420350
• cache_read_input_tokens: 5838460
• invocation_count: 7

dry_walkthrough

• input_tokens: 57
• output_tokens: 30444
• cache_creation_input_tokens: 114452
• cache_read_input_tokens: 1679519
• invocation_count: 3

resolve_review

• input_tokens: 404
• output_tokens: 211704
• cache_creation_input_tokens: 502896
• cache_read_input_tokens: 23247211
• invocation_count: 7

fix

• input_tokens: 291
• output_tokens: 113181
• cache_creation_input_tokens: 415961
• cache_read_input_tokens: 19115239
• invocation_count: 6

investigate

• input_tokens: 2053
• output_tokens: 12607
• cache_creation_input_tokens: 52059
• cache_read_input_tokens: 382017
• invocation_count: 1

rectify

• input_tokens: 4616
• output_tokens: 21997
• cache_creation_input_tokens: 75946
• cache_read_input_tokens: 854207
• invocation_count: 1

open_pr_step

• input_tokens: 52
• output_tokens: 27985
• cache_creation_input_tokens: 102646
• cache_read_input_tokens: 1871801
• invocation_count: 2

analyze_prs

• input_tokens: 13
• output_tokens: 18525
• cache_creation_input_tokens: 55984
• cache_read_input_tokens: 358201
• invocation_count: 1

merge_pr

• input_tokens: 54
• output_tokens: 11011
• cache_creation_input_tokens: 124523
• cache_read_input_tokens: 1156759
• invocation_count: 4

create_review_pr

• input_tokens: 35
• output_tokens: 17881
• cache_creation_input_tokens: 52674
• cache_read_input_tokens: 1060679
• invocation_count: 1

plan

• input_tokens: 6248
• output_tokens: 238067
• cache_creation_input_tokens: 765044
• cache_read_input_tokens: 9628970
• invocation_count: 9

verify

• input_tokens: 2284
• output_tokens: 119880
• cache_creation_input_tokens: 539579
• cache_read_input_tokens: 6350120
• invocation_count: 10

Timing Summary

Timing Summary

implement

• total_seconds: 11896.63371942683
• invocation_count: 16

audit_impl

• total_seconds: 3964.286584958052
• invocation_count: 13

open_pr

• total_seconds: 1599.6864469241118
• invocation_count: 4

retry_worktree

• total_seconds: 483.85407130105887
• invocation_count: 1

make_plan

• total_seconds: 1572.1653282630723
• invocation_count: 1

review_pr

• total_seconds: 2817.96798053605
• invocation_count: 7

dry_walkthrough

• total_seconds: 539.9472401479725
• invocation_count: 3

resolve_review

• total_seconds: 4706.892171586864
• invocation_count: 7

fix

• total_seconds: 3109.516113938147
• invocation_count: 6

investigate

• total_seconds: 586.5382829050068
• invocation_count: 1

rectify

• total_seconds: 725.7269057529047
• invocation_count: 1

open_pr_step

• total_seconds: 579.5783970400225
• invocation_count: 2

analyze_prs

• total_seconds: 279.4915256820386
• invocation_count: 1

merge_pr

• total_seconds: 285.0633245370118
• invocation_count: 4

create_review_pr

• total_seconds: 441.7614419440506
• invocation_count: 1

plan

• total_seconds: 6489.170513134953
• invocation_count: 9

verify

• total_seconds: 2771.1426656231615
• invocation_count: 10

clone

• total_seconds: 5.5492194169996765
• invocation_count: 6

capture_base_sha

• total_seconds: 0.017372207999414968
• invocation_count: 6

create_branch

• total_seconds: 4.241269170999658
• invocation_count: 6

push_merge_target

• total_seconds: 5.88246012000036
• invocation_count: 6

test

• total_seconds: 497.636292823996
• invocation_count: 9

merge

• total_seconds: 877.7062499809981
• invocation_count: 7

push

• total_seconds: 5.489298081000015
• invocation_count: 5

🤖 Generated with Claude Code via AutoSkillit

[Trecek]

AutoSkillit PR Review — Verdict: changes_requested

[Trecek]

[critical] bugs: step['elapsed_seconds'] uses direct dict access with no default. If any TokenEntry dict predates this field, this raises KeyError and crashes _format_token_summary entirely. Use step.get('elapsed_seconds', 0.0) consistent with how pretty_output.py handles the same field.

[Trecek]

[warning] defense: _write_quota_event parameter annotation uses string literal 'Path | None' for log_dir instead of the actual union type. Path is already imported and _resolve_quota_log_dir uses the unquoted form. Remove the quotes for consistency.

[Trecek]

[warning] defense: _format_token_summary directly accesses step['elapsed_seconds'] with no .get() fallback — newly added field most likely to be absent in historical data. Use step.get('elapsed_seconds', 0.0).

[Trecek]

[warning] tests: Disjunctive assertion '"123.4s" in rendered or "t:123.4s" in rendered' passes even if the format is wrong. The format spec is known (t:{elapsed:.1f}s), so pin to '"t:123.4s" in rendered' only, matching the updated compact-line assertions at lines 349-351.

[Trecek]

[warning] tests: T6 (test_quota_event_no_crash_when_log_dir_unresolvable) only asserts empty stdout but does not verify the hook exits 0. A silent crash would also produce empty stdout. If _run_hook captures exit code, assert it is 0.

[Trecek]

[warning] cohesion: AUTOSKILLIT_LOG_DIR env var resolution and platform path logic duplicate execution/session_log.py:resolve_log_dir(). Consider whether the hook should share this logic or keep it standalone (hooks cannot import from the package).

[Trecek]

[warning] cohesion: write_quota_event does not carry the 'quota' infix used throughout the module (e.g., _read_quota_cache, _resolve_quota_log_dir). Rename to _write_quota_log_event for naming symmetry.

[Trecek]

[warning] cohesion: Loose 'or' assertion pattern deviates from the precise assertion style used at lines 349-351. Mirror exact format: '"t:123.4s" in rendered'.

[Trecek]

AutoSkillit review found 7 blocking issues. See inline comments.

Verdict: changes_requested

Critical (1): KeyError on step['elapsed_seconds'] in _format_token_summary — use .get() with a default.
Warnings (6): string-literal type annotation, missing .get() fallback in tools_status, disjunctive test assertions (2), T6 missing exit-code check, naming inconsistency (_write_quota_event).