From d047455ee66d3d75d825966c5744a76688866fde Mon Sep 17 00:00:00 2001 From: James Wiesebron Date: Wed, 29 Apr 2026 23:51:55 -0700 Subject: [PATCH 1/2] Fix #2346: emit worktree_sync_outcome at every _sync_worktree_with_remote return MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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). --- orchestrator/routes/pipelines.py | 141 ++++++++---- orchestrator/tests/test_sync_worktree.py | 279 +++++++++++++++++++++-- 2 files changed, 366 insertions(+), 54 deletions(-) diff --git a/orchestrator/routes/pipelines.py b/orchestrator/routes/pipelines.py index 540072769c..479f7d2a75 100644 --- a/orchestrator/routes/pipelines.py +++ b/orchestrator/routes/pipelines.py @@ -5276,6 +5276,11 @@ def _sync_worktree_with_remote( mode=gateway_mode, ) if not fetch_ok: + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + case="fetch_failed", + ) return # Step 2: Determine current branch @@ -5289,8 +5294,19 @@ def _sync_worktree_with_remote( ) branch = result.stdout.strip() if not branch: - return # Detached HEAD — nothing to sync - except Exception: + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + case="detached_head", + ) + return + except Exception as branch_err: + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + case="branch_detect_failed", + error=str(branch_err), + ) return # Step 3: Verify remote tracking branch exists @@ -5303,13 +5319,27 @@ def _sync_worktree_with_remote( check=False, ) if result.returncode != 0: - return # Remote branch not yet published (first pipeline run) - except Exception: + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + branch=branch, + case="no_remote_tracking", + ) + return + except Exception as rev_parse_err: + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + branch=branch, + case="rev_parse_failed", + error=str(rev_parse_err), + ) return # Step 3b: Check divergence between local and remote. local_ahead = 0 remote_ahead = 0 + rev_list_ok = False try: result = subprocess.run( [*git_base, "rev-list", "--left-right", "--count", f"HEAD...origin/{branch}"], @@ -5323,21 +5353,36 @@ def _sync_worktree_with_remote( if len(parts) == 2: local_ahead = int(parts[0]) remote_ahead = int(parts[1]) - except Exception: - pass # If check fails, proceed with reset (best-effort) + rev_list_ok = True + except Exception as rev_list_err: + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + branch=branch, + case="rev_list_failed", + error=str(rev_list_err), + ) + # Fall through to reset (best-effort) — step 4 will emit its own outcome. # Step 3c: Handle local-ahead commits. + if local_ahead == 0 and remote_ahead == 0 and rev_list_ok: + # Local and remote are already in sync — skip the no-op reset entirely + # so the outcome is distinguishable from a true behind-remote sync. + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + branch=branch, + case="already_in_sync", + local_ahead=0, + remote_ahead=0, + ) + return + if local_ahead > 0 and remote_ahead == 0: # Local is strictly ahead of remote (no divergence). if prior_phase_succeeded: # Prior phase completed successfully — push local work to remote # before resetting, so it's not lost. - logger.info( - "Prior phase succeeded — pushing local-ahead commits to remote", - pipeline_id=pipeline_id, - branch=branch, - local_ahead=local_ahead, - ) push_ok = spawner.gateway.push_worktree_branch( pipeline_id=pipeline_id, repo_path=str(worktree_repo_path), @@ -5354,33 +5399,30 @@ def _sync_worktree_with_remote( repo_path=str(worktree_repo_path), mode=gateway_mode, ) - return # Already in sync — no reset needed + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + branch=branch, + case="local_ahead_pushed", + local_ahead=local_ahead, + remote_ahead=remote_ahead, + ) + return else: logger.warning( - "Failed to push local-ahead commits (continuing with reset)", + "worktree_sync_outcome", pipeline_id=pipeline_id, branch=branch, + case="local_ahead_push_failed", + local_ahead=local_ahead, + remote_ahead=remote_ahead, ) - else: - # Prior phase failed — discard incomplete local work. - logger.info( - "Prior phase failed — discarding local-ahead commits", - pipeline_id=pipeline_id, - branch=branch, - local_ahead=local_ahead, - ) - # Fall through to reset (Step 4) + # Fall through to reset (Step 4) — discards local work when prior phase + # failed, or recovers via reset after a push failure. elif local_ahead > 0 and remote_ahead > 0: # Divergence: local and remote both have unique commits. # Attempt fast-forward merge to reconcile. - logger.info( - "Local and remote have diverged — attempting merge", - pipeline_id=pipeline_id, - branch=branch, - local_ahead=local_ahead, - remote_ahead=remote_ahead, - ) try: merge_result = subprocess.run( [*git_base, "merge", "--ff-only", f"origin/{branch}"], @@ -5391,32 +5433,40 @@ def _sync_worktree_with_remote( ) if merge_result.returncode == 0: logger.info( - "Fast-forward merge succeeded", + "worktree_sync_outcome", pipeline_id=pipeline_id, branch=branch, + case="diverged_ff_succeeded", + local_ahead=local_ahead, + remote_ahead=remote_ahead, ) - return # Merge succeeded — worktree is now in sync + return else: logger.error( - "Cannot fast-forward merge diverged branches — " - "pipeline may need manual intervention", + "worktree_sync_outcome", pipeline_id=pipeline_id, branch=branch, + case="diverged_ff_failed", local_ahead=local_ahead, remote_ahead=remote_ahead, error=merge_result.stderr.strip(), ) - return # Don't force-reset on divergence — signal the problem + return except Exception as merge_err: logger.error( - "Merge attempt failed", + "worktree_sync_outcome", pipeline_id=pipeline_id, + branch=branch, + case="diverged_ff_failed", + local_ahead=local_ahead, + remote_ahead=remote_ahead, error=str(merge_err), ) return # Step 4: Reset local branch to remote. - # This handles: local behind remote, local in-sync, and post-push reset. + # This handles: local behind remote, post-push reset, and rev-list-failed + # fall-through. (The already-in-sync case returns early above.) try: result = subprocess.run( [*git_base, "reset", "--hard", f"origin/{branch}"], @@ -5427,20 +5477,31 @@ def _sync_worktree_with_remote( ) if result.returncode != 0: logger.warning( - "Failed to reset worktree to remote (continuing with local state)", + "worktree_sync_outcome", pipeline_id=pipeline_id, + branch=branch, + case="reset_failed", + local_ahead=local_ahead, + remote_ahead=remote_ahead, error=result.stderr.strip(), ) else: logger.info( - "Synced worktree with remote branch", + "worktree_sync_outcome", pipeline_id=pipeline_id, branch=branch, + case="reset_succeeded", + local_ahead=local_ahead, + remote_ahead=remote_ahead, ) except Exception as sync_err: logger.warning( - "Failed to reset worktree to remote (continuing with local state)", + "worktree_sync_outcome", pipeline_id=pipeline_id, + branch=branch, + case="reset_failed", + local_ahead=local_ahead, + remote_ahead=remote_ahead, error=str(sync_err), ) diff --git a/orchestrator/tests/test_sync_worktree.py b/orchestrator/tests/test_sync_worktree.py index 3cb76cc8cc..59c9dc5f13 100644 --- a/orchestrator/tests/test_sync_worktree.py +++ b/orchestrator/tests/test_sync_worktree.py @@ -147,8 +147,8 @@ def test_local_behind_remote_fetches_then_resets(self): assert "reset" in reset_call[0][0] assert "--hard" in reset_call[0][0] - def test_local_in_sync_no_push_needed(self): - """(d) local in sync → no push, reset is a no-op.""" + def test_local_in_sync_returns_early_without_reset(self): + """(d) local in sync → no push, no reset (early return on already_in_sync).""" spawner = _make_spawner() with patch("routes.pipelines.subprocess.run") as mock_run: mock_run.side_effect = [ @@ -158,12 +158,11 @@ def test_local_in_sync_no_push_needed(self): _make_subprocess_result(returncode=0), # Step 3b: local is 0 ahead, 0 behind _make_subprocess_result(stdout="0\t0\n"), - # Step 4: reset succeeds (no-op when in sync) - _make_subprocess_result(returncode=0), ] _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) spawner.gateway.push_worktree_branch.assert_not_called() - assert mock_run.call_count == 4 + # Already-in-sync skips the step-4 reset entirely. + assert mock_run.call_count == 3 def test_push_fails_continues_with_reset(self): """(e) push fails → logs warning, continues with reset.""" @@ -234,14 +233,10 @@ def test_diverged_merge_fails_signals_error(self): _make_subprocess_result(returncode=1, stderr="fatal: Not possible to fast-forward"), ] _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) - # Error should be logged + # Error should be logged with the diverged_ff_failed case label. mock_logger.error.assert_called() - error_msg = mock_logger.error.call_args[0][0] - assert ( - "fast-forward" in error_msg.lower() - or "merge" in error_msg.lower() - or "diverged" in error_msg.lower() - ) + error_kwargs = mock_logger.error.call_args.kwargs + assert error_kwargs.get("case") == "diverged_ff_failed" def test_successful_reset(self): """Happy path: fetch, detect branch, verify remote, reset.""" @@ -283,8 +278,8 @@ def test_logs_warning_on_failed_reset(self): ] _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) mock_logger.warning.assert_called() - warning_msg = mock_logger.warning.call_args[0][0] - assert "Failed to reset" in warning_msg + warning_kwargs = mock_logger.warning.call_args.kwargs + assert warning_kwargs.get("case") == "reset_failed" def test_handles_subprocess_timeout(self): """If subprocess raises TimeoutExpired, function handles gracefully.""" @@ -377,3 +372,259 @@ def test_rev_list_check_fails_proceeds_to_reset(self): assert mock_run.call_count == 4 reset_call = mock_run.call_args_list[3] assert "reset" in reset_call[0][0] + + +def _outcome_cases(mock_logger: MagicMock) -> list[str]: + """Return the `case=` values from every worktree_sync_outcome log call, in order.""" + cases: list[str] = [] + # method_calls preserves call order across info/warning/error. + for call in mock_logger.method_calls: + if call[0] not in ("info", "warning", "error"): + continue + args = call.args + kwargs = call.kwargs + if args and args[0] == "worktree_sync_outcome" and "case" in kwargs: + cases.append(kwargs["case"]) + return cases + + +class TestSyncWorktreeOutcomeTaxonomy: + """Each return path emits worktree_sync_outcome with the expected case label.""" + + def test_case_fetch_failed(self): + spawner = _make_spawner(fetch_ok=False) + with patch("routes.pipelines.logger") as mock_logger: + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["fetch_failed"] + + def test_case_detached_head(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.return_value = _make_subprocess_result(stdout="") + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["detached_head"] + + def test_case_branch_detect_failed(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = subprocess.TimeoutExpired(cmd="git", timeout=10) + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["branch_detect_failed"] + + def test_case_no_remote_tracking(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=128), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["no_remote_tracking"] + + def test_case_rev_parse_failed(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + subprocess.TimeoutExpired(cmd="git rev-parse", timeout=10), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["rev_parse_failed"] + + def test_case_rev_list_failed_falls_through_to_reset(self): + """rev-list exception emits rev_list_failed, then step 4 emits reset_succeeded.""" + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + # rev-list returns two non-numeric tokens → int() raises ValueError + _make_subprocess_result(stdout="foo\tbar\n"), + # Step 4: reset succeeds + _make_subprocess_result(returncode=0), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["rev_list_failed", "reset_succeeded"] + + def test_case_already_in_sync(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="0\t0\n"), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["already_in_sync"] + + def test_case_local_ahead_pushed(self): + spawner = _make_spawner(push_ok=True) + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="2\t0\n"), + ] + _sync_worktree_with_remote( + spawner, "pipe-1", Path("/tmp/repo"), prior_phase_succeeded=True + ) + assert _outcome_cases(mock_logger) == ["local_ahead_pushed"] + + def test_case_local_ahead_push_failed_falls_through_to_reset(self): + """Push failure emits local_ahead_push_failed, then step 4 emits reset_succeeded.""" + spawner = _make_spawner(push_ok=False) + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="2\t0\n"), + _make_subprocess_result(returncode=0), + ] + _sync_worktree_with_remote( + spawner, "pipe-1", Path("/tmp/repo"), prior_phase_succeeded=True + ) + assert _outcome_cases(mock_logger) == [ + "local_ahead_push_failed", + "reset_succeeded", + ] + + def test_case_diverged_ff_succeeded(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="2\t3\n"), + _make_subprocess_result(returncode=0), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["diverged_ff_succeeded"] + + def test_case_diverged_ff_failed_returncode(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="2\t3\n"), + _make_subprocess_result(returncode=1, stderr="not possible to fast-forward"), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["diverged_ff_failed"] + + def test_case_diverged_ff_failed_exception(self): + """Subprocess crash during ff-merge collapses into diverged_ff_failed.""" + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="2\t3\n"), + subprocess.TimeoutExpired(cmd="git merge", timeout=30), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["diverged_ff_failed"] + + def test_case_reset_succeeded(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="0\t3\n"), + _make_subprocess_result(returncode=0), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["reset_succeeded"] + + def test_case_reset_failed_returncode(self): + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="0\t3\n"), + _make_subprocess_result(returncode=1, stderr="permission denied"), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["reset_failed"] + + def test_case_reset_failed_exception(self): + """Subprocess crash during reset collapses into reset_failed.""" + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="0\t3\n"), + subprocess.TimeoutExpired(cmd="git reset", timeout=30), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["reset_failed"] + + def test_counters_present_when_known(self): + """local_ahead/remote_ahead are included in the structured log when known.""" + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="0\t3\n"), + _make_subprocess_result(returncode=0), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + # Find the reset_succeeded call + reset_call = next( + c + for c in mock_logger.info.call_args_list + if c.args + and c.args[0] == "worktree_sync_outcome" + and c.kwargs.get("case") == "reset_succeeded" + ) + assert reset_call.kwargs["local_ahead"] == 0 + assert reset_call.kwargs["remote_ahead"] == 3 From e72453b1f911503d1020a0a44e3f7e2e4bfccd4c Mon Sep 17 00:00:00 2001 From: "egg-reviewer[bot]" <261018737+egg-reviewer[bot]@users.noreply.github.com> Date: Thu, 30 Apr 2026 07:13:49 +0000 Subject: [PATCH 2/2] Address #2349 review: emit rev_list_failed on non-exception paths, surface PushResult, add local_ahead_discarded MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 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. --- orchestrator/routes/pipelines.py | 40 +++++++++--- orchestrator/tests/test_sync_worktree.py | 79 ++++++++++++++++++++++++ 2 files changed, 111 insertions(+), 8 deletions(-) diff --git a/orchestrator/routes/pipelines.py b/orchestrator/routes/pipelines.py index 479f7d2a75..9314fc8e3d 100644 --- a/orchestrator/routes/pipelines.py +++ b/orchestrator/routes/pipelines.py @@ -5348,12 +5348,21 @@ def _sync_worktree_with_remote( timeout=10, check=False, ) - if result.returncode == 0: - parts = result.stdout.strip().split() - if len(parts) == 2: - local_ahead = int(parts[0]) - remote_ahead = int(parts[1]) - rev_list_ok = True + parts = result.stdout.strip().split() + 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], + ) + # Fall through to reset (best-effort) — step 4 will emit its own outcome. except Exception as rev_list_err: logger.info( "worktree_sync_outcome", @@ -5383,14 +5392,14 @@ def _sync_worktree_with_remote( if prior_phase_succeeded: # Prior phase completed successfully — push local work to remote # before resetting, so it's not lost. - push_ok = spawner.gateway.push_worktree_branch( + push_result = spawner.gateway.push_worktree_branch( pipeline_id=pipeline_id, repo_path=str(worktree_repo_path), branch=branch, mode=gateway_mode, base_branch=base_branch_for_reconcile, ) - if push_ok: + if push_result: # Push succeeded — local and remote are now in sync. # Re-fetch to update the remote tracking ref so that # origin/{branch} reflects the pushed commits. @@ -5416,7 +5425,22 @@ def _sync_worktree_with_remote( case="local_ahead_push_failed", local_ahead=local_ahead, remote_ahead=remote_ahead, + category=push_result.category, + error=push_result.detail, ) + else: + # Prior phase failed — incomplete local work will be discarded by + # the step-4 reset. Emit a distinct case so operators can grep + # this branch of the taxonomy without inferring it from + # reset_succeeded with local_ahead > 0. + logger.info( + "worktree_sync_outcome", + pipeline_id=pipeline_id, + branch=branch, + case="local_ahead_discarded", + local_ahead=local_ahead, + remote_ahead=remote_ahead, + ) # Fall through to reset (Step 4) — discards local work when prior phase # failed, or recovers via reset after a push failure. diff --git a/orchestrator/tests/test_sync_worktree.py b/orchestrator/tests/test_sync_worktree.py index 59c9dc5f13..c02e8909a8 100644 --- a/orchestrator/tests/test_sync_worktree.py +++ b/orchestrator/tests/test_sync_worktree.py @@ -461,6 +461,49 @@ def test_case_rev_list_failed_falls_through_to_reset(self): _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) assert _outcome_cases(mock_logger) == ["rev_list_failed", "reset_succeeded"] + def test_case_rev_list_failed_returncode_falls_through_to_reset(self): + """rev-list non-zero returncode emits rev_list_failed (no exception path).""" + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + # rev-list exits non-zero — must still emit rev_list_failed + _make_subprocess_result(returncode=128, stderr="bad ref"), + _make_subprocess_result(returncode=0), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["rev_list_failed", "reset_succeeded"] + # The rev_list_failed log carries the rc field for non-exception failures. + rev_list_call = next( + c + for c in mock_logger.info.call_args_list + if c.args + and c.args[0] == "worktree_sync_outcome" + and c.kwargs.get("case") == "rev_list_failed" + ) + assert rev_list_call.kwargs.get("rc") == 128 + + def test_case_rev_list_failed_unparseable_output(self): + """rev-list returncode=0 but malformed output emits rev_list_failed.""" + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + # rev-list rc=0 but only one token — len(parts) != 2 + _make_subprocess_result(stdout="42\n"), + _make_subprocess_result(returncode=0), + ] + _sync_worktree_with_remote(spawner, "pipe-1", Path("/tmp/repo")) + assert _outcome_cases(mock_logger) == ["rev_list_failed", "reset_succeeded"] + def test_case_already_in_sync(self): spawner = _make_spawner() with ( @@ -511,6 +554,42 @@ def test_case_local_ahead_push_failed_falls_through_to_reset(self): "local_ahead_push_failed", "reset_succeeded", ] + # PushResult diagnostics are propagated into the structured log so + # operators don't need to pull gateway-side logs for the failure mode. + push_failed_call = next( + c + for c in mock_logger.warning.call_args_list + if c.args + and c.args[0] == "worktree_sync_outcome" + and c.kwargs.get("case") == "local_ahead_push_failed" + ) + assert push_failed_call.kwargs.get("category") == "test" + assert push_failed_call.kwargs.get("error") == "mock failure" + + def test_case_local_ahead_discarded(self): + """Prior phase failed + local-ahead → emit local_ahead_discarded then reset.""" + spawner = _make_spawner() + with ( + patch("routes.pipelines.subprocess.run") as mock_run, + patch("routes.pipelines.logger") as mock_logger, + ): + mock_run.side_effect = [ + _make_subprocess_result(stdout="egg/issue-42\n"), + _make_subprocess_result(returncode=0), + _make_subprocess_result(stdout="2\t0\n"), + _make_subprocess_result(returncode=0), + ] + _sync_worktree_with_remote( + spawner, + "pipe-1", + Path("/tmp/repo"), + prior_phase_succeeded=False, + ) + spawner.gateway.push_worktree_branch.assert_not_called() + assert _outcome_cases(mock_logger) == [ + "local_ahead_discarded", + "reset_succeeded", + ] def test_case_diverged_ff_succeeded(self): spawner = _make_spawner()