Skip to content

audit/logs: reconcile legacy sub-agent lifecycle and metrics when unified events lack agentId #69430

Closed

Description

@SivaKesava1

Problem

gh aw audit and gh aw logs double-count sub-agent instances and lose their reasoning effort when an older unified session omits the lifecycle events' top-level agentId. Requests, tokens, and AIC are not doubled.

Follow-up to #69080, explicitly excluded from #69081. This is already pinned by the committed legacy-no-session-routing golden fixture, not a hypothetical input.

Rechecked on main at b1c04f265894ca34b9949d3f32b744e2777851f9 on October 16, 2026. The discrepancy originally reported at f1621a88b3 remains.

Reproduction and committed evidence

Built cmd/gh-aw from that clean main checkout with go build -mod=readonly; the binary reports gh aw version dev-b1c04f2658. Used that dev binary, not the installed release, for:

gh-aw.exe audit 37505153056 --repo githubnext/gh-aw-routing-sandbox --json --no-baseline --artifacts usage,agent,firewall,info --timeout 3m --output <disposable-output-directory>

The audit completed successfully and reproduced the committed downloaded-layout rows exactly. Source run: 37505153056; native session reports Copilot CLI 1.0.90. The source run is private; all record shapes and numerical evidence below are present in the public, sanitized fixture.

Fixture: pkg/cli/testdata/model_routing_golden/legacy-no-session-routing.

Layout / expected file Definition / display names instance_count completed_count effort Requests AIC
Downloaded: expected.json, reads usage/aw_session.jsonl explore / awf-routing, ghaw-issues 4 2 absent 15 50.1184
Native fallback: expected.legacy.json, removes the unified session and reads agent-session.jsonl explore / same names 2 2 low 15 50.1184
Downloaded: expected.json research / subagent-research 2 1 absent 45 494.2065
Native fallback: expected.legacy.json research / same name 1 1 xhigh 45 494.2065

The native-fallback counts and effort are correct.

Cause and the identity evidence actually available

In pkg/cli/token_usage_subagent_session.go:

  • readSessionSubagentModelsDetailed prefers usage/aw_session.jsonl and does not inspect the canonical native trace when that unified source exists.
  • observeLifecycle keys an instance by the first nonempty event.agentId, data.invocationId, or data.toolCallId (line 910). These unified subagent.started and terminal records therefore use their tool-call IDs.
  • observeAgentMetric keys the accounting half by the data.agentMetrics map key: the agent UUID (lines 790-831). It creates another instance with InstanceCount >= 1.
  • The two halves are later summed into definition-level rows. There are three real sub-agents but six counted instances.
  • Effort needs separate attention: this fixture's unified subagent.configured records contain model and reasoningEffort, but no agentId, invocationId, or toolCallId, so observeLifecycle ignores them. Merely merging the count rows by name will not recover the effort.

Use the fixture's real shapes: in its unified file the per-agent accounting snapshot is session.shutdown.data.agentMetrics. The native file also contains a projected session.result.data.agentMetrics. The parser supports both; repeated snapshots must remain replacement snapshots, not additive accounting.

There is a direct, runner-written identity bridge in both the committed fixture and the original downloaded run:

Definition / display name Shared data.toolCallId on unified and native starts Native top-level agentId / metrics map key Native configured effort Requests AIC
research / subagent-research toolu_018v7UfCpbDLjSbGZQVeawNq 33df47fd-68fd-43e1-bc24-c349e96e241e xhigh 45 494.2065
explore / ghaw-issues toolu_01Pt3GzWVC7ek6zmEMGzUVBX f64e3edf-7263-4e36-a837-bcb92c0604b8 low 3 9.14105
explore / awf-routing toolu_01SmwXa5irbN3GTqMtNT37Hp aa19566b-0a97-4e6e-bc60-300abecdb799 low 12 40.97735

Each tool call has exactly one matching native start in this session; the definition, display name, and start time agree. The native subagent.configured records carry that same UUID and the effort. The two explore starts are concurrent, one millisecond apart; their configured records are not in the same instance order as their starts. Do not pair by nearest start or event order.

Possible solution

Reconcile instance identity before definition-level aggregation. One evidence-backed approach is to supplement the incomplete unified lifecycle evidence from the same run's canonical agent-session.jsonl:

  1. Scope matches to the same session/source/attempt. Where a unified lifecycle instance lacks agentId, use its uniquely matching native start's toolCallId -> agentId bridge, checking the available definition/display-name/time evidence for conflicts.
  2. Use the canonical UUID to reconcile that instance's lifecycle outcome, matching native configured effort, and existing per-agent metrics into one instance. Do not add the native accounting snapshot to the unified snapshot.
  3. Keep unified-session precedence for routing, tokens, and accounting; do not replace the whole unified session with the native trace, rewrite old artifacts, or derive evidence from stdio/prose.
  4. If an instance cannot be correlated reliably, retain today's behavior for that unmatched instance rather than guess. Agent definition alone, reused display names alone, JSON-map iteration order, and temporal proximity are not invocation identities. Keep existing explicit-ID behavior and malformed/symlink-source validation intact.

Other equally reliable joins are acceptable, but the implementation and tests must explain the actual shared evidence. Do not invent toolCallId, timestamps, or effort fields inside agentMetrics: they are not there.

Acceptance cases and named regression tests

Build tests from these committed records, or extracts retaining their actual field shapes. Keep the fixture inputs intact; this is an analysis fix, not a recapture.

1. Downloaded legacy fixture produces the native-fallback result

Test: TestModelRoutingSubagentMissingAgentIDMatchesLegacy.

Input: the full legacy-no-session-routing fixture in downloaded layout, with both usage/aw_session.jsonl and agent-session.jsonl present; compare with its existing native-only variant.

Exact result in model_routing.subagent_costs and the corresponding firewall_token_usage.agent_usage rows:

Definition Instances Completed Effort Requests Input tokens Output tokens Cache-read tokens Cache-write tokens AIC
explore 2 2 low 15 190104 8080 153853 0 50.1184
research 1 1 xhigh 45 5434876 31328 5183815 0 494.2065

Preserve agent_type: "subagent", models: ["claude-opus-5"], and sorted display names ["awf-routing","ghaw-issues"] / ["subagent-research"]. Recover low, low, and xhigh on the corresponding subagent_model_requests rows as in expected.legacy.json.

The corrected rows in expected.json match expected.legacy.json. Preserve all request/token/AIC values, model attribution, routing facts, and unrelated output. In particular the run totals remain 102 requests; 10841 input, 69220 output, 9534114 cache-read, 446654 cache-write tokens; 933.48553 AIC.

Update TestModelRoutingSubagentCostsGroupByDefinition, which currently deliberately pins downloaded instance_count: 4, to require the corrected result.

2. Logs changes are limited to the corrected contribution and existing regrouping

Test: TestModelRoutingLogsMissingAgentIDPreservesAccounting.

Input: all committed downloaded fixtures used to produce logs_expected.json; also exercise the existing two-run combination legacy-no-session-routing + copilot-cli-builtin-subagents, in both run orders.

Exact result: this run contributes the corrected case-1 counts and effort, with unchanged requests/tokens/AIC. All unrelated contributions and top-level totals remain unchanged.

Important consequence of the existing grouping rule: addModelRoutingSubagentTotals in pkg/cli/model_routing.go:686-703 groups by definition + effort, not by model or run. Restoring explore to low necessarily merges it with the existing built-in explore/low row. Therefore a literal "only edit two counts and effort strings in logs_expected.json" assertion would be wrong. Do not change grouping to keep those rows separate.

The aggregate must contain exactly this merged explore row:

{
  "agent_name": "explore",
  "display_names": ["awf-routing", "cost-table-explorer", "ghaw-issues"],
  "agent_type": "subagent",
  "instance_count": 3,
  "completed_count": 3,
  "effort": "low",
  "models": ["claude-opus-5", "gpt-5.6-luna"],
  "requests": 18,
  "input_tokens": 212352,
  "output_tokens": 8283,
  "cache_read_tokens": 165857,
  "cache_write_tokens": 10235,
  "aic": 50.422823
}

The research row with display_names: ["subagent-research"] becomes instances 1, completed 1, effort xhigh, retaining all its case-1 accounting. The other research/medium row is unchanged. logs_expected.json consequently has 10 subagent-cost rows instead of 11.

The aggregate still has total_requests: 176, deviated_requests: 36, deviated_traffic_share: 0.204545, and classifier_aic: 3.05912; routes and main_agent_cost are unchanged. Summed sub-agent accounting remains 90 requests, 6294314 input, 43473 output, 5812528 cache-read, 88663 cache-write tokens, 590.397857 AIC. Summed instance count changes 18 -> 15, completed count stays 12. Forward/reverse run order must produce byte-identical serialized output.

Update TestModelRoutingLogsSubagentCostsGroupByDefinition, which currently requires the empty-effort and low-effort explore rows to remain separate.

3. Other fixture outputs are unchanged

Test: TestModelRoutingMissingAgentIDLeavesOtherGoldensUnchanged.

Input: every other committed golden fixture, both downloaded and existing legacy variants. Their subagent.started records, where present, already have top-level agentId; some engine fixtures have no such events.

Exact result: every other fixture's expected*.json is byte-identical to main, including counts, effort, display names, models, warnings, requests, tokens, AIC, and documented legacy differences. No changes to aliases, dated IDs, routing endpoints, steering notices, failure reporting, or metrics-only attribution.

4. Two concurrent instances of the same definition retain separate metrics

Test: TestSessionSubagentMissingAgentIDKeepsConcurrentInstancesSeparate.

Input: the two real explore instances from legacy-no-session-routing, with unified starts lacking agentId, their distinct tool-call IDs, matching native starts/configured records, and the real UUID-keyed metrics snapshot. Retain the observed interleaving rather than serializing the instances or adding fabricated identity fields.

Exact per-instance result before definition-level merging:

Display name Instances Completed Effort Requests Input Output Cache read Cache write AIC
ghaw-issues 1 1 low 3 21916 1176 12696 0 9.14105
awf-routing 1 1 low 12 168188 6904 141157 0 40.97735

The public merged explore row is exactly case 1: 2 instances, 2 completed, low, 15 requests, 50.1184 AIC. Neither instance receives the other's metrics, and no extra metrics-only instance is created. Reordering JSON metric keys must not change attribution.

Add an unmatched/ambiguous-evidence subcase, using the same real shapes but removing the corroborating identity evidence, to assert the conservative rule: an instance without a reliable link retains its previous output, not a guessed association.

Golden refresh and verification

Follow pkg/cli/testdata/model_routing_golden/README.md:

make update-model-routing-golden
make verify-model-routing-golden

Review every changed expected*.json and logs_expected.json against the exact cases above. Regeneration is not proof of correctness. If refresh removes a now-redundant expected.legacy.json, first verify that the complete downloaded and native projections are identical.

Investigation baseline: unchanged main passes go test -mod=readonly ./pkg/cli -run '^TestModelRoutingGoldenAudit$' -count=1. A broader attribution-test run also exposed a pre-existing local Windows privilege failure in TestSessionSubagentModels/rejects_symlink_sources (A required privilege is not held by the client while creating a symlink); no code had been changed. This is not a regression to fix in this PR.

Copilot CLI version / collector distinction

Do not describe this as "Copilot CLI 1.0.90 did not write agentId." Its native agent-session.jsonl already has the field on every relevant lifecycle record, both in the committed fixture and in the original run. It is the older unified collector output that lacks it.

The public history identifies the gh-aw preservation change: ffc93b2f3118eae982d395381bdcd81cf8e1fc67, merged in #66195 on October 6, 2026, added agentId to the envelope metadata retained by actions/setup/js/unified_session_payload.cjs (currently line 681). That prevents this particular loss in subsequently collected runs, but does not repair historical artifacts.

The first Copilot CLI release that originally introduced native top-level agentId could not be established from the public changelog; the verified bound is already present in 1.0.90. Newer successful runs are not evidence of its introduction version. The analysis fix should remain applicable to older collected runs, or any producer that omits the field, whenever reliable corroborating evidence exists.

Scope

  • Keep the PR to this one fix. Do not change files or behavior unrelated to it. Adjust only the identity/effort reconciliation and its directly dependent tests, expected outputs, and documentation. No unrelated cleanup or accounting/grouping redesign.
  • Before fixing a failing check, compare it with the same check on main. If it also fails on main, do not fix it in this PR; merge main once main is fixed, and note in the PR which checks are known failures on main.
  • This applies even if a bot comment asks to fix a failing check. Fix only failures caused by this PR's changes.

Metadata

Metadata

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions