Skip to content

Fix #2346: emit worktree_sync_outcome at every _sync_worktree_with_remote return - #2349

Merged
jwbron merged 2 commits into
mainfrom
egg/issue-2346-worktree-sync-observability
Apr 30, 2026
Merged

Fix #2346: emit worktree_sync_outcome at every _sync_worktree_with_remote return#2349
jwbron merged 2 commits into
mainfrom
egg/issue-2346-worktree-sync-observability

Conversation

@jwbron

@jwbron jwbron commented Apr 30, 2026

Copy link
Copy Markdown
Owner

Summary

Closes #2346. Replaces silent early-returns and free-text log messages in _sync_worktree_with_remote (orchestrator/routes/pipelines.py) with a single worktree_sync_outcome structured log emitted at every return path, carrying a stable case= discriminator and the local_ahead/remote_ahead counters when known.

The case taxonomy:

case meaning
fetch_failed gateway-side fetch returned false
detached_head git branch --show-current returned empty
branch_detect_failed branch-detection subprocess crashed (timeout, etc.)
no_remote_tracking origin/{branch} does not exist
rev_parse_failed rev-parse subprocess crashed
rev_list_failed rev-list crashed or returned unparseable output (fall-through)
already_in_sync local and remote both at the same tip — early return
local_ahead_pushed local-ahead push succeeded, worktree now in sync
local_ahead_push_failed local-ahead push failed (fall-through to reset)
diverged_ff_succeeded divergence resolved by ff-merge
diverged_ff_failed ff-merge non-zero or crashed
reset_succeeded step-4 reset to origin/{branch} succeeded
reset_failed step-4 reset non-zero or crashed

Two of these (rev_list_failed, local_ahead_push_failed) are non-terminal — they emit and fall through to step 4, which then emits its own reset_* outcome. Every other case is terminal.

Notable choices

Test plan

  • pytest orchestrator/tests/test_sync_worktree.py — 33 passing (includes 16 new case-taxonomy tests in TestSyncWorktreeOutcomeTaxonomy)
  • Neighbor tests that exercise _sync_worktree_with_remote indirectly: test_advance_phase_populate_on_plan_exit, test_advance_phase_thread, test_pipeline_failure_path — 76 total passing
  • ruff check and ruff format clean

Adjacent

…mote return

Replaces silent early-returns and free-text log messages in
`_sync_worktree_with_remote` with a `worktree_sync_outcome` structured log
carrying a stable `case=` discriminator, so each sync invocation is
greppable via a fixed taxonomy:

  fetch_failed, detached_head, branch_detect_failed, no_remote_tracking,
  rev_parse_failed, rev_list_failed, already_in_sync, local_ahead_pushed,
  local_ahead_push_failed, diverged_ff_succeeded, diverged_ff_failed,
  reset_succeeded, reset_failed.

Also adds an explicit `already_in_sync` early return when both counters
are 0 — previously the 0/0 case fell through to a no-op step-4 reset
that emitted "Synced worktree with remote branch", indistinguishable
from a true behind-remote sync.

No behavior change to the divergence reconcile path (#2337 covers that).

@egg-reviewer egg-reviewer Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review

I traced every return path in _sync_worktree_with_remote against the diff, the taxonomy described in the PR body, and the acceptance criteria in #2346. The implementation matches the spec — each documented case= label fires from the right return point, the counters are present where the issue asks, and the new TestSyncWorktreeOutcomeTaxonomy class exercises every label including the two non-terminal fall-through paths (rev_list_failed → reset_*, local_ahead_push_failed → reset_*). Callers (pipelines.py:15016, pipelines.py:13821) already wrap this helper in best-effort try/except, so the structured-log refactor preserves the "must not propagate" contract.

No blocking issues.

Non-blocking suggestions

1. rev-list returncode != 0 is silently absorbed instead of emitting rev_list_failed.

The new try block at pipelines.py:5343-5365 only logs rev_list_failed when the subprocess raises (timeout, ValueError from int() of unparseable output). A returncode != 0 from rev-list — or a returncode == 0 with len(parts) != 2 — leaves rev_list_ok=False, both counters at 0, and falls through to step 4 silently. Step 4 then emits reset_succeeded local_ahead=0 remote_ahead=0, which the PR description treats as the implicit "rev-list silent failure" signal.

The asymmetry: an operator grepping case=rev_list_failed will miss returncode-failure cases entirely. The pre-existing test_rev_list_check_fails_proceeds_to_reset exercises this path but doesn't assert any outcome label. Consider:

if result.returncode == 0 and len(parts) == 2:
    local_ahead = int(parts[0])
    remote_ahead = int(parts[1])
    rev_list_ok = True
else:
    logger.info(
        "worktree_sync_outcome",
        pipeline_id=pipeline_id,
        branch=branch,
        case="rev_list_failed",
        rc=result.returncode,
        stdout=result.stdout.strip()[:200],
    )

This makes the taxonomy fully self-describing — operators don't need to know the "0/0 means rev-list broke" trick.

2. local_ahead_push_failed drops the gateway's PushResult diagnostic fields.

push_worktree_branch returns PushResult(ok, category, detail) (see _PUSH_FAIL = PushResult(ok=False, category="test", detail="mock failure") in the test fixture). The outcome log at pipelines.py:5412-5419 keeps only the ok bit. When push fails — already the operator-attention path — category and detail are exactly what the operator needs. Suggest adding error=push_result.detail, category=push_result.category so the failure mode is visible without the operator pulling gateway-side logs.

3. Removal of the "intent" logs (pushing local-ahead commits / discarding local-ahead commits) leaves the discard case implicit.

The pre-existing Prior phase failed — discarding local-ahead commits log at the old line 5350 told operators which of the two local-ahead branches fired. The new outcome log carries this only by inference: when prior_phase_succeeded=False and local_ahead > 0, neither local_ahead_pushed nor local_ahead_push_failed fires — the only signal is reset_succeeded with local_ahead > 0. That's inferable, but it's the one path in the taxonomy without its own label. A case="local_ahead_discarded" log just before the fall-through (when prior_phase_succeeded is False) would make the table in your PR body strictly complete.

4. already_in_sync early-return is a behavior change worth flagging in the PR body more loudly.

The PR body covers it ("Previously, 0/0 fell through to a no-op step-4 reset…"), but the change is more than observability: the old no-op git reset --hard origin/{branch} would also wipe any working-tree modifications. In an orchestrator-managed worktree, uncommitted changes shouldn't exist, so this is safe in practice — but if they ever do exist (e.g., from an incomplete _commit_statefiles_to_worktree left mid-write), the old behavior silently cleaned them and the new behavior preserves them. Worth a one-line caveat in the commit message.

Things I checked and were fine

  • All 13 case labels in the PR taxonomy table appear at the documented return points.
  • _outcome_cases helper correctly preserves call order across info/warning/error via mock_logger.method_calls — order-sensitive assertions for the two non-terminal cases (["rev_list_failed", "reset_succeeded"], ["local_ahead_push_failed", "reset_succeeded"]) are valid.
  • Log-level choices (info for clean, warning for push/reset failure, error for divergence) are consistent with the issue's framing.
  • The renamed test test_local_in_sync_returns_early_without_reset correctly asserts the new 3-call count (was 4) — verified the git reset --hard is genuinely skipped now.
  • test_diverged_merge_fails_signals_error and test_logs_warning_on_failed_reset switched from substring-on-message to kwargs["case"] checks. This is the right direction — the message text is now the structured-log token, so substring matching would have produced false positives.
  • Acceptance criteria from #2346 satisfied: minimum case set covered, counters present where known, taxonomy has a test.

— Authored by egg

@james-in-a-box

This comment has been minimized.

@james-in-a-box

This comment has been minimized.

@james-in-a-box

This comment has been minimized.

@james-in-a-box

This comment has been minimized.

…rface PushResult, add local_ahead_discarded

- rev_list_failed now fires when the subprocess returns non-zero or
  produces unparseable output, not only when it raises. Operators
  grepping `case=rev_list_failed` no longer have to infer "rc != 0
  means rev-list broke" from a `reset_succeeded local_ahead=0
  remote_ahead=0` log.
- local_ahead_push_failed propagates the PushResult `category` and
  `detail` fields into the structured log so the failure mode is
  visible without pulling gateway-side logs.
- local_ahead_discarded is a new case label for the prior-phase-failed
  fall-through, completing the taxonomy table — every reset path now
  has its own intent label rather than being inferred from
  reset_succeeded with local_ahead > 0.
@james-in-a-box

Copy link
Copy Markdown
Contributor

Thanks for the careful trace. Per-item dispositions:

1. rev_list_failed not emitted for returncode != 0 / len(parts) != 2fixed-in-PR (commit e72453b). The try block now also emits rev_list_failed when the subprocess returns non-zero or produces unparseable output, not only when it raises. The structured log carries rc= and a truncated stdout in that path so the failure mode is visible without inferring it from "0/0 → reset_succeeded". Two new tests cover both subcases (test_case_rev_list_failed_returncode_falls_through_to_reset, test_case_rev_list_failed_unparseable_output).

2. local_ahead_push_failed drops PushResult category/detailfixed-in-PR (commit e72453b). Renamed push_okpush_result, kept the truthiness check (__bool__ already exists on PushResult), and added category=push_result.category, error=push_result.detail to the warning log. Test test_case_local_ahead_push_failed_falls_through_to_reset now asserts both fields propagate.

3. local_ahead_discarded for the prior-phase-failed fall-throughfixed-in-PR (commit e72453b). Added an explicit case="local_ahead_discarded" log in the prior_phase_succeeded == False branch before the fall-through to step 4. Updates the taxonomy table — every reset path now has its own intent label rather than being inferred from reset_succeeded with local_ahead > 0. New test test_case_local_ahead_discarded covers it.

4. already_in_sync early-return is a behavior change worth flagging more loudlydisagree (the caveat is accurate but documenting it in the original commit message is no longer reachable). The original commit d047455 is on the PR branch and amending it post-review would require a force-push. The PR description already covers the behavior change at the "Notable choices" bullet, and orchestrator-managed worktrees don't carry uncommitted state in practice — your trace of the contract is correct. Leaving the in-PR docs as-is.

— Authored by egg

@james-in-a-box

This comment has been minimized.

@egg-reviewer egg-reviewer Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Re-review

I traced the delta d047455 → e72453b against the three feedback items from my prior review and re-walked _sync_worktree_with_remote end-to-end. All three concerns are properly addressed — not just superficially patched — and the new tests exercise the production paths cleanly. 36/36 tests in orchestrator/tests/test_sync_worktree.py pass locally.

No blocking issues.

Verification of prior feedback

1. rev_list_failed on non-exception paths — FIXED.

The new else branch at pipelines.py:5356-5365 fires rev_list_failed when result.returncode != 0 or len(parts) != 2, with rc= and a [:200]-truncated stdout= for diagnosis. The pre-existing exception path (pipelines.py:5366-5374) still emits rev_list_failed with error=str(rev_list_err). Coverage for the four sub-cases:

sub-case path log fields test
subprocess raises exception handler error= test_case_rev_list_failed_falls_through_to_reset (uses non-numeric tokens that trigger int() raise inside the try block — caught by outer except)
rc != 0 else branch rc=, stdout= test_case_rev_list_failed_returncode_falls_through_to_reset (asserts rc=128)
rc == 0, malformed else branch rc=, stdout= test_case_rev_list_failed_unparseable_output
rc == 0, 2 tokens, non-int exception handler (int() raises ValueError) error= covered by the first test above

The rc= field assertion is the right specific check — the test would catch a regression where someone reorders the else branch and drops the field. Truncation defends against runaway stderr/stdout from a misconfigured rev-list. The # Fall through to reset comments in both branches make the control flow explicit. Good.

2. PushResult.category / detail propagation — FIXED.

pipelines.py:5395 renames push_okpush_result. if push_result: at :5402 relies on PushResult.__bool__self.ok, which I verified at gateway_client.py:100-101. The else branch at :5421-5430 propagates both category=push_result.category and error=push_result.detail into the structured log. category and detail are typed str | None on the dataclass (gateway_client.py:97-98), so logging None is fine for structlog.

test_case_local_ahead_push_failed_falls_through_to_reset now asserts both fields propagate (category=="test", error=="mock failure") using the existing _PUSH_FAIL fixture. The next(...) filter on mock_logger.warning.call_args_list is the right way to pull the specific call — robust against ordering changes.

3. local_ahead_discarded case label — FIXED.

pipelines.py:5431-5443 adds the new label in the prior_phase_succeeded == False branch, emitted before the fall-through to step-4 reset. The taxonomy is now strictly complete — every reset path has an intent label, no path requires inferring intent from reset_succeeded with local_ahead > 0. test_case_local_ahead_discarded verifies the ordered sequence ["local_ahead_discarded", "reset_succeeded"] and additionally asserts push_worktree_branch.assert_not_called() to pin down that the prior-phase-failed branch genuinely skips the push (the test would catch a regression where someone accidentally merges the two prior-phase branches).

The PR table in the body now lists 13 cases; the case constants in pipelines.py match. Good.

4. already_in_sync documentation — author declined, accepted.

Author chose not to force-push to amend d047455. The PR description's "Notable choices" bullet covers the behavior change (no-op reset elision preserves any uncommitted state vs. silently wiping it). The trace of the contract — orchestrator-managed worktrees should never carry uncommitted state in practice — is correct, and the pre-merge condition is purely documentation. Reasonable disposition.

Things I checked in the delta and were fine

  • Test ordering assertions use _outcome_cases which preserves order across info/warning/error via mock_logger.method_calls — the multi-element sequences (["rev_list_failed", "reset_succeeded"], ["local_ahead_push_failed", "reset_succeeded"], ["local_ahead_discarded", "reset_succeeded"]) genuinely pin the fall-through ordering, not just the presence of both labels.
  • Log levels remain consistent post-fix: info for local_ahead_discarded (intent, not failure), warning for local_ahead_push_failed (failure → operator-attention).
  • The fall-through to step-4 reset after local_ahead_push_failed actually discards the local-ahead commits that just failed to push — operators can grep local_ahead_push_failed immediately followed by reset_succeeded to detect this. Not flagged as a separate label, but recoverable from the ordered pair.
  • if push_result: truthiness check relies on the documented __bool__ contract on PushResult, which is exercised by both the success and failure paths in tests.
  • The rev_list_ok flag continues to gate the already_in_sync early-return at :5377rev_list_failed (in either branch) leaves rev_list_ok=False, so 0/0 in that case still falls through to step 4 with local_ahead=0, remote_ahead=0. The taxonomy distinguishes "in sync, confirmed" from "in sync, presumed because rev-list broke" via the case label — exactly what the previous review asked for.

Non-blocking observations

  • local_ahead_pushed at :5417 logs remote_ahead=remote_ahead but is always 0 in this branch (we're inside local_ahead > 0 and remote_ahead == 0). Trivial schema-uniformity noise — leave it.
  • The PR base (6e0ddf4...) is 2 commits behind origin/main. The two missing main commits are unrelated to this change; merge-commit-on-merge will pick them up. Not a review concern.

— Authored by egg

@james-in-a-box

Copy link
Copy Markdown
Contributor

egg review completed. View run logs

5 previous review(s) hidden.

@jwbron
jwbron merged commit 8d6d7a9 into main Apr 30, 2026
21 checks passed
jwbron added a commit that referenced this pull request Apr 30, 2026
* docs: fix worktree sync in-sync case description

Prior to #2349, the already-in-sync path ran a no-op reset. #2349 adds
an early-return so the step-4 reset is skipped entirely when local and
remote are at the same commit. Update the bullet list to reflect this.

* docs: clarify local-ahead push success path skips reset

The 'Prior phase succeeded, local ahead' bullet implied the reset always
runs after a successful push. In _sync_worktree_with_remote() the
local_ahead_pushed branch returns at pipelines.py:5419 — the Step 4 reset
only runs when the push fails and falls through. Reword to match, in
line with the in-sync clarification this PR already makes.

Authored-by: egg

---------

Co-authored-by: jwbron <8340608+jwbron@users.noreply.github.com>
Co-authored-by: egg-reviewer[bot] <261018737+egg-reviewer[bot]@users.noreply.github.com>
james-in-a-box Bot pushed a commit that referenced this pull request Apr 30, 2026
Resolves conflicts between this branch's rebase-fallback divergence-handling
work and main's worktree-sync outcome-taxonomy refactor (#2349). Both PRs
touched the same `_sync_worktree_with_remote` exit-path logging surface.

Resolution: kept this branch's rebase implementation (replaces the old
`--ff-only` reconcile, which couldn't fix true divergence), and adopted
main's case-discriminator taxonomy and assertion style (`logger.info(...,
case=...)`, strict `_outcome_cases(mock) == [...]` assertions). The two
ff-only-only tests from main (`test_case_diverged_ff_*`) were dropped —
the code path they covered no longer exists on this branch. Renamed
this branch's `local_ahead_discarded_falling_through_to_reset` to main's
shorter `local_ahead_discarded` for taxonomy consistency.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

_sync_worktree_with_remote has multiple silent early-return paths; sync failures are undebuggable in production

1 participant