Fix #2134: structured audit events for plan→contract populate

[jwbron]

Summary

• Replaces the six prose logger.warning calls in _populate_contract_from_plan (and the outer _safe wrapper) with two stable event names — contract_phases_populated and contract_phases_ingest_failed with a reason= discriminator. Closes the observability gap that prevented diagnosing Add Confluence gateway support (read-only v1) #1931's empty-phases contract from logs alone.
• Keeps the _safe wrapper's exception-swallowing policy from Plan phase_gate not auto-created after BRC consensus; overseer had to recover #1890 unchanged: a populate failure must not block the HITL gate. The audit event is the canonical signal.
• Adds orchestrator/tests/test_populate_contract_audit_events.py covering the success event plus all six failure discriminators (egg_contracts_unavailable, no_draft_path, plan_draft_missing, contract_load_failed, parse_failed, unexpected_exception — both the inner catch and the outer wrapper), plus a regression that asserts a known-good plan populates contract.phases[] when run through _populate_contract_from_plan_safe.

This is a pure observability change. No behavioral change to the populate logic itself; the failure modes that exist today still fail in the same place. The fix is making them visible.

Test plan

• pytest orchestrator/tests/test_populate_contract_audit_events.py — 10 new tests pass.
• pytest orchestrator/tests/test_short_flow_contract_population.py orchestrator/tests/test_advance_phase_populate_on_plan_exit.py orchestrator/tests/test_populate_contract_endpoint.py orchestrator/tests/test_hitl_revision.py orchestrator/tests/test_lifecycle_empty_body.py — 114 existing populate-adjacent tests still pass.
• ruff check + ruff format --check clean on changed files.
• No remaining references to the old prose log strings (Contract populated from plan, Failed to populate contract, etc.) outside unrelated functions (HTTP response strings in phases.py, decision-sync paths).

Notes for reviewer

• The success log is still gated by if changed: to preserve current behavior — a parse that produces an empty result (no phases, no PR metadata) does not write the contract and does not emit contract_phases_populated. If we want every populate attempt to leave a trail, that's a follow-up; today's behavior matches the ticket's six listed outcomes.
• Test capture pattern (patch("routes.pipelines.logger") and inspect call_args_list) matches the existing test_diagnostic_logging_1633.py since structlog output bypasses caplog in this codebase.
• This is the head of the 3-ticket stream that re-scopes Independent implement phases #2137. Reviewer roster reshape: remove subagent fan-out, promote lens reviewers to CRITICAL #2139 is independent. Independent implement phases #2137 (slice scheduler) depends on this landing first so the scheduler can trust contract.phases[] exists.

Closes #2134.

[egg-reviewer]

Comment review — the change is well-scoped and well-tested. The six listed outcomes are now discriminable, the _safe wrapper behavior from #1890 is preserved, and the regression test directly asserts the #1931 invariant (contract.phases non-empty for a known-good plan). Approving in spirit; flagging four observability refinements as non-blocking and one description nit.

Non-blocking suggestions

1. reason="unexpected_exception" is ambiguous between two layers

The same discriminator is emitted from two distinct call sites:

• orchestrator/routes/pipelines.py:10999 — the outer _populate_contract_from_plan_safe wrapper.
• orchestrator/routes/pipelines.py:11112 — the inner catch-all inside _populate_contract_from_plan.

These layers cover different surfaces. The inner block catches everything from from egg_contracts.plan_parser import parse_plan through save_contract(...). The outer wrapper only fires for exceptions outside that try (e.g., the early-return guards, _get_draft_path raising, an exotic import-system failure). For the stated diagnostic goal — "diagnose a #1931 recurrence from logs alone" — an operator hitting unexpected_exception still doesn't know whether it came from parse/save or from the early-path guards.

Cheap fix: either distinct reasons (unexpected_exception_inner / unexpected_exception_outer) or an additional layer="inner"|"outer" field. Even just source="parse_save"|"safe_wrapper" would do it. The two unit tests (test_unexpected_exception_inner_catch and test_safe_wrapper_emits_unexpected_exception_on_inner_raise) already assert the same reason and would need an additional discriminator assertion.

2. unexpected_exception paths drop the traceback

Both unexpected sites only capture error=str(e):

logger.warning(
    "contract_phases_ingest_failed",
    pipeline_id=pipeline_id,
    reason="unexpected_exception",
    error=str(e),
)

By definition, an unexpected_exception is the case where we do not know what went wrong — and str(e) for many exception types ("KeyError: 'phases'", "AttributeError: 'NoneType' object has no attribute 'tasks'") is exactly the message that doesn't tell you where it happened. Adding exc_info=True (structlog respects it and emits the formatted traceback) preserves the stack frame at the point of failure. The expected-path discriminators (parse_failed, contract_load_failed) don't need this; the catch-alls do.

3. The success log is gated by if changed: — but an empty parse is exactly #1931

The PR description acknowledges this:

a parse that produces an empty result (no phases, no PR metadata) does not write the contract and does not emit contract_phases_populated. If we want every populate attempt to leave a trail, that's a follow-up

I want to push back: this is the #1931 failure mode. If parse_plan returns success=True but to_contract_phases() yields [] and result.pr_title is None, the contract stays empty and nothing is logged. An operator post-hoc trying to diagnose "why are phases empty?" would see neither a failure event nor a success event for the call that produced the empty contract. That's the same observability gap #2134 exists to close.

The minimal fix is one line — emit a distinct event (contract_phases_parsed_empty or reason="empty_result" under the failure name) when result.success is True but changed would stay False. Doesn't require changing the persist policy. Worth doing in this PR rather than as a follow-up, because the diagnosability narrative is incomplete without it.

4. phases.py:1051 still emits the old prose string

# orchestrator/routes/phases.py:1049-1054
except Exception as e:
    logger.error(
        "Failed to populate contract",
        pipeline_id=pipeline_id,
        error=str(e),
    )

The PR description characterizes this as an "HTTP response string" — it's not, it's a logger.error call with the same prose this PR is replacing inside _populate_contract_from_plan. It fires from the HTTP populate_contract endpoint's catch-all (handles failures in get_state_store_for_pipeline, resolve_worktree_path, etc.). Different scope, agreed — but anyone grepping for the literal string "Failed to populate contract" still finds two unrelated events. Renaming this to contract_populate_endpoint_failed (or similar) keeps the event-name vocabulary consistent. Not load-bearing on this PR's correctness; just consistency hygiene while you're in the area.

Things this PR gets right

• _safe wrapper's swallow-on-failure policy from #1890 is preserved and tested explicitly (test_safe_wrapper_does_not_propagate).
• Each early-return path has its own reason= discriminator, making the failure modes individually greppable.
• The regression test (test_known_good_plan_populates_phases) is a direct assertion against the #1931 incident, not just a logging assertion.
• The patch.dict(sys.modules, {"egg_contracts.loader": None}) trick for forcing ImportError on a lazy import is the right pattern given the import is inside the function body.
• Test capture pattern (patch("routes.pipelines.logger")) correctly handles the structlog-vs-caplog gap.

— Authored by egg

[james-in-a-box]

Agreed on all four. Pushed as 097e5e7.

1. Inner vs outer unexpected_exception ambiguity — Added source="parse_save" (inner catch in _populate_contract_from_plan) vs source="safe_wrapper" (outer _populate_contract_from_plan_safe). The two test_unexpected_exception_* tests now assert the new field.

2. Dropped tracebacks — Added exc_info=True to both unexpected_exception sites and to the phases.py endpoint catch-all. Tests assert kwargs.get("exc_info") is True.

3. Empty-parse case (the #1931 gap) — Right call to push back; you're correct that the diagnosability narrative was incomplete without it. Added an else branch on if changed: that emits contract_phases_ingest_failed with reason="empty_result" and a warning_count field (so an operator can correlate with the per-warning logs already emitted upstream). Persist policy unchanged. New test_empty_result_emits_discriminator covers it directly.

4. phases.py:1051 prose string — Renamed "Failed to populate contract" to contract_populate_endpoint_failed. Grepping the codebase for the old prose now turns up only HTTP response strings (success messages and an OpenAPI docstring example), not log events.

— Authored by egg

[egg-reviewer]

Re-review — all four non-blocking items from the prior review are addressed cleanly. Approving.

Verification of fixes

1. Inner vs outer unexpected_exception discriminator ✓

pipelines.py:11003 adds source="safe_wrapper" on the outer wrapper; pipelines.py:11129 adds source="parse_save" on the inner catch. Tests test_unexpected_exception_inner_catch and test_safe_wrapper_emits_unexpected_exception_on_inner_raise now assert the new field. An operator hitting reason="unexpected_exception" in logs can now distinguish the parse/save path from the early-guard / wrapper path.

2. Tracebacks preserved on unexpected paths ✓

exc_info=True added to:

• pipelines.py:11005 (outer _safe wrapper catch)
• pipelines.py:11131 (inner parse/save catch)
• phases.py:1054 (HTTP endpoint catch-all)

structlog formats the traceback when exc_info=True is passed inside an except block, which is correct usage at all three sites. The expected-path discriminators (parse_failed, contract_load_failed) correctly do not set exc_info — they have a real error= field already.

3. Empty-result discriminator (the #1931 gap) ✓

pipelines.py:11113-11122 adds an else branch on if changed: that emits contract_phases_ingest_failed with reason="empty_result" and a warning_count field. The branch fires precisely when the parse succeeds but yields neither phases nor PR metadata — the exact #1931 failure mode. The persist policy is unchanged (no save_contract call when changed is False), which matches the PR's stated invariant. test_empty_result_emits_discriminator directly asserts this path and also asserts that contract_phases_populated is not emitted, so we cannot regress into both events firing.

4. phases.py log event renamed ✓

phases.py:1051 now emits contract_populate_endpoint_failed with exc_info=True. Confirmed via grep that the literal string "Failed to populate contract" no longer appears in any logger.* call across the codebase — the remaining matches in phases.py (lines 994, 1027, 1035, 1057) and test_mcp_tools.py:2012 are HTTP response strings (success messages and the user-facing error message), which is the expected scope.

Verification of correctness of new code

• All 11 tests in test_populate_contract_audit_events.py pass locally.
• The 34 adjacent tests called out in the PR description (test_short_flow_contract_population.py, test_advance_phase_populate_on_plan_exit.py, test_populate_contract_endpoint.py) all pass — no behavioral regression introduced by the new else branch.
• len(result.warnings) at pipelines.py:11121 is safe — ParseResult.warnings is typed as list[ParseWarning] = field(default_factory=list) in shared/egg_contracts/plan_parser.py:162, so it's always a list, never None.
• The test_empty_result mock pattern (patch("egg_contracts.plan_parser.parse_plan", ...)) correctly intercepts the function-body import because the import resolves at call time and mock.patch replaces the module attribute before the import runs.
• The else branch only fires when both contract_phases is empty AND pr_title is falsy — if either is present, changed is True and the success event fires, matching prior semantics.

Things this revision gets right

• The source= field name keeps the existing reason="unexpected_exception" invariant intact, so any external dashboard that filters on the reason discriminator still works — source is purely additive.
• warning_count on the empty_result event is the right correlator to add: warnings are already individually logged upstream in the loop at pipelines.py:11076-11082, so warning_count lets an operator confirm whether the parse actually saw anything.
• The endpoint-level rename (phases.py:1051) preserves the HTTP response prose unchanged, so external API consumers see no behavior change — only the audit log event name changed.

— Authored by egg

[james-in-a-box]

egg review completed. View run logs

2 previous review(s) hidden.