diff --git a/.github/workflows/backend-tests.yml b/.github/workflows/backend-tests.yml index 5c0d3c3e08..087913cac0 100644 --- a/.github/workflows/backend-tests.yml +++ b/.github/workflows/backend-tests.yml @@ -266,11 +266,10 @@ jobs: - name: Run golangci-lint # golangci-lint is preinstalled in the kandev-ci image; invoke it # directly instead of going through `golangci/golangci-lint-action`, - # which would re-download its own binary on every run. `--timeout=5m` - # matches the action's previous implicit default (the binary's own - # default is 1m, which can trip on cold caches). + # which would re-download its own binary on every run. Ten minutes + # leaves headroom for cold caches while still bounding analysis time. shell: bash - run: golangci-lint run ./... --new-from-rev="${BASE_SHA}" --timeout=5m + run: golangci-lint run ./... --new-from-rev="${BASE_SHA}" --timeout=10m test_shards: name: Backend Tests (${{ matrix.shard }}/2) diff --git a/apps/backend/internal/agent/runtime/lifecycle/persistence.go b/apps/backend/internal/agent/runtime/lifecycle/persistence.go index df283a6a5c..695058bd2d 100644 --- a/apps/backend/internal/agent/runtime/lifecycle/persistence.go +++ b/apps/backend/internal/agent/runtime/lifecycle/persistence.go @@ -263,6 +263,28 @@ func (m *Manager) persistExecutorRunning(ctx context.Context, execution *AgentEx _ = m.persistExecutorRunningResult(ctx, execution) } +// buildRunningForPersistence reads a tracked execution while the execution +// store's read lock is held. Status transitions use that store lock, so taking +// the same lock here prevents persistence from racing with an asynchronous +// readiness failure. Callers that are persisting an execution before it is +// tracked still use the mapper directly. +func (m *Manager) buildRunningForPersistence( + execution *AgentExecution, + prior *models.ExecutorRunning, +) *models.ExecutorRunning { + if execution == nil || m.executionStore == nil { + return buildRunningFromExecution(execution, prior) + } + + var running *models.ExecutorRunning + if err := m.executionStore.WithRLock(execution.ID, func(tracked *AgentExecution) { + running = buildRunningFromExecution(tracked, prior) + }); err == nil { + return running + } + return buildRunningFromExecution(execution, prior) +} + func (m *Manager) persistExecutorRunningResult(ctx context.Context, execution *AgentExecution) error { if m.runningWriter == nil { // Permitted in tests that don't exercise persistence; logged so a @@ -305,7 +327,7 @@ func (m *Manager) persistExecutorRunningResult(ctx context.Context, execution *A execution.AgentProfileID = prior.ExecutionProfileID } - running := buildRunningFromExecution(execution, prior) + running := m.buildRunningForPersistence(execution, prior) // Attach the host-local liveness handle for local/standalone rows. Kept out // of buildRunningFromExecution (a pure mapper) because the PID lives on the // manager, wired from the agentctl launcher at DI. resolveLocalPID returns 0 diff --git a/apps/backend/internal/agent/runtime/lifecycle/persistence_test.go b/apps/backend/internal/agent/runtime/lifecycle/persistence_test.go index 14a3a9ec82..b33640d7c3 100644 --- a/apps/backend/internal/agent/runtime/lifecycle/persistence_test.go +++ b/apps/backend/internal/agent/runtime/lifecycle/persistence_test.go @@ -9,6 +9,7 @@ import ( "github.com/kandev/kandev/internal/agentruntime" "github.com/kandev/kandev/internal/task/models" v1 "github.com/kandev/kandev/pkg/api/v1" + "github.com/stretchr/testify/require" ) type captureExecutorRunningWriter struct { @@ -172,6 +173,22 @@ func TestPersistExecutorRunningRestoresRecoveredExecutionProfile(t *testing.T) { } } +func TestPersistExecutorRunningUsesTrackedExecutionStatus(t *testing.T) { + writer := &captureExecutorRunningWriter{} + mgr := newTestManager(t) + mgr.SetExecutorRunningWriter(writer) + execution := &AgentExecution{ + ID: "exec-tracked-status", TaskID: "task-1", SessionID: "session-1", + Status: v1.AgentStatusRunning, + } + require.NoError(t, mgr.executionStore.Add(execution)) + mgr.executionStore.UpdateError(execution.ID, "agentctl not ready") + + require.NoError(t, mgr.persistExecutorRunningResult(context.Background(), execution)) + require.NotNil(t, writer.running) + require.Equal(t, models.ExecutorRunningStatusFailed, writer.running.Status) +} + func TestPersistExecutorRunningReturnsUpsertFailure(t *testing.T) { writer := &captureExecutorRunningWriter{upsertErr: errors.New("database is locked")} mgr := newTestManager(t) diff --git a/apps/backend/internal/agent/runtime/lifecycle/preparer_script.go b/apps/backend/internal/agent/runtime/lifecycle/preparer_script.go index 677faa763a..595d849895 100644 --- a/apps/backend/internal/agent/runtime/lifecycle/preparer_script.go +++ b/apps/backend/internal/agent/runtime/lifecycle/preparer_script.go @@ -63,7 +63,7 @@ func resolvePreparerSetupScript(req *EnvPrepareRequest, workspacePath string) (s resolved := resolver.Resolve(script) if isScriptEffectivelyEmpty(resolved) { - prepareScriptLogger.Warn("setup script is comment-only after resolution, skipping", + prepareScriptLogger.Debug("setup script is comment-only after resolution, skipping", zap.String("task_id", req.TaskID), zap.String("executor_type", string(req.ExecutorType)), zap.Bool("use_worktree", req.UseWorktree), diff --git a/apps/backend/internal/agent/runtime/lifecycle/preparer_script_test.go b/apps/backend/internal/agent/runtime/lifecycle/preparer_script_test.go index 31b3a8f3c8..fb4004291d 100644 --- a/apps/backend/internal/agent/runtime/lifecycle/preparer_script_test.go +++ b/apps/backend/internal/agent/runtime/lifecycle/preparer_script_test.go @@ -1,13 +1,136 @@ package lifecycle import ( + "fmt" "strings" "testing" "github.com/kandev/kandev/internal/agent/executor" + commonlogger "github.com/kandev/kandev/internal/common/logger" "github.com/kandev/kandev/internal/task/models" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" ) +// @covers AC-PLATFORM-DIAGNOSTIC-LOGGING-001.12 +func TestResolvePreparerSetupScriptDiagnosticSeverity(t *testing.T) { + core, logs := observer.New(zapcore.DebugLevel) + log, err := commonlogger.NewFromZap(zap.New(core)) + if err != nil { + t.Fatalf("create observer logger: %v", err) + } + previousLogger := prepareScriptLogger + prepareScriptLogger = log + t.Cleanup(func() { prepareScriptLogger = previousLogger }) + + cases := []struct { + name string + request EnvPrepareRequest + wantExplicit bool + wantEmptyDiagnostic bool + secret string + }{ + { + name: "default comment-only script", + request: EnvPrepareRequest{ + TaskID: "task-default", + ExecutorType: executor.NameStandalone, + RepositoryPath: "/tmp/my-repo", + }, + wantEmptyDiagnostic: true, + }, + { + name: "explicit comment-only script", + request: EnvPrepareRequest{ + TaskID: "task-explicit", + ExecutorType: executor.NameStandalone, + RepositoryPath: "/tmp/my-repo", + SetupScript: "# secret-comment\n# another comment", + }, + wantExplicit: true, + wantEmptyDiagnostic: true, + secret: "secret-comment", + }, + { + name: "blank and shebang-only script", + request: EnvPrepareRequest{ + TaskID: "task-shebang", + ExecutorType: executor.NameStandalone, + RepositoryPath: "/tmp/my-repo", + SetupScript: "\n#!/bin/sh\n\n", + }, + wantExplicit: true, + wantEmptyDiagnostic: true, + }, + { + name: "executable script", + request: EnvPrepareRequest{ + TaskID: "task-command", + ExecutorType: executor.NameStandalone, + RepositoryPath: "/tmp/my-repo", + SetupScript: "echo setup-command", + }, + wantExplicit: true, + }, + } + + for _, tt := range cases { + t.Run(tt.name, func(t *testing.T) { + before := logs.Len() + got, err := resolvePreparerSetupScript(&tt.request, "/tmp/my-repo") + if err != nil { + t.Fatalf("resolvePreparerSetupScript() error = %v", err) + } + if tt.wantEmptyDiagnostic && got != "" { + t.Fatalf("resolved script = %q, want empty", got) + } + if !tt.wantEmptyDiagnostic && got == "" { + t.Fatal("resolved executable script is empty") + } + + entries := logs.All()[before:] + assertSetupScriptDiagnostic(t, entries, tt.request, tt.wantExplicit, tt.wantEmptyDiagnostic, tt.secret) + if !tt.wantEmptyDiagnostic && len(entries) != 0 { + t.Fatalf("executable script emitted omission diagnostics: %v", entries) + } + }) + } + + for _, entry := range logs.All() { + if entry.Level == zap.WarnLevel { + t.Fatalf("comment-only setup emitted warning: %#v", entry) + } + } +} + +func assertSetupScriptDiagnostic( + t *testing.T, entries []observer.LoggedEntry, req EnvPrepareRequest, wantExplicit, wantEmpty bool, secret string, +) { + t.Helper() + if !wantEmpty { + return + } + if len(entries) != 1 { + t.Fatalf("diagnostic entries = %d, want 1", len(entries)) + } + entry := entries[0] + if entry.Message != "setup script is comment-only after resolution, skipping" { + t.Fatalf("diagnostic message = %q", entry.Message) + } + if entry.Level != zap.DebugLevel { + t.Fatalf("diagnostic level = %s, want debug", entry.Level) + } + fields := entry.ContextMap() + if fields["task_id"] != req.TaskID || fields["executor_type"] != string(req.ExecutorType) || + fields["use_worktree"] != req.UseWorktree || fields["has_explicit_script"] != wantExplicit { + t.Fatalf("diagnostic fields = %v", fields) + } + if secret != "" && (strings.Contains(entry.Message, secret) || strings.Contains(fmt.Sprint(fields), secret)) { + t.Fatalf("diagnostic exposed script content: %#v", entry) + } +} + func TestResolvePreparerSetupScript_LocalFallbackCommentOnly(t *testing.T) { req := &EnvPrepareRequest{ ExecutorType: executor.NameStandalone, diff --git a/apps/backend/internal/gateway/websocket/task_notifications_test.go b/apps/backend/internal/gateway/websocket/task_notifications_test.go index fcbc430271..b7c417dfc9 100644 --- a/apps/backend/internal/gateway/websocket/task_notifications_test.go +++ b/apps/backend/internal/gateway/websocket/task_notifications_test.go @@ -226,7 +226,7 @@ func TestTaskEventBroadcaster_NoDuplicateSubscriptions(t *testing.T) { // // Update this number when adding or removing event subscriptions in // RegisterTaskNotifications — it is intentionally exact. - const wantSubscriptions = 76 + const wantSubscriptions = 77 if got := len(b.subscriptions); got != wantSubscriptions { t.Errorf("RegisterTaskNotifications created %d subscriptions, want %d — "+ "did an event get subscribed twice?", got, wantSubscriptions) diff --git a/apps/backend/internal/github/service_pr_discovery_health.go b/apps/backend/internal/github/service_pr_discovery_health.go index c0af325a2f..e9332ffa31 100644 --- a/apps/backend/internal/github/service_pr_discovery_health.go +++ b/apps/backend/internal/github/service_pr_discovery_health.go @@ -676,6 +676,13 @@ func classifyPRDiscoveryError(err error) PRDiscoveryHealthCategory { return PRDiscoveryHealthUnavailable } +// ClassifyPRDiscoveryError returns the bounded category used for PR discovery +// diagnostics. It deliberately exposes the category contract without exposing +// provider error text or payloads to callers. +func ClassifyPRDiscoveryError(err error) PRDiscoveryHealthCategory { + return classifyPRDiscoveryError(err) +} + func containsRateLimitMarker(value string) bool { lower := strings.ToLower(value) for _, marker := range []string{"rate limit", "too many requests", "429", "abuse detection", "secondary limit"} { diff --git a/apps/backend/internal/orchestrator/event_handlers_github.go b/apps/backend/internal/orchestrator/event_handlers_github.go index 3866f7b195..f226a596bc 100644 --- a/apps/backend/internal/orchestrator/event_handlers_github.go +++ b/apps/backend/internal/orchestrator/event_handlers_github.go @@ -781,6 +781,9 @@ func (s *Service) detectPushAndAssociatePRWithIdentity( if identity.owner == "" || identity.name == "" { return } + if prDiscoveryContextCanceled(ctx) { + return + } // Check if we already have a watch for this (session, repo, branch). // Multi-branch: keying by branch as well means a secondary branch's @@ -790,6 +793,9 @@ func (s *Service) detectPushAndAssociatePRWithIdentity( // If the watch has pr_number=0, it's still searching — do an immediate // search (faster than waiting for the 1-minute poller). existing, err := s.githubService.GetPRWatchBySessionRepoAndBranch(ctx, sessionID, identity.repositoryID, branch) + if prDiscoveryContextCanceled(ctx) { + return + } if err == nil && existing != nil { if existing.PRNumber > 0 { return // PR already found and being monitored @@ -798,45 +804,133 @@ func (s *Service) detectPushAndAssociatePRWithIdentity( return } - // Try to find a PR immediately, then retry after delays - delays := []time.Duration{0, 30 * time.Second, 60 * time.Second} - for _, delay := range delays { - if delay > 0 { - select { - case <-ctx.Done(): - return - case <-time.After(delay): - } - // Re-check if a watch was created in the meantime (e.g. by CreatePR callback) - if ex, err := s.githubService.GetPRWatchBySessionRepoAndBranch(ctx, sessionID, identity.repositoryID, branch); err == nil && ex != nil { - return - } - } - foundPR, findErr := s.githubService.FindPRByBranchForWorkspace( - ctx, workspaceID, identity.owner, identity.name, branch, - ) - if findErr != nil || foundPR == nil { - s.logger.Debug("no PR found for branch (will retry)", - zap.String("branch", branch), - zap.String("session_id", sessionID), - zap.String("repository_name", repositoryName), - zap.Duration("delay", delay)) - continue - } - s.logger.Info("PR found after push, associating with task", - zap.String("session_id", sessionID), - zap.String("task_id", taskID), - zap.String("repository_name", repositoryName), - zap.Int("pr_number", foundPR.Number), - zap.String("branch", branch)) - s.associatePRFromPushScoped(ctx, workspaceID, sessionID, taskID, identity.owner, identity.name, identity.repositoryID, branch, foundPR) + foundPR := s.discoverPRAfterPush(ctx, workspaceID, sessionID, taskID, identity, branch) + if foundPR == nil { return } - s.logger.Warn("exhausted all retries, no PR found after push", + s.logger.Info("PR found after push, associating with task", zap.String("session_id", sessionID), zap.String("task_id", taskID), zap.String("repository_name", repositoryName), + zap.Int("pr_number", foundPR.Number), zap.String("branch", branch)) + s.associatePRFromPushScoped(ctx, workspaceID, sessionID, taskID, identity.owner, identity.name, identity.repositoryID, branch, foundPR) +} + +func (s *Service) discoverPRAfterPush( + ctx context.Context, + workspaceID, sessionID, taskID string, + identity pushRepositoryIdentity, + branch string, +) *github.PR { + const prDiscoveryOutcomeFailed = "failed" + delays := []time.Duration{0, 30 * time.Second, 60 * time.Second} + attemptCount := 0 + errorCount := 0 + emptyCount := 0 + lastOutcome := "" + for attempt, delay := range delays { + if delay > 0 { + if !s.waitForPRDiscoveryRetry(ctx, delay) { + return nil + } + // Re-check if a watch was created in the meantime (e.g. by CreatePR callback). + if ex, err := s.githubService.GetPRWatchBySessionRepoAndBranch(ctx, sessionID, identity.repositoryID, branch); prDiscoveryContextCanceled(ctx) { + return nil + } else if err == nil && ex != nil { + return nil + } + } + if prDiscoveryContextCanceled(ctx) { + return nil + } + attemptCount++ + foundPR, findErr := s.githubService.FindPRByBranchForWorkspace( + ctx, workspaceID, identity.owner, identity.name, branch, + ) + if prDiscoveryContextCanceled(ctx) { + return nil + } + if findErr != nil { + errorCount++ + lastOutcome = prDiscoveryOutcomeFailed + s.logger.Warn("PR discovery lookup failed after push", + zap.String("operation", "post_push_branch_lookup"), + zap.String("workspace_id", workspaceID), + zap.String("session_id", sessionID), + zap.String("task_id", taskID), + zap.String("repository_id", identity.repositoryID), + zap.String("owner", identity.owner), + zap.String("repo", identity.name), + zap.String("branch", branch), + zap.String("category", string(github.ClassifyPRDiscoveryError(findErr))), + zap.Int("attempt", attempt+1)) + continue + } + if foundPR == nil { + emptyCount++ + lastOutcome = "empty" + s.logger.Debug("no PR found for branch (will retry)", + zap.String("operation", "post_push_branch_lookup"), + zap.String("workspace_id", workspaceID), + zap.String("session_id", sessionID), + zap.String("task_id", taskID), + zap.String("repository_id", identity.repositoryID), + zap.String("owner", identity.owner), + zap.String("repo", identity.name), + zap.String("branch", branch), + zap.Int("attempt", attempt+1), + zap.Duration("delay", delay)) + continue + } + return foundPR + } + s.logPRDiscoveryExhausted(workspaceID, sessionID, taskID, identity, branch, + attemptCount, errorCount, emptyCount, lastOutcome) + return nil +} + +func (s *Service) logPRDiscoveryExhausted( + workspaceID, sessionID, taskID string, + identity pushRepositoryIdentity, + branch string, + attemptCount, errorCount, emptyCount int, + lastOutcome string, +) { + s.logger.Debug("exhausted all retries, no PR found after push", + zap.String("operation", "post_push_branch_lookup"), + zap.String("workspace_id", workspaceID), + zap.String("session_id", sessionID), + zap.String("task_id", taskID), + zap.String("repository_id", identity.repositoryID), + zap.String("owner", identity.owner), + zap.String("repo", identity.name), + zap.String("branch", branch), + zap.Int("attempt_count", attemptCount), + zap.Int("error_count", errorCount), + zap.Int("empty_count", emptyCount), + zap.String("last_outcome", lastOutcome)) +} + +func (s *Service) waitForPRDiscoveryRetry(ctx context.Context, delay time.Duration) bool { + if s.prDiscoveryWait != nil { + return s.prDiscoveryWait(ctx, delay) + } + timer := time.NewTimer(delay) + defer timer.Stop() + select { + case <-ctx.Done(): + return false + case <-timer.C: + return true + } +} + +func prDiscoveryContextCanceled(ctx context.Context) bool { + // Provider clients can use their own timeout context and return a wrapped + // context error while the caller remains active. Only the caller context + // decides whether discovery should stop quietly. + return ctx.Err() != nil } // resolvePushRepo returns (owner, name, repository_id) for the per-repo push @@ -946,43 +1040,69 @@ func (s *Service) searchPRForExistingWatch( foundPR, findErr := s.githubService.FindPRByBranchForWorkspace( ctx, workspaceID, watch.Owner, watch.Repo, branch, ) - if findErr == nil && foundPR != nil { - if foundPR.RepoOwner != "" && foundPR.RepoName != "" && - (!strings.EqualFold(watch.Owner, foundPR.RepoOwner) || !strings.EqualFold(watch.Repo, foundPR.RepoName)) { - if err := s.githubService.UpdatePRWatchRepository(ctx, watch.ID, foundPR.RepoOwner, foundPR.RepoName); err != nil { - s.logger.Warn("failed to rebind PR watch repository", - zap.String("watch_id", watch.ID), - zap.String("owner", foundPR.RepoOwner), - zap.String("repo", foundPR.RepoName), - zap.Error(err)) - return - } - watch.Owner = foundPR.RepoOwner - watch.Repo = foundPR.RepoName - } - if err := s.githubService.UpdatePRWatchPRNumber(ctx, watch.ID, foundPR.Number); err != nil { - s.logger.Warn("failed to update PR watch number", - zap.String("watch_id", watch.ID), - zap.Int("pr_number", foundPR.Number), - zap.Error(err)) - } - // Use the watch's own repository_id so the association lands on the - // correct per-repo TaskPR row (matters once multi-repo watches exist; - // for legacy single-repo watches this is empty and matches the old - // "delete all" behavior). - if _, err := s.githubService.AssociatePRWithTaskForWorkspace( - ctx, workspaceID, taskID, watch.RepositoryID, foundPR, - ); err != nil { - s.logger.Error("failed to associate PR with task", - zap.String("task_id", taskID), - zap.Int("pr_number", foundPR.Number), - zap.Error(err)) - } - s.logger.Info("auto-detected PR from push (existing watch)", - zap.String("session_id", sessionID), - zap.Int("pr_number", foundPR.Number), - zap.String("branch", branch)) + if prDiscoveryContextCanceled(ctx) { + return } + if findErr != nil { + s.logger.Warn("PR discovery lookup failed for existing watch", + zap.String("operation", "existing_watch_branch_lookup"), + zap.String("workspace_id", workspaceID), + zap.String("session_id", sessionID), + zap.String("task_id", taskID), + zap.String("repository_id", watch.RepositoryID), + zap.String("owner", watch.Owner), + zap.String("repo", watch.Repo), + zap.String("branch", branch), + zap.String("category", string(github.ClassifyPRDiscoveryError(findErr)))) + return + } + if foundPR == nil { + s.logger.Debug("no PR found for existing watch", + zap.String("operation", "existing_watch_branch_lookup"), + zap.String("workspace_id", workspaceID), + zap.String("session_id", sessionID), + zap.String("task_id", taskID), + zap.String("repository_id", watch.RepositoryID), + zap.String("owner", watch.Owner), + zap.String("repo", watch.Repo), + zap.String("branch", branch)) + return + } + if foundPR.RepoOwner != "" && foundPR.RepoName != "" && + (!strings.EqualFold(watch.Owner, foundPR.RepoOwner) || !strings.EqualFold(watch.Repo, foundPR.RepoName)) { + if err := s.githubService.UpdatePRWatchRepository(ctx, watch.ID, foundPR.RepoOwner, foundPR.RepoName); err != nil { + s.logger.Warn("failed to rebind PR watch repository", + zap.String("watch_id", watch.ID), + zap.String("owner", foundPR.RepoOwner), + zap.String("repo", foundPR.RepoName), + zap.Error(err)) + return + } + watch.Owner = foundPR.RepoOwner + watch.Repo = foundPR.RepoName + } + if err := s.githubService.UpdatePRWatchPRNumber(ctx, watch.ID, foundPR.Number); err != nil { + s.logger.Warn("failed to update PR watch number", + zap.String("watch_id", watch.ID), + zap.Int("pr_number", foundPR.Number), + zap.Error(err)) + } + // Use the watch's own repository_id so the association lands on the + // correct per-repo TaskPR row (matters once multi-repo watches exist; + // for legacy single-repo watches this is empty and matches the old + // "delete all" behavior). + if _, err := s.githubService.AssociatePRWithTaskForWorkspace( + ctx, workspaceID, taskID, watch.RepositoryID, foundPR, + ); err != nil { + s.logger.Error("failed to associate PR with task", + zap.String("task_id", taskID), + zap.Int("pr_number", foundPR.Number), + zap.Error(err)) + } + s.logger.Info("auto-detected PR from push (existing watch)", + zap.String("session_id", sessionID), + zap.Int("pr_number", foundPR.Number), + zap.String("branch", branch)) } // resolveSessionRepo looks up the repository owner and name for a session. diff --git a/apps/backend/internal/orchestrator/event_handlers_github_push_diagnostics_test.go b/apps/backend/internal/orchestrator/event_handlers_github_push_diagnostics_test.go new file mode 100644 index 0000000000..fc2effdcc0 --- /dev/null +++ b/apps/backend/internal/orchestrator/event_handlers_github_push_diagnostics_test.go @@ -0,0 +1,382 @@ +package orchestrator + +import ( + "context" + "errors" + "fmt" + "strings" + "testing" + "time" + + commonlogger "github.com/kandev/kandev/internal/common/logger" + "github.com/kandev/kandev/internal/github" + "github.com/kandev/kandev/internal/task/models" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +type pushDiscoveryLookup struct { + pr *github.PR + err error +} + +type pushDiscoveryCall struct { + WorkspaceID string + Owner string + Repo string + Branch string +} + +type pushDiagnosticsGitHubService struct { + *mockGitHubService + lookups []pushDiscoveryLookup + calls []pushDiscoveryCall +} + +func (s *pushDiagnosticsGitHubService) FindPRByBranchForWorkspace( + _ context.Context, workspaceID, owner, repo, branch string, +) (*github.PR, error) { + s.calls = append(s.calls, pushDiscoveryCall{ + WorkspaceID: workspaceID, + Owner: owner, + Repo: repo, + Branch: branch, + }) + if len(s.lookups) == 0 { + return nil, nil + } + lookup := s.lookups[0] + s.lookups = s.lookups[1:] + return lookup.pr, lookup.err +} + +func newPushDiagnosticsService( + t *testing.T, repositoryID, repositoryName, owner, repoName string, watch *github.PRWatch, +) (*Service, *pushDiagnosticsGitHubService, *observer.ObservedLogs) { + t.Helper() + ctx := context.Background() + repository := setupTestRepo(t) + seedSession(t, repository, "t1", "s1", "step1") + now := time.Now().UTC() + if err := repository.CreateRepository(ctx, &models.Repository{ + ID: repositoryID, + WorkspaceID: "ws1", + Name: repositoryName, + SourceType: "provider", + Provider: "github", + ProviderOwner: owner, + ProviderName: repoName, + CreatedAt: now, + UpdatedAt: now, + }); err != nil { + t.Fatalf("create repository: %v", err) + } + if err := repository.CreateTaskRepository(ctx, &models.TaskRepository{ + ID: "task-repository-1", + TaskID: "t1", + RepositoryID: repositoryID, + Position: 0, + CreatedAt: now, + UpdatedAt: now, + }); err != nil { + t.Fatalf("create task repository: %v", err) + } + session, err := repository.GetTaskSession(ctx, "s1") + if err != nil { + t.Fatalf("get session: %v", err) + } + session.RepositoryID = repositoryID + if err := repository.UpdateTaskSession(ctx, session); err != nil { + t.Fatalf("update session: %v", err) + } + + log, logs := newPushDiagnosticsLogger(t) + svc := createTestService(repository, newMockStepGetter(), newMockTaskRepo()) + svc.logger = log + gh := &pushDiagnosticsGitHubService{ + mockGitHubService: &mockGitHubService{prWatch: watch}, + } + svc.SetGitHubService(gh) + return svc, gh, logs +} + +func newPushDiagnosticsLogger(t *testing.T) (*commonlogger.Logger, *observer.ObservedLogs) { + t.Helper() + core, logs := observer.New(zapcore.DebugLevel) + log, err := commonlogger.NewFromZap(zap.New(core)) + if err != nil { + t.Fatalf("create observer logger: %v", err) + } + return log, logs +} + +func installPushDiagnosticsWait(svc *Service, waits *[]time.Duration) { + svc.prDiscoveryWait = func(ctx context.Context, delay time.Duration) bool { + *waits = append(*waits, delay) + select { + case <-ctx.Done(): + return false + default: + return true + } + } +} + +func assertPushDiagnosticLogsContainNoRawError(t *testing.T, logs *observer.ObservedLogs, raw string) { + t.Helper() + for _, entry := range logs.All() { + if strings.Contains(entry.Message, raw) || strings.Contains(fmt.Sprint(entry.ContextMap()), raw) { + t.Fatalf("log exposed raw provider error %q: %#v", raw, entry) + } + } +} + +func TestPushDiscoveryDiagnostics(t *testing.T) { + providerErr := errors.New("GET https://token:push-secret@example.invalid/repos/myorg/myrepo: 503 service unavailable") + providerDeadlineErr := fmt.Errorf("provider request: %w", context.DeadlineExceeded) + foundPR := &github.PR{ + Number: 17, + RepoOwner: "myorg", + RepoName: "myrepo", + HeadBranch: "feature-branch", + } + + tests := []struct { + name string + lookups []pushDiscoveryLookup + wantCalls int + wantWaits []time.Duration + wantWarns int + wantSummary bool + wantLastState string + wantAssoc int + }{ + { + name: "all empty", + lookups: []pushDiscoveryLookup{{}, {}, {}}, + wantCalls: 3, + wantWaits: []time.Duration{30 * time.Second, 60 * time.Second}, + wantSummary: true, + wantLastState: "empty", + }, + { + name: "all errors", + lookups: []pushDiscoveryLookup{{err: providerErr}, {err: providerErr}, {err: providerErr}}, + wantCalls: 3, + wantWaits: []time.Duration{30 * time.Second, 60 * time.Second}, + wantWarns: 3, + wantSummary: true, + wantLastState: "failed", + }, + { + name: "wrapped provider deadline remains retryable", + lookups: []pushDiscoveryLookup{{err: providerDeadlineErr}, {err: providerDeadlineErr}, {err: providerDeadlineErr}}, + wantCalls: 3, + wantWaits: []time.Duration{30 * time.Second, 60 * time.Second}, + wantWarns: 3, + wantSummary: true, + wantLastState: "failed", + }, + { + name: "error then empty", + lookups: []pushDiscoveryLookup{{err: providerErr}, {}, {}}, + wantCalls: 3, + wantWaits: []time.Duration{30 * time.Second, 60 * time.Second}, + wantWarns: 1, + wantSummary: true, + wantLastState: "empty", + }, + { + name: "empty then error", + lookups: []pushDiscoveryLookup{{}, {err: providerErr}, {}}, + wantCalls: 3, + wantWaits: []time.Duration{30 * time.Second, 60 * time.Second}, + wantWarns: 1, + wantSummary: true, + wantLastState: "empty", + }, + { + name: "error then found", + lookups: []pushDiscoveryLookup{{err: providerErr}, {pr: foundPR}}, + wantCalls: 2, + wantWaits: []time.Duration{30 * time.Second}, + wantWarns: 1, + wantAssoc: 1, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + svc, gh, logs := newPushDiagnosticsService(t, "repo1", "myrepo", "myorg", "myrepo", nil) + gh.lookups = append([]pushDiscoveryLookup(nil), tt.lookups...) + var waits []time.Duration + installPushDiagnosticsWait(svc, &waits) + + svc.detectPushAndAssociatePR(context.Background(), "s1", "t1", "", "feature-branch") + + if len(gh.calls) != tt.wantCalls { + t.Fatalf("lookup calls = %d, want %d", len(gh.calls), tt.wantCalls) + } + if len(waits) != len(tt.wantWaits) { + t.Fatalf("waits = %v, want %v", waits, tt.wantWaits) + } + for i := range waits { + if waits[i] != tt.wantWaits[i] { + t.Fatalf("waits = %v, want %v", waits, tt.wantWaits) + } + } + if gh.associateCalls != tt.wantAssoc { + t.Fatalf("association calls = %d, want %d", gh.associateCalls, tt.wantAssoc) + } + failed := logs.FilterMessage("PR discovery lookup failed after push").All() + if len(failed) != tt.wantWarns { + t.Fatalf("failed lookup warnings = %d, want %d; logs = %v", len(failed), tt.wantWarns, logs.All()) + } + for _, entry := range failed { + fields := entry.ContextMap() + if fields["workspace_id"] != "ws1" || fields["task_id"] != "t1" || + fields["repository_id"] != "repo1" || fields["owner"] != "myorg" || + fields["repo"] != "myrepo" || fields["branch"] != "feature-branch" || + fields["category"] != string(github.PRDiscoveryHealthUnavailable) { + t.Fatalf("failed lookup fields = %v", fields) + } + } + summary := logs.FilterMessage("exhausted all retries, no PR found after push").All() + if len(summary) != boolToInt(tt.wantSummary) { + t.Fatalf("retry summaries = %d, want %d; logs = %v", len(summary), boolToInt(tt.wantSummary), logs.All()) + } + if tt.wantSummary { + if summary[0].Level != zap.DebugLevel { + t.Fatalf("retry summary level = %s, want debug", summary[0].Level) + } + fields := summary[0].ContextMap() + if fields["attempt_count"] != int64(3) || fields["error_count"] != int64(countLookupErrors(tt.lookups)) || + fields["empty_count"] != int64(3-countLookupErrors(tt.lookups)) || fields["last_outcome"] != tt.wantLastState { + t.Fatalf("retry summary fields = %v", fields) + } + } + assertPushDiagnosticLogsContainNoRawError(t, logs, "push-secret") + }) + } + + t.Run("cancellation before lookup", func(t *testing.T) { + svc, gh, logs := newPushDiagnosticsService(t, "repo1", "myrepo", "myorg", "myrepo", nil) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + svc.detectPushAndAssociatePR(ctx, "s1", "t1", "", "feature-branch") + if len(gh.calls) != 0 { + t.Fatalf("lookup calls = %d, want 0", len(gh.calls)) + } + if logs.FilterMessage("PR discovery lookup failed after push").Len() != 0 || + logs.FilterMessage("exhausted all retries, no PR found after push").Len() != 0 { + t.Fatalf("cancellation emitted failure logs: %v", logs.All()) + } + }) + + t.Run("cancellation during delay", func(t *testing.T) { + svc, gh, logs := newPushDiagnosticsService(t, "repo1", "myrepo", "myorg", "myrepo", nil) + gh.lookups = []pushDiscoveryLookup{{err: providerErr}} + ctx, cancel := context.WithCancel(context.Background()) + var waits []time.Duration + svc.prDiscoveryWait = func(_ context.Context, delay time.Duration) bool { + waits = append(waits, delay) + cancel() + return false + } + svc.detectPushAndAssociatePR(ctx, "s1", "t1", "", "feature-branch") + if len(gh.calls) != 1 || len(waits) != 1 || waits[0] != 30*time.Second { + t.Fatalf("calls/waits = %d/%v, want 1/[30s]", len(gh.calls), waits) + } + if logs.FilterMessage("exhausted all retries, no PR found after push").Len() != 0 { + t.Fatalf("cancellation emitted exhaustion warning: %v", logs.All()) + } + assertPushDiagnosticLogsContainNoRawError(t, logs, "push-secret") + }) +} + +func TestExistingWatchDiscoveryDiagnostics(t *testing.T) { + providerErr := errors.New("GET https://token:watch-secret@example.invalid/repos/acme/secondary: 503 service unavailable") + providerDeadlineErr := fmt.Errorf("provider request: %w", context.DeadlineExceeded) + foundPR := &github.PR{ + Number: 23, + RepoOwner: "acme", + RepoName: "secondary", + HeadBranch: "feature-branch", + } + + tests := []struct { + name string + lookup pushDiscoveryLookup + wantWarn bool + wantAssoc int + }{ + {name: "provider error", lookup: pushDiscoveryLookup{err: providerErr}, wantWarn: true}, + {name: "wrapped provider deadline", lookup: pushDiscoveryLookup{err: providerDeadlineErr}, wantWarn: true}, + {name: "empty result", lookup: pushDiscoveryLookup{}, wantAssoc: 0}, + {name: "found result", lookup: pushDiscoveryLookup{pr: foundPR}, wantAssoc: 1}, + {name: "provider cancellation", lookup: pushDiscoveryLookup{err: context.Canceled}, wantWarn: true, wantAssoc: 0}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + watch := &github.PRWatch{ + ID: "watch-secondary", + SessionID: "s1", + TaskID: "t1", + RepositoryID: "repo-secondary", + Owner: "acme", + Repo: "secondary", + PRNumber: 0, + Branch: "feature-branch", + } + svc, gh, logs := newPushDiagnosticsService(t, "repo-secondary", "secondary", "acme", "secondary", watch) + gh.lookups = []pushDiscoveryLookup{tt.lookup} + + svc.detectPushAndAssociatePR(context.Background(), "s1", "t1", "", "feature-branch") + + if len(gh.calls) != 1 || gh.calls[0].WorkspaceID != "ws1" || gh.calls[0].Owner != "acme" || + gh.calls[0].Repo != "secondary" || gh.calls[0].Branch != "feature-branch" { + t.Fatalf("lookup identity = %#v, want ws1/acme/secondary/feature-branch", gh.calls) + } + if gh.associateCalls != tt.wantAssoc { + t.Fatalf("association calls = %d, want %d", gh.associateCalls, tt.wantAssoc) + } + failed := logs.FilterMessage("PR discovery lookup failed for existing watch").All() + if len(failed) != boolToInt(tt.wantWarn) { + t.Fatalf("existing-watch failure warnings = %d, want %d; logs = %v", len(failed), boolToInt(tt.wantWarn), logs.All()) + } + if tt.wantWarn { + fields := failed[0].ContextMap() + if fields["workspace_id"] != "ws1" || fields["task_id"] != "t1" || + fields["repository_id"] != "repo-secondary" || fields["owner"] != "acme" || + fields["repo"] != "secondary" || fields["category"] != string(github.PRDiscoveryHealthUnavailable) { + t.Fatalf("existing-watch failure fields = %v", fields) + } + } + if logs.FilterMessage("no PR found for existing watch").Len() > 0 && tt.lookup.err != nil { + t.Fatalf("failed existing-watch lookup was logged as empty: %v", logs.All()) + } + if tt.lookup.err == nil && tt.lookup.pr == nil && logs.FilterMessage("no PR found for existing watch").Len() != 1 { + t.Fatalf("empty existing-watch result did not emit debug log: %v", logs.All()) + } + assertPushDiagnosticLogsContainNoRawError(t, logs, "watch-secret") + }) + } +} + +func countLookupErrors(lookups []pushDiscoveryLookup) int { + count := 0 + for _, lookup := range lookups { + if lookup.err != nil { + count++ + } + } + return count +} + +func boolToInt(value bool) int { + if value { + return 1 + } + return 0 +} diff --git a/apps/backend/internal/orchestrator/service.go b/apps/backend/internal/orchestrator/service.go index 0d99e2a826..87e05fdf8d 100644 --- a/apps/backend/internal/orchestrator/service.go +++ b/apps/backend/internal/orchestrator/service.go @@ -1018,6 +1018,9 @@ type Service struct { // GitHub service for PR auto-detection on push githubService GitHubService + // prDiscoveryWait is nil in production and overridable by package tests so + // retry diagnostics can be exercised without real-time delays. + prDiscoveryWait func(context.Context, time.Duration) bool // ciAutomationInFlight serializes each PR's evaluation and coalesces one // follow-up request instead of dropping an event that arrives mid-run. ciAutomationInFlight ciAutomationCoordinator diff --git a/apps/backend/internal/worktree/manager_git.go b/apps/backend/internal/worktree/manager_git.go index ae323701c1..945c87c540 100644 --- a/apps/backend/internal/worktree/manager_git.go +++ b/apps/backend/internal/worktree/manager_git.go @@ -531,6 +531,7 @@ func (m *Manager) handleBaseFetchFailure( onProgress SyncProgressCallback, ) (string, string, error) { reason := classifyGitFallbackReason(err, string(output), execCtxErr) + m.logRefreshDiagnostic("fetch", repoPath, baseBranch, reason, output, err, execCtxErr) if required { fallback := strings.TrimSpace(fallbackBaseBranch) if reason == gitFallbackReasonMissingRemoteRef && fallback != "" && fallback != baseBranch { @@ -701,6 +702,7 @@ func (m *Manager) pullCurrentBranchOrFallback( output, err, execCtxErr := m.runGitCombinedAfterAcquire(ctx, m.pullTimeout, repoPath, "pull", "--ff-only", "origin", baseBranch) if err != nil { reason := classifyGitFallbackReason(err, string(output), execCtxErr) + m.logRefreshDiagnostic("pull", repoPath, baseBranch, reason, output, err, execCtxErr) resolved, selectErr := m.selectContainingRef(ctx, repoPath, baseBranch, remoteRef) if selectErr != nil { if !localBaseExists { @@ -770,9 +772,8 @@ func (m *Manager) selectContainingRef( } // syncFailureCause intentionally suppresses cmdErr because Git output can -// contain credentials. Callers expose only a bounded failure class and keep -// raw command output in internal logs where the existing redaction policy -// applies. +// contain credentials. Callers expose only a bounded failure class and never +// include the command output in errors or progress. func syncFailureCause(reason string, _ error, contextErr error) error { if contextErr != nil { return contextErr diff --git a/apps/backend/internal/worktree/refresh_diagnostics.go b/apps/backend/internal/worktree/refresh_diagnostics.go new file mode 100644 index 0000000000..a60827d04f --- /dev/null +++ b/apps/backend/internal/worktree/refresh_diagnostics.go @@ -0,0 +1,127 @@ +package worktree + +import ( + "context" + "errors" + "os/exec" + "strings" + + "go.uber.org/zap" +) + +const ( + refreshDiagnosticAuthentication = "authentication_failed" + refreshDiagnosticSSHKey = "ssh_public_key_rejected" + refreshDiagnosticSSHHost = "ssh_host_verification_failed" + refreshDiagnosticDNS = "dns_resolution_failed" + refreshDiagnosticConnection = "connection_failed" + refreshDiagnosticTLS = "tls_verification_failed" + refreshDiagnosticMissingRef = "missing_remote_ref" + refreshDiagnosticNonFastForward = "non_fast_forward" + refreshDiagnosticRepository = "repository_access_failed" + refreshDiagnosticLock = "lock_contention" + refreshDiagnosticTimeout = "timeout" + refreshDiagnosticCanceled = "canceled" + refreshDiagnosticUnknown = "unknown" +) + +type refreshDiagnostic struct { + code string + detail string + exitCode int + hasExitCode bool +} + +func classifyRefreshDiagnostic(output string, runErr, contextErr error) refreshDiagnostic { + if errors.Is(contextErr, context.Canceled) || errors.Is(runErr, context.Canceled) { + return newRefreshDiagnostic(refreshDiagnosticCanceled, "The Git refresh was canceled.", runErr) + } + if errors.Is(contextErr, context.DeadlineExceeded) || errors.Is(runErr, context.DeadlineExceeded) { + return newRefreshDiagnostic(refreshDiagnosticTimeout, "The Git refresh timed out.", runErr) + } + + code, detail := classifyRefreshDiagnosticOutput(output) + return newRefreshDiagnostic(code, detail, runErr) +} + +func classifyRefreshDiagnosticOutput(output string) (string, string) { + lower := strings.ToLower(output) + switch { + case strings.Contains(lower, "permission denied (publickey)"), + strings.Contains(lower, "no supported authentication methods available"): + return refreshDiagnosticSSHKey, "The SSH server rejected the configured public key." + case strings.Contains(lower, "host key verification failed"), + strings.Contains(lower, "remote host identification has changed"): + return refreshDiagnosticSSHHost, "The SSH host could not be verified." + case strings.Contains(lower, "could not resolve host"), + strings.Contains(lower, "could not resolve hostname"), + strings.Contains(lower, "name or service not known"), + strings.Contains(lower, "temporary failure in name resolution"): + return refreshDiagnosticDNS, "The remote host name could not be resolved." + case strings.Contains(lower, "ssl certificate problem"), + strings.Contains(lower, "certificate verify failed"), + strings.Contains(lower, "server certificate verification failed"): + return refreshDiagnosticTLS, "The remote TLS certificate could not be verified." + case strings.Contains(lower, "connection refused"), + strings.Contains(lower, "connection reset"), + strings.Contains(lower, "network is unreachable"), + strings.Contains(lower, "no route to host"), + strings.Contains(lower, "failed to connect"), + strings.Contains(lower, "couldn't connect"): + return refreshDiagnosticConnection, "The connection to the Git remote failed." + case strings.Contains(lower, "couldn't find remote ref"), + strings.Contains(lower, "could not find remote ref"), + strings.Contains(lower, "remote ref does not exist"), + strings.Contains(lower, "no such ref"): + return refreshDiagnosticMissingRef, "The requested remote branch was not found." + case strings.Contains(lower, "not possible to fast-forward"): + return refreshDiagnosticNonFastForward, "The local branch could not be fast-forwarded." + case strings.Contains(lower, "non-fast-forward"): + return refreshDiagnosticNonFastForward, "The Git refresh encountered a non-fast-forward update." + case strings.Contains(lower, "index.lock"), + strings.Contains(lower, "cannot lock ref"), + strings.Contains(lower, "another git process seems to be running"), + // Require both fragments so a generic "unable to create" error stays unknown. + strings.Contains(lower, "unable to create") && strings.Contains(lower, "lock"): + return refreshDiagnosticLock, "Git could not acquire the repository lock." + case strings.Contains(lower, "repository not found"), + strings.Contains(lower, "does not appear to be a git repository"), + strings.Contains(lower, "could not read from remote repository"): + return refreshDiagnosticRepository, "The Git repository could not be accessed." + case strings.Contains(lower, "could not read username"), + strings.Contains(lower, "authentication failed"), + strings.Contains(lower, "terminal prompts disabled"), + strings.Contains(lower, "authentication required"): + return refreshDiagnosticAuthentication, "Git could not authenticate to the remote." + default: + return refreshDiagnosticUnknown, "The Git refresh failed for an unknown reason." + } +} + +func newRefreshDiagnostic(code, detail string, runErr error) refreshDiagnostic { + diagnostic := refreshDiagnostic{code: code, detail: detail} + var exitErr *exec.ExitError + if errors.As(runErr, &exitErr) && exitErr.ExitCode() >= 0 { + diagnostic.exitCode = exitErr.ExitCode() + diagnostic.hasExitCode = true + } + return diagnostic +} + +func (m *Manager) logRefreshDiagnostic( + operation, repoPath, branch, reason string, output []byte, runErr, contextErr error, +) { + diagnostic := classifyRefreshDiagnostic(string(output), runErr, contextErr) + fields := []zap.Field{ + zap.String("operation", operation), + zap.String("repository_path", repoPath), + zap.String("branch", branch), + zap.String("reason", reason), + zap.String("diagnostic_code", diagnostic.code), + zap.String("detail", diagnostic.detail), + } + if diagnostic.hasExitCode { + fields = append(fields, zap.Int("exit_code", diagnostic.exitCode)) + } + m.logger.Warn("git refresh failed", fields...) +} diff --git a/apps/backend/internal/worktree/refresh_diagnostics_test.go b/apps/backend/internal/worktree/refresh_diagnostics_test.go new file mode 100644 index 0000000000..fa3512351a --- /dev/null +++ b/apps/backend/internal/worktree/refresh_diagnostics_test.go @@ -0,0 +1,338 @@ +package worktree + +import ( + "context" + "errors" + "fmt" + "os" + "strings" + "testing" +) + +// @covers AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.14 +func TestRefreshDiagnosticClassification(t *testing.T) { + tests := []struct { + name string + output string + runErr error + contextErr error + wantCode string + wantDetail string + wantNoText string + }{ + {name: "SSH public key", output: "Permission denied (publickey).", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticSSHKey, wantDetail: "public key"}, + {name: "SSH host key", output: "Host key verification failed.", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticSSHHost, wantDetail: "host"}, + {name: "DNS", output: "Could not resolve host: example.invalid", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticDNS, wantDetail: "host name"}, + {name: "connection", output: "Connection refused", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticConnection, wantDetail: "connection"}, + {name: "TLS", output: "SSL certificate problem: unable to get local issuer certificate", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticTLS, wantDetail: "TLS"}, + {name: "missing ref", output: "couldn't find remote ref feature/missing", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticMissingRef, wantDetail: "remote branch"}, + {name: "non-fast-forward", output: "rejected: non-fast-forward", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticNonFastForward, wantDetail: "non-fast-forward"}, + {name: "pull fast-forward refusal", output: "fatal: Not possible to fast-forward, aborting.", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticNonFastForward, wantDetail: "local branch", wantNoText: "remote"}, + {name: "tag clobber is not branch refusal", output: "! [rejected] v1 -> v1 (would clobber existing tag)", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticUnknown, wantDetail: "unknown reason"}, + {name: "repository access", output: "Repository not found.", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticRepository, wantDetail: "accessed"}, + {name: "lock", output: "fatal: Unable to create '.git/index.lock': File exists.", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticLock, wantDetail: "repository lock"}, + {name: "generic lock", output: "fatal: unable to create '.git/refs/heads/main.lock': File exists.", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticLock, wantDetail: "repository lock"}, + {name: "authentication", output: "terminal prompts disabled", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticAuthentication, wantDetail: "authenticate"}, + {name: "unknown", output: "unexpected backend detail: token-secret", runErr: errors.New("exit status 128"), wantCode: refreshDiagnosticUnknown, wantDetail: "unknown reason", wantNoText: "token-secret"}, + {name: "timeout wins", output: "Permission denied (publickey)", runErr: context.DeadlineExceeded, contextErr: context.DeadlineExceeded, wantCode: refreshDiagnosticTimeout, wantDetail: "timed out"}, + {name: "cancellation wins", output: "Permission denied (publickey)", runErr: context.Canceled, contextErr: context.Canceled, wantCode: refreshDiagnosticCanceled, wantDetail: "canceled"}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := classifyRefreshDiagnostic(tt.output, tt.runErr, tt.contextErr) + if got.code != tt.wantCode { + t.Fatalf("diagnostic code = %q, want %q", got.code, tt.wantCode) + } + if !strings.Contains(strings.ToLower(got.detail), strings.ToLower(tt.wantDetail)) { + t.Fatalf("diagnostic detail = %q, want it to contain %q", got.detail, tt.wantDetail) + } + if tt.wantNoText != "" && strings.Contains(got.detail, tt.wantNoText) { + t.Fatalf("diagnostic detail contains raw output %q: %q", tt.wantNoText, got.detail) + } + }) + } +} + +// @covers AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.14 +func TestBaseRefreshDiagnosticEmission(t *testing.T) { + tests := []struct { + name string + gitScript string + wantRef string + wantCode string + wantOperation string + secret string + }{ + { + name: "fetch authentication failure", + gitScript: ` +case "${1:-}" in + fetch) + echo "fatal: could not read Username for 'https://token:fetch-secret@example.invalid/repo.git': terminal prompts disabled" >&2 + exit 128 + ;; + rev-parse) + exit 0 + ;; + *) + exit 0 + ;; +esac +`, + wantRef: "main", + wantCode: "authentication_failed", + wantOperation: "fetch", + secret: "fetch-secret", + }, + { + name: "fetch non-fast-forward update", + gitScript: ` +case "${1:-}" in + rev-parse) + exit 0 + ;; + fetch) + echo "From https://example.invalid/repo.git" >&2 + echo " ! [rejected] main -> main (non-fast-forward)" >&2 + echo "error: some local refs could not be updated" >&2 + exit 128 + ;; + *) + exit 0 + ;; +esac +`, + wantRef: "main", + wantCode: "non_fast_forward", + wantOperation: "fetch", + }, + { + name: "pull TLS failure", + gitScript: ` +case "${1:-}" in + fetch) + exit 0 + ;; + pull) + echo "fatal: unable to access 'https://token:pull-secret@example.invalid/repo.git': SSL certificate problem" >&2 + exit 128 + ;; + rev-parse) + if [ "${2:-}" = "--abbrev-ref" ]; then + echo "main" + fi + exit 0 + ;; + merge-base) + exit 0 + ;; + *) + exit 0 + ;; +esac +`, + wantRef: "origin/main", + wantCode: "tls_verification_failed", + wantOperation: "pull", + secret: "pull-secret", + }, + { + name: "pull fast-forward refusal", + gitScript: ` +case "${1:-}" in + fetch) + exit 0 + ;; + pull) + echo "fatal: Not possible to fast-forward, aborting." >&2 + exit 128 + ;; + rev-parse) + if [ "${2:-}" = "--abbrev-ref" ]; then + echo "main" + fi + exit 0 + ;; + merge-base) + exit 0 + ;; + *) + exit 0 + ;; +esac +`, + wantRef: "origin/main", + wantCode: "non_fast_forward", + wantOperation: "pull", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + scriptDir := writeFakeGitScript(t, tt.gitScript) + t.Setenv("PATH", scriptDir+string(os.PathListSeparator)+os.Getenv("PATH")) + + log, logs := newObservedWorktreeLogger(t) + mgr, err := NewManager(newTestConfig(t), newMockStore(), log) + if err != nil { + t.Fatalf("NewManager() error = %v", err) + } + + ref, err := mgr.pullBaseBranch(context.Background(), t.TempDir(), "main", nil) + if err != nil { + t.Fatalf("pullBaseBranch() error = %v", err) + } + if ref != tt.wantRef { + t.Fatalf("pullBaseBranch() ref = %q, want %q", ref, tt.wantRef) + } + + entries := logs.FilterMessage("git refresh failed").All() + if len(entries) != 1 { + t.Fatalf("observed %d refresh diagnostics, want 1; logs = %v", len(entries), logs.All()) + } + fields := entries[0].ContextMap() + if fields["operation"] != tt.wantOperation { + t.Fatalf("operation = %v, want %q", fields["operation"], tt.wantOperation) + } + if fields["branch"] != "main" { + t.Fatalf("branch = %v, want main", fields["branch"]) + } + if fields["diagnostic_code"] != tt.wantCode { + t.Fatalf("diagnostic_code = %v, want %q", fields["diagnostic_code"], tt.wantCode) + } + if fields["detail"] == "" { + t.Fatal("diagnostic detail is empty") + } + for _, entry := range logs.All() { + if strings.Contains(entry.Message, "https://token:") || + (tt.secret != "" && strings.Contains(entry.Message, tt.secret)) { + t.Fatalf("log message contains secret material: %q", entry.Message) + } + for key, value := range entry.ContextMap() { + rendered := fmt.Sprint(value) + if strings.Contains(key, "https://token:") || + strings.Contains(rendered, "https://token:") || + (tt.secret != "" && + (strings.Contains(key, tt.secret) || strings.Contains(rendered, tt.secret))) { + t.Fatalf("log field %q contains secret material: %v", key, value) + } + } + } + }) + } +} + +// @covers AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.14 +func TestRefreshDiagnosticsPreservePolicy(t *testing.T) { + scriptDir := writeFakeGitScript(t, ` +case "${1:-}" in + rev-parse) + exit 1 + ;; + fetch) + echo "fatal: unexpected backend detail token-secret" >&2 + exit 128 + ;; + *) + exit 0 + ;; +esac +`) + t.Setenv("PATH", scriptDir+string(os.PathListSeparator)+os.Getenv("PATH")) + + log, logs := newObservedWorktreeLogger(t) + mgr, err := NewManager(newTestConfig(t), newMockStore(), log) + if err != nil { + t.Fatalf("NewManager() error = %v", err) + } + + var events []SyncProgressEvent + _, _, err = mgr.pullBaseBranchWithPolicy( + context.Background(), t.TempDir(), "main", "", true, captureSyncProgress(&events), + ) + if !errors.Is(err, ErrGitCommandFailed) { + t.Fatalf("pullBaseBranchWithPolicy() error = %v, want ErrGitCommandFailed", err) + } + if strings.Contains(err.Error(), "token-secret") { + t.Fatalf("returned error exposed raw Git output: %v", err) + } + if len(events) != 2 || events[1].Status != SyncProgressFailed { + t.Fatalf("sync progress = %#v, want running then failed", events) + } + if events[1].Error != "git_command_failed" || strings.Contains(events[1].Output, "token-secret") { + t.Fatalf("sync progress exposed raw failure details: %#v", events[1]) + } + + entries := logs.FilterMessage("git refresh failed").All() + if len(entries) != 1 { + t.Fatalf("observed %d refresh diagnostics, want 1; logs = %v", len(entries), logs.All()) + } + fields := entries[0].ContextMap() + if fields["operation"] != "fetch" || fields["branch"] != "main" || fields["reason"] != "git_command_failed" { + t.Fatalf("diagnostic fields = %v, want fetch/main/git_command_failed", fields) + } + if fields["diagnostic_code"] != refreshDiagnosticUnknown { + t.Fatalf("diagnostic_code = %v, want %q", fields["diagnostic_code"], refreshDiagnosticUnknown) + } + for _, entry := range logs.All() { + if strings.Contains(entry.Message, "token-secret") || strings.Contains(fmt.Sprint(entry.ContextMap()), "token-secret") { + t.Fatalf("log exposed raw Git output: %#v", entry) + } + } + + t.Run("configured fallback failure", func(t *testing.T) { + scriptDir := writeFakeGitScript(t, ` +case "${1:-}" in + rev-parse) + exit 1 + ;; + fetch) + case "${4:-}" in + feature/missing) + echo "fatal: couldn't find remote ref feature/missing" >&2 + ;; + main) + echo "fatal: could not read Username for 'https://token:fallback-secret@example.invalid/repo.git': terminal prompts disabled" >&2 + ;; + esac + exit 128 + ;; + *) + exit 0 + ;; +esac +`) + t.Setenv("PATH", scriptDir+string(os.PathListSeparator)+os.Getenv("PATH")) + log, logs := newObservedWorktreeLogger(t) + mgr, err := NewManager(newTestConfig(t), newMockStore(), log) + if err != nil { + t.Fatalf("NewManager() error = %v", err) + } + var events []SyncProgressEvent + _, _, err = mgr.pullBaseBranchWithFallback( + context.Background(), t.TempDir(), "feature/missing", "main", captureSyncProgress(&events), + ) + if !errors.Is(err, ErrAuthFailed) { + t.Fatalf("pullBaseBranchWithFallback() error = %v, want ErrAuthFailed", err) + } + if strings.Contains(err.Error(), "fallback-secret") || strings.Contains(fmt.Sprint(events), "fallback-secret") { + t.Fatalf("fallback failure exposed raw Git output: error=%v events=%#v", err, events) + } + entries := logs.FilterMessage("git refresh failed").All() + if len(entries) != 2 { + t.Fatalf("observed %d refresh diagnostics, want primary and fallback failures", len(entries)) + } + if entries[0].ContextMap()["branch"] != "feature/missing" || entries[0].ContextMap()["diagnostic_code"] != refreshDiagnosticMissingRef { + t.Fatalf("primary diagnostic fields = %v", entries[0].ContextMap()) + } + if entries[1].ContextMap()["branch"] != "main" || entries[1].ContextMap()["diagnostic_code"] != refreshDiagnosticAuthentication { + t.Fatalf("fallback diagnostic fields = %v", entries[1].ContextMap()) + } + for _, entry := range logs.All() { + if strings.Contains(fmt.Sprint(entry.ContextMap()), "fallback-secret") { + t.Fatalf("fallback diagnostic exposed raw Git output: %#v", entry) + } + } + }) +} diff --git a/docs/plans/recovery-diagnostics/plan.md b/docs/plans/recovery-diagnostics/plan.md new file mode 100644 index 0000000000..9529632e07 --- /dev/null +++ b/docs/plans/recovery-diagnostics/plan.md @@ -0,0 +1,170 @@ +--- +created: 2026-09-22 +status: complete +requirements: + - REQ-WORKSPACES-WORKTREE-BASE-REFRESH-001 + - REQ-INTEGRATIONS-GITHUB-PR-DISCOVERY-001 + - REQ-PLATFORM-DIAGNOSTIC-LOGGING-001 +system_design: + - ../../specs/workspaces/system-design/worktree-base-refresh.md + - ../../specs/integrations/system-design/github-pr-discovery-health.md + - ../../specs/platform/system-design/diagnostic-logging-01.md +legacy_specs: [] +--- + +# Implementation plan: Recovery diagnostic fixes + +## Overview + +Improve evidence for failed Git refresh and PR discovery. Remove warnings for +intentional setup-script omissions. Execute three work orders sequentially. +Each work order has an independent result. The order prioritizes lost failure +evidence before warning cleanup. + +## Evidence and requirement conformance + +The supplied September 22 logs show two failed recovery attempts at 16:12 and +16:15 Lisbon time. Both stop at required base refresh with `exit status 128`. +Terminal requests report a missing workspace path. Another task later continues +with an `origin/master` fallback. The original task reaches setup resolution at +16:25, then reports no PR after push at 16:26. + +These logs do not establish the Git cause, installed version, local-ref state, +or whether a PR existed. The plan repairs source-confirmed diagnostic defects. +It does not claim to repair the user's environment or change refresh policy. + +- `handleBaseFetchFailure` uses output for coarse classification, then discards + it. `pullCurrentBranchOrFallback` passes the process error without useful + command context. The original logs can match pull failures too. +- `detectPushAndAssociatePRWithIdentity` merges errors and empty search results. + `searchPRForExistingWatch` also discards provider errors. These are concrete + gaps in discovery AC .3, extended with diagnostic AC .5. +- `resolvePreparerSetupScript` intentionally skips comment-only scripts but + logs WARN. Platform AC .12 makes the intended severity explicit. + +Smallest reproductions use fake Git command output, a scripted PR service, +and the existing setup resolver with an observed logger. No live environment +or GitHub credentials are needed. Permanent regression tests belong to the +implementation turn and must fail before the correction. + +## Scope + +### In scope + +- Credential-safe Git operation, checkout identity, and diagnostic categories. +- Distinct provider-error, empty, found, and cancellation outcomes for post-push lookup. +- Debug severity for comment-only setup scripts. +- Tests for diagnostics and unchanged execution decisions. + +### Out of scope + +- Terminal readiness, frontend reconnect timing, 503 severity, or rate limiting. +- Git fallback policy, automatic credentials repair, branch changes, or lock deletion. +- Provider retry budgets, discovery health state, schema, APIs, UI, or translations. +- Deployment, live-instance changes, persistent subtasks, or delegated implementation. + +## Ownership and technical approach + +Workspaces owns base refresh and its Git diagnostics. Integrations owns PR +query outcomes. Platform owns diagnostic severity. Extend those existing +requirement/design pairs rather than creating a separate repair specification. + +Task 01 adds diagnostic-only classification to fetch and pull failure paths in +`internal/worktree`. Fixed explanations preserve secret exclusion without a new +raw-output redaction boundary. Existing reasons retain their policy meaning. +Task 02 separates PR lookup results in both orchestrator entry paths and reuses +the GitHub category classifier. Task 03 changes one setup omission log level. +The paired designs define fields, cancellation, and final-outcome semantics. + +No new ADR is needed. Existing credential exclusion and refresh decisions remain +authoritative, including the local-first and required-refresh ADRs linked by the +workspace design. No public documentation changes are needed for this change. + +## Tests + +| Acceptance criteria | Regression evidence | +| --- | --- | +| Workspace .14; preserve .3, .6, .10, .13 | New `internal/worktree/refresh_diagnostics_test.go`: `TestRefreshDiagnosticClassification`, `TestBaseRefreshDiagnosticEmission`, `TestRefreshDiagnosticsPreservePolicy`. Cover fetch/pull, fallback failure, unknown output, secrets, context, and unchanged decisions. | +| Discovery .3, .5; preserve .1, .2, .4 | New `internal/orchestrator/event_handlers_github_push_diagnostics_test.go`: `TestPushDiscoveryDiagnostics`, `TestExistingWatchDiscoveryDiagnostics`. Include mixed outcomes, cancellation, found PR, and exact repository identity. | +| Platform .12 | Extend `internal/agent/runtime/lifecycle/preparer_script_test.go`: `TestResolvePreparerSetupScriptDiagnosticSeverity`. Assert debug omission and unchanged resolution. Retain actual failure coverage in `env_preparer_setup_script_test.go`. | + +These are backend log contracts. Observer tests through the real service paths +provide end-to-end diagnostic evidence. No browser layout or flow changes, so +no Playwright work order is necessary. Unknown environmental failures remain +unknown even after richer diagnostics. + +## Companion package inventory + +The completed `github-pr-discovery-health` and `github-pr-watch-reconciliation` +packages own health UI/admission and watch target stability. Their delivered +scope, browser matrices, and historical results stay unchanged. This package +adds only post-push log correctness. Existing Git fallback tests remain policy +regressions; this package does not reopen the refresh decisions. + +## Work orders + +- [x] [Task 01: Explain Git refresh failures](task-01-git-diagnostics.md) +- [x] [Task 02: Distinguish PR lookup outcomes](task-02-pr-diagnostics.md) +- [x] [Task 03: Quiet empty setup scripts](task-03-setup-log-severity.md) + +## Verification results + +Implementation complete on September 22, 2026. Design validation passed before +implementation: + +- Catalog validation: 299 decisions and 1,108 specifications. +- Specification linter tests: 36 passed. +- Full specification lint: passed. +- Scoped diff whitespace check: passed. +- Scoped status inspection: six specification edits and four new plan files. + +Implementation verification passed for every work order, including targeted +race checks, and `go build ./...` passed. Targeted `golangci-lint` for all four +affected backend packages passed with zero issues. Specification catalog +validation and full specification lint also passed. A repository-wide +`go test ./... -count=1` run reached the changed packages successfully but exited non-zero on unrelated +environment-sensitive failures in process probing, home-config discovery, +websocket subscription counting, GitHub fixture setup, launcher restart tests, +and executor timing. + +The review remediation then corrected provider deadline handling in PR +discovery and the pull fast-forward diagnostic classifier, and added focused +regression fixtures. Builds and tests were not rerun for that remediation per +the review instruction. The verification results above therefore apply to the +pre-remediation implementation state at that time. + +PR fixup then split the PR discovery retry handler to satisfy the backend +function-size limit, added the review-requested assertions and comments, and +guarded optional secret checks. The focused orchestrator, worktree, and GitHub +tests passed, and base-relative `golangci-lint` completed with zero issues. The +later CI remediation corrected a stale websocket subscription-count assertion, +made tracked execution persistence read status under the execution-store lock, +and raised the static-analysis budget from five to ten minutes after CI timed +out with zero lint findings. The new lifecycle and websocket regressions pass +under `-race`, the full lifecycle and websocket packages pass, `go build ./...` +passes, and base-relative `golangci-lint --timeout=10m` reports zero issues. +A complete local `go test ./... -count=1` run still exits nonzero on the +environment-sensitive process-tree probe, home-config discovery, and launcher +restart tests, and one lifecycle package failure under aggregate scheduling; +the lifecycle package passes when rerun alone. CI's E2E matrix was green during +both post-push runs, so no E2E code change was made. + +Each work order supplies exact Go checks, rooted at the repository root. +Final package checks: + +```bash +python3 scripts/list-docs.py validate +python3 scripts/lint-spec-files.test.py +python3 scripts/lint-spec-files.py --all +git diff --check -- docs/specs docs/plans/recovery-diagnostics +git status --short -- docs/specs docs/plans/recovery-diagnostics +``` + +## Risks + +- Git text varies by version and locale. Unrecognized output must remain unknown. +- Diagnostic codes must not become fallback policy inputs. +- Raw Git and provider output can contain credentials. Only fixed summaries leave classifiers. +- PR retries can have mixed results. Tests must prove the final outcome reflects the latest attempt. +- Package-level logger replacement in tests needs cleanup and serial execution. +- The original Git root cause requires the affected version and additional safe evidence. diff --git a/docs/plans/recovery-diagnostics/task-01-git-diagnostics.md b/docs/plans/recovery-diagnostics/task-01-git-diagnostics.md new file mode 100644 index 0000000000..c5abebe458 --- /dev/null +++ b/docs/plans/recovery-diagnostics/task-01-git-diagnostics.md @@ -0,0 +1,144 @@ +--- +id: "01-git-diagnostics" +title: "Explain Git refresh failures" +status: done +wave: 1 +depends_on: [] +plan: "plan.md" +requirements: + - REQ-WORKSPACES-WORKTREE-BASE-REFRESH-001 +acceptance_criteria: + - AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.3 + - AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.6 + - AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.10 + - AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.13 + - AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.14 +system_design: + - ../../specs/workspaces/system-design/worktree-base-refresh.md +--- + +# Task 01: Explain Git refresh failures + +## Summary + +Add diagnostic evidence without changing refresh admission or fallback. Use +fixed categories and explanations instead of raw Git output. + +## In scope + +- Add `refresh_diagnostics.go` with a diagnostic-only classifier and fixed summaries. +- Integrate both fetch and pull failure paths, including configured fallback failures. +- Record operation, local checkout path, branch, existing reason, diagnostic code, + fixed detail, and optional exit code. Do not read or emit remote URLs. +- Preserve error identities, progress payloads, return values, and ref selection. +- Correct the misleading raw-output comment on `syncFailureCause`. + +## Out of scope + +Other work orders, terminal behavior, UI, schema, retry policy, and live-instance changes. + +## Acceptance + +1. Known failures have useful fixed explanations. Unknown output remains unknown. +2. Logs, errors, and progress contain no injected secret or raw command output. +3. Required refresh, local fallback, missing-ref fallback, and cancellation retain their decisions. + +## Regression evidence + +In new `refresh_diagnostics_test.go`, add `TestRefreshDiagnosticClassification`, +`TestBaseRefreshDiagnosticEmission`, and `TestRefreshDiagnosticsPreservePolicy`. +The emission test must fail first because current logs lack the new fields. +Use the fake command pattern from `manager_test.go` and the observer pattern +from `manager_state_test.go`. Exercise fetch and pull through the manager, +not only the classifier. Include SSH public-key and host-key errors, DNS, +connection/TLS errors, missing refs, non-fast-forward errors, inaccessible +repositories, locks, unknown text, timeout, and cancellation. + +Inject tokens, credential URLs, headers, control characters, and long output. +Assert their absence from all emitted fields, returned errors, and progress. +Use actual local refs to cover required failure and successful local fallback. +Assert no ref mutation or extra Git invocation. Keep the existing missing-ref +policy tests authoritative for eligibility. + +## Verification + +Run the regression first and record its expected failure. After implementation, +run these commands from the repository root: + +```bash +(cd apps/backend && go test ./internal/worktree -count=1) +(cd apps/backend && go test -race ./internal/worktree -run 'Test(RefreshDiagnostic|BaseRefreshDiagnostic|RefreshDiagnosticsPreservePolicy)' -count=1) +git diff --check +``` + +## Files likely touched + +- `apps/backend/internal/worktree/manager_git.go` +- `apps/backend/internal/worktree/refresh_diagnostics.go (new)` +- `apps/backend/internal/worktree/refresh_diagnostics_test.go (new)` + +## Dependencies + +None. Execute in the plan order by default. + +## Risks + +Git text is not a stable API. Keep diagnostic classification separate from policy. + +## Parallelism + +`sequential` + +## Inputs + +- [Requirement](../../specs/workspaces/requirements/worktree-base-refresh.md) +- [System design](../../specs/workspaces/system-design/worktree-base-refresh.md) +- [Plan evidence and exclusions](plan.md) +- Backend AGENTS.md and TDD backend test guidance. + +## Results + +Implemented credential-safe diagnostic classification and emission for base +branch fetch and pull failures. The diagnostic fields preserve the existing +refresh reason and policy decisions, while fixed explanations and optional +exit codes keep raw Git output out of logs, returned errors, and progress. + +The new regression suite covers authentication, SSH key and host failures, +DNS, connection, TLS, missing refs, non-fast-forward updates, repository +access, lock contention, unknown output, timeout, cancellation, fetch and +pull emission, and required-refresh policy preservation. The first emission +test failed before the production change because no diagnostic log existed. + +Verification passed: + +```text +go test ./internal/worktree -count=1 +go test -race ./internal/worktree -run 'Test(RefreshDiagnostic|BaseRefreshDiagnostic|RefreshDiagnosticsPreservePolicy)' -count=1 +git diff --check +``` + +## Review remediation + +The classifier now recognizes Git's pull fast-forward refusal, uses local +branch wording for that outcome, and leaves tag-clobber output unknown. Fetch +and pull fixtures cover the real failure forms. Builds and tests were not +rerun for this review remediation, so the verification above describes the +pre-remediation implementation state at that time. + +## PR fixup verification + +The focused worktree regression passed after the review fixes: + +```text +go test ./internal/worktree -run 'Test(RefreshDiagnostic|BaseRefreshDiagnostic|RefreshDiagnosticsPreservePolicy)' -count=1 +golangci-lint run ./... --new-from-rev='195530e5766abf7f44f08e2d5ad436b22c28d748' --timeout=5m +``` + +The later CI remediation also passed `go build ./...` and the full +`internal/worktree`, `internal/agent/runtime/lifecycle`, and +`internal/gateway/websocket` package suites, including race-enabled runs for +the two packages affected by CI. Base-relative lint reports zero issues with +the ten-minute analyzer budget. A complete local `go test ./... -count=1` +run remains nonzero on environment-sensitive process-tree, home-config, and +launcher tests, plus one lifecycle package failure under aggregate scheduling; +the lifecycle package passed when rerun alone. diff --git a/docs/plans/recovery-diagnostics/task-02-pr-diagnostics.md b/docs/plans/recovery-diagnostics/task-02-pr-diagnostics.md new file mode 100644 index 0000000000..f2a1f59655 --- /dev/null +++ b/docs/plans/recovery-diagnostics/task-02-pr-diagnostics.md @@ -0,0 +1,149 @@ +--- +id: "02-pr-diagnostics" +title: "Distinguish PR lookup outcomes" +status: done +wave: 1 +depends_on: [] +plan: "plan.md" +requirements: + - REQ-INTEGRATIONS-GITHUB-PR-DISCOVERY-001 +acceptance_criteria: + - AC-INTEGRATIONS-GITHUB-PR-DISCOVERY-001.1 + - AC-INTEGRATIONS-GITHUB-PR-DISCOVERY-001.2 + - AC-INTEGRATIONS-GITHUB-PR-DISCOVERY-001.3 + - AC-INTEGRATIONS-GITHUB-PR-DISCOVERY-001.4 + - AC-INTEGRATIONS-GITHUB-PR-DISCOVERY-001.5 +system_design: + - ../../specs/integrations/system-design/github-pr-discovery-health.md +--- + +# Task 02: Distinguish PR lookup outcomes + +## Summary + +Separate provider errors from successful empty post-push searches. Apply the +same diagnostic contract to existing searching watches. + +## In scope + +- Update `detectPushAndAssociatePRWithIdentity` and `searchPRForExistingWatch`. +- Reuse GitHub discovery categories through a narrow exported classifier. +- Warn on failed attempts with resolved target identity and safe category. +- Keep empty and exhausted summaries at debug. Record counts and latest outcome. +- Preserve production delays, context cancellation, association, and admission. +- Add a private wait seam only as needed to exercise retries without real sleeps. + +## Out of scope + +Other work orders, terminal behavior, UI, schema, retry policy, and live-instance changes. + +## Acceptance + +1. Provider errors never become successful empty results or expose raw error text. +2. Empty results and cancellation produce no provider-failure or exhaustion warning. +3. Later success, watch reuse, repository identity, and association behavior remain correct. + +## Regression evidence + +Add `TestPushDiscoveryDiagnostics` and `TestExistingWatchDiscoveryDiagnostics` +in new `event_handlers_github_push_diagnostics_test.go`. Reuse service seeding +and mocks from `event_handlers_github_test.go` and multi-branch association tests. +First prove a provider error is currently absent from warnings and that all-empty +retries currently end with WARN. Use an observed logger through the real caller. + +Cover all-empty, all-error, error then empty, empty then error, error then found, +and cancellation before lookup and during a delay. Include an existing searching +watch, a numbered watch, empty legacy repository name, and a secondary repository. +Assert exact provider calls, wait schedule, no duplicate associations, no health +mutation, and no raw credential-containing errors in logs. A successful lookup +must continue through existing association persistence. Extend classifier tests +in `service_pr_discovery_health_test.go` only if the exported seam needs coverage. +Do not duplicate the category rules in the orchestrator. + +## Verification + +Run the regression first and record its expected failure. After implementation, +run these commands from the repository root: + +```bash +(cd apps/backend && go test ./internal/orchestrator -run 'Test(PushDiscoveryDiagnostics|ExistingWatchDiscoveryDiagnostics|DetectPushAndAssociatePR|GitHubPushAssociation|PushAssociation|ResolvePRWatchBranchForWatch)' -count=1) +(cd apps/backend && go test -race ./internal/orchestrator -run 'Test(PushDiscoveryDiagnostics|ExistingWatchDiscoveryDiagnostics)' -count=1) +(cd apps/backend && go test ./internal/github -run 'Test(ClassifyPRDiscoveryError|PRDiscovery)' -count=1) +git diff --check +``` + +## Files likely touched + +- `apps/backend/internal/orchestrator/event_handlers_github.go` +- `apps/backend/internal/orchestrator/event_handlers_github_push_diagnostics_test.go (new)` +- `apps/backend/internal/orchestrator/event_handlers_github_test.go (mock seam if needed)` +- `apps/backend/internal/github/service_pr_discovery_health.go` +- `apps/backend/internal/github/service_pr_discovery_health_test.go` + +## Dependencies + +None. Execute in the plan order by default. + +## Risks + +Error and empty results can alternate. Historical errors must not override later successful outcomes. + +## Parallelism + +`sequential` + +## Inputs + +- [Requirement](../../specs/integrations/requirements/github-pr-discovery-health.md) +- [System design](../../specs/integrations/system-design/github-pr-discovery-health.md) +- [Plan evidence and exclusions](plan.md) +- Backend AGENTS.md and TDD backend test guidance. + +## Results + +Implemented a bounded exported GitHub discovery classifier and separated +successful empty lookups, provider failures, found PRs, and cancellation in +post-push and existing-watch paths. Failed provider attempts now log only the +workspace, task, repository identity, branch, attempt, and safe category. +Empty attempts and retry exhaustion are debug logs with outcome counts. The +existing association and watch reuse paths remain unchanged after a found PR. + +The first regression run failed at compile time because the retry wait seam was +not yet present. After implementation, verification passed: + +```text +go test ./internal/orchestrator -run 'Test(PushDiscoveryDiagnostics|ExistingWatchDiscoveryDiagnostics|DetectPushAndAssociatePR|GitHubPushAssociation|PushAssociation|ResolvePRWatchBranchForWatch)' -count=1 +go test -race ./internal/orchestrator -run 'Test(PushDiscoveryDiagnostics|ExistingWatchDiscoveryDiagnostics)' -count=1 +go test ./internal/github -run 'Test(ClassifyPRDiscoveryError|PRDiscovery)' -count=1 +git diff --check +``` + +## Review remediation + +PR discovery now uses the caller context state to decide whether to stop. A +live caller treats wrapped provider deadlines and cancellations as failed +attempts, so post-push retries and existing-watch diagnostics remain active. +Focused coverage covers wrapped provider deadlines in both paths and retains +actual caller-cancellation coverage. Builds and tests were not rerun for this +review remediation, so the verification above describes the pre-remediation +implementation state at that time. + +## PR fixup verification + +The focused orchestrator and GitHub regression commands passed after the review +fixes, and the base-relative backend lint completed with zero issues: + +```text +go test ./internal/orchestrator -run 'Test(PushDiscoveryDiagnostics|ExistingWatchDiscoveryDiagnostics|DetectPushAndAssociatePR|GitHubPushAssociation|PushAssociation|ResolvePRWatchBranchForWatch)' -count=1 +go test ./internal/github -run 'Test(ClassifyPRDiscoveryError|PRDiscovery)' -count=1 +golangci-lint run ./... --new-from-rev='195530e5766abf7f44f08e2d5ad436b22c28d748' --timeout=5m +``` + +The later CI remediation reran base-relative lint with a ten-minute analyzer +budget and it reported zero issues. The changed lifecycle and websocket +packages, including race-enabled runs, pass locally. The full backend build +now passes; a complete local test run remains nonzero on the documented +environment-sensitive process-tree, home-config, and launcher tests, plus one +lifecycle package failure under aggregate scheduling; the lifecycle package +passed when rerun alone. CI's E2E matrix remained green, so this work order has +no E2E changes. diff --git a/docs/plans/recovery-diagnostics/task-03-setup-log-severity.md b/docs/plans/recovery-diagnostics/task-03-setup-log-severity.md new file mode 100644 index 0000000000..0ed6a1db9b --- /dev/null +++ b/docs/plans/recovery-diagnostics/task-03-setup-log-severity.md @@ -0,0 +1,97 @@ +--- +id: "03-setup-log-severity" +title: "Quiet empty setup scripts" +status: done +wave: 1 +depends_on: [] +plan: "plan.md" +requirements: + - REQ-PLATFORM-DIAGNOSTIC-LOGGING-001 +acceptance_criteria: + - AC-PLATFORM-DIAGNOSTIC-LOGGING-001.12 +system_design: + - ../../specs/platform/system-design/diagnostic-logging-01.md +--- + +# Task 03: Quiet empty setup scripts + +## Summary + +Record intentional comment-only setup omissions at debug level. Preserve +setup resolution and actual script-failure warnings. + +## In scope + +- Change the omission log in `resolvePreparerSetupScript` from Warn to Debug. +- Preserve identity fields and omit script contents. +- Cover default and explicit comment-only scripts without changing execution. + +## Out of scope + +Other work orders, terminal behavior, UI, schema, retry policy, and live-instance changes. + +## Acceptance + +1. Comment-only scripts return an empty result without a warning. +2. Debug logs retain useful identity fields and contain no script content. +3. Executable scripts and actual setup failures retain their existing behavior. + +## Regression evidence + +Extend `preparer_script_test.go` with +`TestResolvePreparerSetupScriptDiagnosticSeverity`. Observe the logger while +resolving default and explicit comment-only scripts. The warning assertion must +fail before the change. Include blank and shebang-only inputs and an executable +script control. Restore the package logger with cleanup and do not run this test +in parallel. Retain existing script execution failure tests. + +## Verification + +Run the regression first and record its expected failure. After implementation, +run these commands from the repository root: + +```bash +(cd apps/backend && go test ./internal/agent/runtime/lifecycle -run 'Test(ResolvePreparerSetupScript|IsScriptEffectivelyEmpty|.*SetupScript.*)' -count=1) +(cd apps/backend && go test -race ./internal/agent/runtime/lifecycle -run 'TestResolvePreparerSetupScriptDiagnosticSeverity' -count=1) +git diff --check +``` + +## Files likely touched + +- `apps/backend/internal/agent/runtime/lifecycle/preparer_script.go` +- `apps/backend/internal/agent/runtime/lifecycle/preparer_script_test.go` + +## Dependencies + +None. Execute in the plan order by default. + +## Risks + +Package logger replacement needs serial tests and cleanup. + +## Parallelism + +`sequential` + +## Inputs + +- [Requirement](../../specs/platform/requirements/diagnostic-logging.md) +- [System design](../../specs/platform/system-design/diagnostic-logging-01.md) +- [Plan evidence and exclusions](plan.md) +- Backend AGENTS.md and TDD backend test guidance. + +## Results + +Changed the intentional comment-only setup omission log from WARN to DEBUG. +Resolution remains empty for default, explicit, blank, and shebang-only scripts; +executable scripts remain executable. The observer regression confirms identity +fields remain present and script contents remain absent. + +The warning assertion failed before the production change because the existing +log level was WARN. Verification passed: + +```text +go test ./internal/agent/runtime/lifecycle -run 'Test(ResolvePreparerSetupScript|IsScriptEffectivelyEmpty|.*SetupScript.*)' -count=1 +go test -race ./internal/agent/runtime/lifecycle -run 'TestResolvePreparerSetupScriptDiagnosticSeverity' -count=1 +git diff --check +``` diff --git a/docs/specs/integrations/requirements/github-pr-discovery-health.md b/docs/specs/integrations/requirements/github-pr-discovery-health.md index 8aa3ad78dc..36384d3f94 100644 --- a/docs/specs/integrations/requirements/github-pr-discovery-health.md +++ b/docs/specs/integrations/requirements/github-pr-discovery-health.md @@ -36,6 +36,12 @@ and provider status. Task and UI systems consume its results. A confirmed rename may update that target; missing or ambiguous branch information shall not redirect it to a sibling target. +- **AC-INTEGRATIONS-GITHUB-PR-DISCOVERY-001.5:** Post-push diagnostics shall + distinguish a provider error from a successful search without a PR. + Provider errors shall include a credential-safe category and target identity. + Successful empty searches shall not produce warnings. Cancellation shall not + report provider failure. A later success shall not retain a failed final outcome. + ### REQ-INTEGRATIONS-GITHUB-PR-DISCOVERY-HEALTH-001: Explain discovery failures #### Acceptance criteria diff --git a/docs/specs/integrations/system-design/github-pr-discovery-health.md b/docs/specs/integrations/system-design/github-pr-discovery-health.md index f0efde4824..204a817199 100644 --- a/docs/specs/integrations/system-design/github-pr-discovery-health.md +++ b/docs/specs/integrations/system-design/github-pr-discovery-health.md @@ -149,6 +149,37 @@ They must assert the phone drawer, not a tooltip opened by a simulated tap. No live task is repaired by this package. After deployment, normal discovery can link eligible PRs. Waiting for quota reset cannot repair invalid code. +## Post-push diagnostic outcomes + +Discovery ACs .3 and .5 also cover `event_handlers_github.go` in the +orchestrator. `detectPushAndAssociatePRWithIdentity` currently merges provider +errors and empty results. `searchPRForExistingWatch` silently discards lookup +errors. Both paths must distinguish `found`, `empty`, `failed`, and `canceled`. + +For a failed lookup, log a warning with the operation, workspace, task, session, +resolved repository ID, owner, repository name, branch, and safe category. +Reuse `classifyPRDiscoveryError` through a narrow exported classifier in the +GitHub package. Do not log `err.Error()`, response bodies, or request URLs. +Retain `invalid_query`, `rate_limited`, and `unavailable` as categories. +Do not invent an authentication diagnosis from an unclassified error. + +Each successful empty lookup is debug-level evidence. At retry exhaustion, +report attempt, error, and empty counts plus the last outcome at debug level. +Failed attempts already have warnings. An empty result after an error records +an empty final outcome. A found result follows the existing association path. +Cancellation returns without a failure or exhausted-retry warning. + +Keep the production retry schedule, service admission, watch identity, +association ownership, and health recovery rules unchanged. Factor a private +retry runner with an injected wait function if needed for deterministic tests. +Production waits remain context-aware with delays of zero, 30, and 60 seconds. +Tests exercise the runner through the orchestration entry point without sleeps. +No public status fields or frontend changes are necessary. + +Delivery: [Recovery diagnostic fixes](../../../plans/recovery-diagnostics/plan.md). +The completed discovery-health and watch-reconciliation packages retain their +historical scope and results. + ## References - [GitHub Repository schema](https://docs.github.com/en/graphql/reference/objects#repository) diff --git a/docs/specs/platform/requirements/diagnostic-logging.md b/docs/specs/platform/requirements/diagnostic-logging.md index d1a59cfe7c..1168430921 100644 --- a/docs/specs/platform/requirements/diagnostic-logging.md +++ b/docs/specs/platform/requirements/diagnostic-logging.md @@ -41,6 +41,11 @@ Users can see frontend failures that leave no backend evidence, and support cann than 15 seconds. A browser wall-clock offset shall not change this duration. The backend shall remain authoritative for job expiry. +- **AC-PLATFORM-DIAGNOSTIC-LOGGING-001.12:** When a resolved setup script + contains only comments, a shebang, or blank lines, its omission shall not + produce a warning. Debug diagnostics can record the omission. Executable + script failures shall retain their existing warning behavior. + ## System design The migrated technical source is split into [part 1](../system-design/diagnostic-logging-01.md), [part 2](../system-design/diagnostic-logging-02.md). diff --git a/docs/specs/platform/system-design/diagnostic-logging-01.md b/docs/specs/platform/system-design/diagnostic-logging-01.md index 8577152504..0fef57a066 100644 --- a/docs/specs/platform/system-design/diagnostic-logging-01.md +++ b/docs/specs/platform/system-design/diagnostic-logging-01.md @@ -331,3 +331,17 @@ acp/session-01/normalized-acp.jsonl description. The bootstrap route never waits for frontend collection. The task-context copy retains the existing 24-hour cleanup window so a newly launched agent can read it. + +## Expected setup-script omissions + +AC .12 applies the logging severity contract to +`internal/agent/runtime/lifecycle/preparer_script.go`. Change the comment-only +branch in `resolvePreparerSetupScript` to debug severity. Retain its current +structured identity fields and omit script content. This includes both default +and explicit comment-only scripts. + +Keep `isScriptEffectivelyEmpty`, placeholder resolution, returned values, and +`runSetupScriptStep` failure warnings unchanged. No logger-wide filter or +terminal HTTP suppression is part of this change. + +Delivery: [Recovery diagnostic fixes](../../../plans/recovery-diagnostics/plan.md). diff --git a/docs/specs/workspaces/requirements/worktree-base-refresh.md b/docs/specs/workspaces/requirements/worktree-base-refresh.md index b75ff7dabc..21b0d4808d 100644 --- a/docs/specs/workspaces/requirements/worktree-base-refresh.md +++ b/docs/specs/workspaces/requirements/worktree-base-refresh.md @@ -82,6 +82,13 @@ local branches without publishing them first. classification. Authentication, network, timeout, cancellation, divergent, uncertain, and other unproven failures remain fatal for pull-request tasks. +- **AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.14:** When a base refresh fails, + backend diagnostics shall identify the repository, operation, branch, and + failure category. Known causes shall have a fixed diagnostic explanation. + Unknown causes shall remain explicitly unknown. Diagnostics shall exclude + credentials, remote URLs, and raw command output. Existing refresh and + fallback decisions shall remain unchanged. + ## Compatibility This requirement replaces the universal fail-closed refresh behavior from diff --git a/docs/specs/workspaces/system-design/worktree-base-refresh.md b/docs/specs/workspaces/system-design/worktree-base-refresh.md index 5b9b751b68..5b7f409dad 100644 --- a/docs/specs/workspaces/system-design/worktree-base-refresh.md +++ b/docs/specs/workspaces/system-design/worktree-base-refresh.md @@ -37,6 +37,7 @@ change Git commands that an agent runs after launch. | `AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.11` | [Pull-request base reconciliation](#pull-request-base-reconciliation) | | `AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.12` | [Pull-request base reconciliation](#pull-request-base-reconciliation) | | `AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.13` | [Missing-base fallback](#missing-base-fallback) | +| `AC-WORKSPACES-WORKTREE-BASE-REFRESH-001.14` | [Safe refresh diagnostics](#safe-refresh-diagnostics) | ## Components and responsibilities @@ -211,6 +212,39 @@ Local fallback reports completion with a warning, not a launch error. Structured logs record repository identity, refresh route, failure class, and selected fallback ref. Logs exclude credential material and raw remote URLs. +### Safe refresh diagnostics + +AC .14 extends the existing observability contract. `manager_git.go` captures +combined command output, but failure paths retain only coarse reasons or an +exit status. Inspect that output in memory and emit fixed diagnostic values. +Do not append raw output to logs, returned errors, or progress events. + +Keep the existing policy `reason` separate from a diagnostic-only +`diagnostic_code`. Add an allow-listed classifier in +`internal/worktree/refresh_diagnostics.go`. It recognizes authentication, +SSH public-key rejection, SSH host verification, DNS, connection failure, +TLS verification, missing remote ref, non-fast-forward rejection, repository +access failure, and lock contention. Unknown output maps to `unknown`. +Context cancellation and execution timeout take precedence over text matches. +Each code maps to a fixed English explanation. No explanation includes +substrings from Git output. Repository access failure does not assert that +credentials are invalid, and lock contention does not assert a stale lock. + +Emit one structured diagnostic per failed fetch or pull with `operation`, +`repository_path`, `branch`, `reason`, `diagnostic_code`, `detail`, and an exit +code when available. The local repository path identifies the checkout without +reading its remote URL. Existing failure or fallback logs can carry these fields +instead of adding a duplicate diagnostic. Cover both required and best-effort +paths, including a failed configured fallback branch. + +Classification is observational. Do not feed new diagnostic categories into +missing-base fallback eligibility or alter `syncFailureCause` identities. +Preserve context errors and current progress/error payloads. Correct the +`syncFailureCause` comment that implies raw output reaches internal logs. +No new logging configuration, subprocess, retry, or persistence is required. + +Delivery: [Recovery diagnostic fixes](../../../plans/recovery-diagnostics/plan.md). + ## Related decisions - [Local Worktree Refresh Is Best Effort](../../../decisions/2026-08-31-local-worktree-refresh-best-effort.md)