From 30329f3e268069d80654287e160b450122bc0e80 Mon Sep 17 00:00:00 2001 From: Manas Srivastava Date: Sat, 30 May 2026 16:31:17 +0530 Subject: [PATCH 1/3] fix(deploy_failure_autopsy): capture build logs + emit failure email backstop MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The autopsy already wrote a deployment_events row with kind=failure_autopsy, but in the 2026-05-30 silent-deploy-failure incident: - deployments.error_message was never updated → CLI / dashboard list views showed an empty error column. - No audit_log row was emitted → event_email_forwarder never dispatched the user-visible failure email (the api's runDeploy normally emits this, but the api goroutine had already crashed mid-build). - The autopsy only queried the runtime app pod (label instant-app-id=). For a Job-only failure (PR 1's case) the app pod was never created → last_lines stayed empty even when the build pod was still alive with the kaniko stderr tail that explains the failure. This PR adds three things to captureDeploymentAutopsy: 1. Build-pod fallback: when the app pod yields no logs, list pods matching label "job-name=build-" and pull the kaniko log tail. On success the reason is upgraded from Unknown to BuildFailed. 2. updateDeploymentErrorMessage: stamps ": " onto deployments.error_message when the column is NULL or empty (the non-clobber guard prevents overwriting a more-specific api-side error). 3. emitDeployFailedAudit: looks up team_id from deployments, then INSERTs an audit_log row with kind=deploy.failed so event_email_forwarder dispatches the failure email. Metadata includes source="worker_autopsy" so an operator can distinguish the worker-backstop emit from the api's synchronous one. Rule 25 observability: new Prom counter instant_deploy_autopsy_captured_total{outcome} with bounded labels (logs_captured | logs_unavailable | already_present | audit_emit_failed). NR alert suggestions documented in metrics.go. All four label families are primed at process start (metrics_test.go) so the dashboard panel renders from /metrics scrape #1. Coverage block: Symptom: failed deployments had no error_message in the API row response and the user never received a deploy.failed email. Enumeration: rg "captureDeploymentAutopsy|deploy.failed|error_message" worker/internal/jobs (also api/internal/handlers for sources). Sites found: 1 (deploy_failure_autopsy.go:captureDeploymentAutopsy). Sites touched: 1 (callers in deploy_status_reconcile.go work unchanged). Coverage test: TestAutopsy_PodAlive_CapturesLogs, TestAutopsy_PodGCd_FallsBackToJobEvent, TestAutopsy_Idempotent, TestAutopsy_BuildPodFallback, TestUpdateDeploymentErrorMessage_OnlyUpdatesEmptyColumn, TestUpdateDeploymentErrorMessage_DBError, TestFirstSentence, TestEmitDeployFailedAudit_NoRow / _LookupError / _NilTeamID / _InsertError / _SummaryTruncation, TestAutopsyAlreadyPresentWithReason (3 branches), TestFindBuildPodName (3 branches), TestAutopsy_NamespaceMismatch_EarlyReturn. Live verified: PENDING — verify post-merge via rule 14, then trigger a deliberately failing Dockerfile build and confirm the user receives the deploy.failed email AND GET /deploy/:id returns a populated error_message + failure.last_lines. Pairs with PR fix/deploy-status-reconcile-job-failed (PR 1) — together they close the silent-deploy-failure bug class. Each ships as a separate PR for independent rollback per swarm charter. make gate: green locally (matches deploy.yml test step). Co-Authored-By: Claude Opus 4.7 (1M context) --- internal/jobs/deploy_failure_autopsy.go | 311 ++++++++- ...deploy_failure_autopsy_log_capture_test.go | 591 ++++++++++++++++++ internal/jobs/deploy_failure_autopsy_test.go | 31 +- internal/metrics/metrics.go | 40 ++ internal/metrics/metrics_test.go | 7 + 5 files changed, 971 insertions(+), 9 deletions(-) create mode 100644 internal/jobs/deploy_failure_autopsy_log_capture_test.go diff --git a/internal/jobs/deploy_failure_autopsy.go b/internal/jobs/deploy_failure_autopsy.go index 2201acb..ef3f3aa 100644 --- a/internal/jobs/deploy_failure_autopsy.go +++ b/internal/jobs/deploy_failure_autopsy.go @@ -58,6 +58,7 @@ import ( "context" "database/sql" "encoding/json" + "errors" "fmt" "io" "log/slog" @@ -69,8 +70,45 @@ import ( apierrors "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/client-go/kubernetes" + + "instant.dev/worker/internal/metrics" +) + +// ── Autopsy metric outcome labels ───────────────────────────────────────────── +// +// Used as the `outcome` label on instant_deploy_autopsy_captured_total. Kept +// in a small bounded set so dashboard panels render predictable series. + +const ( + // autopsyOutcomeLogsCaptured: at least one log line was captured from + // either the app pod or the build pod — full autopsy succeeded. + autopsyOutcomeLogsCaptured = "logs_captured" + + // autopsyOutcomeLogsUnavailable: the autopsy ran but the pod was already + // GC'd (or never existed — image-pull failure) and no log lines were + // captured. Reason and event fields are still populated from k8s state + // + Job event fallback; lastLines is empty. + autopsyOutcomeLogsUnavailable = "logs_unavailable" + + // autopsyOutcomeAlreadyPresent: the deployment_events row already had a + // real (non-Unknown) reason from a prior autopsy and this tick added + // nothing new — pure idempotent re-capture. Distinguishes "the autopsy + // is doing useful work" from "the autopsy is just looping over old + // state every 30s". + autopsyOutcomeAlreadyPresent = "already_present" + + // autopsyOutcomeAuditEmitFailed: the autopsy row upsert succeeded but + // the audit_log emit failed (Postgres brownout). Surfaces in the + // dashboard so a missing failure email has a corresponding metric. + autopsyOutcomeAuditEmitFailed = "audit_emit_failed" ) +// labelBuildJobName mirrors api/internal/providers/compute/k8s/client.go's +// build-Job pod label `job-name=build-`. Used by the autopsy log +// fallback path to fetch logs from the kaniko build pod when the runtime +// app pod was never created (BuildFailed / DeadlineExceeded modal case). +const labelBuildJobName = "job-name" + // ── Failure reason constants ────────────────────────────────────────────────── // // Mirror of api/internal/models/deployment_event.go constants. Duplicated @@ -248,6 +286,27 @@ type autopsyResult struct { // case the function writes an Unknown row with an empty last_lines so the // api can at least surface "failure" : { "reason": "Unknown" } rather than // omitting the field entirely. +// +// SILENT-DEPLOY-FAILURE FIX (2026-05-30, PR 2): +// +// In addition to writing the deployment_events row, the autopsy now ALSO: +// +// 1. UPDATEs deployments.error_message with ": " so +// the api's GET /deploy/:id surfaces a one-line human-readable cause +// even when the caller doesn't pull the structured deployment_events. +// +// 2. Emits an audit_log row with kind='deploy.failed' so the +// event_email_forwarder dispatches the failure email (the api's runDeploy +// normally emits this, but the user incident showed that when the api +// goroutine crashes mid-build the audit row is never written — the +// worker fills the gap so the user still gets the email). +// +// 3. Increments instant_deploy_autopsy_captured_total{outcome} so the NR +// dashboard can chart logs_captured vs logs_unavailable vs already_present. +// +// The audit-emit is idempotent at the email layer (event_email_forwarder +// dedupes by audit_log.id), so re-running the autopsy on every tick +// re-emits the row but the user receives exactly one email. func captureDeploymentAutopsy( ctx context.Context, db *sql.DB, @@ -261,6 +320,7 @@ func captureDeploymentAutopsy( // Write an Unknown autopsy so the api still surfaces the failure field. _ = upsertAutopsyRow(ctx, db, deploymentID, workerFailureReasonUnknown, sql.NullInt32{}, "provider_id did not match app- shape", nil) + metrics.DeployAutopsyCapturedTotal.WithLabelValues(autopsyOutcomeLogsUnavailable).Inc() return } @@ -275,6 +335,11 @@ func captureDeploymentAutopsy( result.hint = workerHintForReason(result.reason) + // PR 2 — fail-soft: was the row already populated with a real reason + // from a prior autopsy? Used to label the metric "already_present" so + // operators can distinguish first-capture from idempotent re-capture. + preexisting := autopsyAlreadyPresentWithReason(ctx, db, deploymentID) + if err := upsertAutopsyRow(ctx, db, deploymentID, result.reason, result.exitCode, result.event, result.lastLines); err != nil { slog.Warn("jobs.deploy_failure_autopsy.upsert_failed", "deployment_id", deploymentID, @@ -282,13 +347,58 @@ func captureDeploymentAutopsy( "reason", result.reason, "error", err, ) - } else { - slog.Info("jobs.deploy_failure_autopsy.captured", + // Emit the metric even on failure so the operator sees a non-zero + // "logs_unavailable" rate when the DB is brown — pair with NR + // alert on Postgres pool saturation. + metrics.DeployAutopsyCapturedTotal.WithLabelValues(autopsyOutcomeLogsUnavailable).Inc() + return + } + + // PR 2 enhancement (rule 25 metric outcome label): + outcome := autopsyOutcomeLogsCaptured + if len(result.lastLines) == 0 { + outcome = autopsyOutcomeLogsUnavailable + } + if preexisting && result.reason == workerFailureReasonUnknown { + // Idempotent re-capture — the existing row had a real reason and + // this tick added nothing new. Keep the dashboard signal honest. + outcome = autopsyOutcomeAlreadyPresent + } + metrics.DeployAutopsyCapturedTotal.WithLabelValues(outcome).Inc() + + // PR 2: update deployments.error_message with ": " so the + // api's row-only readers (CLI, dashboard list view) see a one-liner + // cause without having to pull the deployment_events row. + if err := updateDeploymentErrorMessage(ctx, db, deploymentID, result.reason, result.hint); err != nil { + slog.Warn("jobs.deploy_failure_autopsy.error_message_update_failed", + "deployment_id", deploymentID, + "reason", result.reason, + "error", err, + ) + } + + // PR 2: emit audit_log kind='deploy.failed' so event_email_forwarder + // dispatches the user-visible failure email. The api's runDeploy + // normally emits this; the worker is the backstop for the + // goroutine-crashed-mid-build case (which IS the 2026-05-30 incident). + if err := emitDeployFailedAudit(ctx, db, deploymentID, result.reason, result.event); err != nil { + // audit-emit failure is fail-soft — surfaces in the + // instant_worker_fail_open_total counter but doesn't block the + // rest of the sweep. + slog.Warn("jobs.deploy_failure_autopsy.audit_emit_failed", "deployment_id", deploymentID, - "provider_id", providerID, "reason", result.reason, + "error", err, ) } + + slog.Info("jobs.deploy_failure_autopsy.captured", + "deployment_id", deploymentID, + "provider_id", providerID, + "reason", result.reason, + "outcome", outcome, + "lines_captured", len(result.lastLines), + ) } // collectAutopsyFromK8s gathers pod lastState, namespace events, and log tail @@ -362,9 +472,204 @@ func collectAutopsyFromK8s( } } + // PR 2: fall back to the BUILD pod's logs when the runtime app pod yielded + // no log lines. The build pod runs as part of the kaniko Job + // (label "job-name=build-") and is the typical source of failure + // when the autopsy is triggered by a Job-failed state (PR 1) — the + // runtime Deployment was never created so an app-pod log fetch returns + // nothing useful. This call is best-effort; on success the kaniko + // stderr tail surfaces the actual Dockerfile error in the api response. + if len(result.lastLines) == 0 { + buildPodName := findBuildPodName(ctx, k8s, ns, appID) + if buildPodName != "" { + buildLogCtx, cancel := context.WithTimeout(ctx, 10*time.Second) + defer cancel() + lines, err := k8s.GetPodLogs(buildLogCtx, ns, buildPodName, maxAutopsyLogLines) + if err != nil { + slog.Warn("jobs.deploy_failure_autopsy.get_build_logs_failed", + "namespace", ns, "pod", buildPodName, "error", err) + } + if len(lines) > 0 { + result.lastLines = lines + if result.reason == workerFailureReasonUnknown { + // We have logs from a build pod — classify as BuildFailed + // unless something more specific was already set from + // pod-status or event extraction. + result.reason = workerFailureReasonBuildFailed + } + } + } + } + return result } +// findBuildPodName lists pods in the deploy namespace matching the kaniko +// Job's pod label (`job-name=build-`) and returns the first pod name, +// or "" when no build pod is reachable (already GC'd past +// TTLSecondsAfterFinished, or never created). Fail-soft: errors are logged +// and treated as "no pod found". +func findBuildPodName(ctx context.Context, k8s deployAutopsyK8sProvider, ns, appID string) string { + listCtx, cancel := context.WithTimeout(ctx, k8sGetTimeout) + defer cancel() + selector := labelBuildJobName + "=" + buildJobNamePrefix + appID + podList, err := k8s.ListPods(listCtx, ns, selector) + if err != nil && !apierrors.IsNotFound(err) { + slog.Warn("jobs.deploy_failure_autopsy.list_build_pods_failed", + "namespace", ns, "selector", selector, "error", err) + return "" + } + if podList == nil || len(podList.Items) == 0 { + return "" + } + return podList.Items[0].Name +} + +// buildJobNamePrefix mirrors api/internal/providers/compute/k8s/client.go's +// build Job naming convention: jobName = "build-" + sanitizeName(appID). Kept +// duplicated (no shared import — same pattern the rest of this file uses). +const buildJobNamePrefix = "build-" + +// updateDeploymentErrorMessage stamps the deployments.error_message column +// with a ": " one-liner so row-only readers see a +// human-readable cause without having to pull deployment_events. +// +// The snippet is the first sentence of the hint (up to the first period or +// 200 chars), keeping the column under the historical 2KB cap the api uses. +// We deliberately DO NOT clear a pre-existing error_message that doesn't +// match this format — the api may have already stamped a more specific +// build error (e.g. the kaniko stderr) and we should not clobber it. The +// UPDATE only runs when error_message IS NULL or empty. +func updateDeploymentErrorMessage(ctx context.Context, db *sql.DB, id uuid.UUID, reason, hint string) error { + if reason == "" { + reason = workerFailureReasonUnknown + } + snippet := firstSentence(hint, 200) + combined := reason + if snippet != "" { + combined = reason + ": " + snippet + } + _, err := db.ExecContext(ctx, ` + UPDATE deployments + SET error_message = $1 + WHERE id = $2 + AND (error_message IS NULL OR error_message = '') + `, combined, id) + if err != nil { + return fmt.Errorf("updateDeploymentErrorMessage: %w", err) + } + return nil +} + +// firstSentence returns the leading portion of s up to the first period +// (inclusive) or up to maxLen chars, whichever is shorter. Used to derive +// a one-line snippet from the multi-sentence hint strings. +func firstSentence(s string, maxLen int) string { + if s == "" { + return "" + } + if i := strings.Index(s, "."); i >= 0 && i+1 <= maxLen { + return s[:i+1] + } + if len(s) > maxLen { + return s[:maxLen] + } + return s +} + +// emitDeployFailedAudit inserts an audit_log row with kind='deploy.failed' +// so event_email_forwarder dispatches the user-visible failure email. The +// api's runDeploy normally emits this synchronously; the worker is the +// backstop for the case where the api goroutine crashed mid-build and +// never wrote the row (the 2026-05-30 silent-deploy-failure incident). +// +// team_id is required by the schema (NOT NULL). We resolve it by joining +// deployments → teams; on a missing deploy row (already deleted), the +// helper logs and returns nil — no audit emit possible without a team_id. +// +// Metadata mirrors the api's emitDeployAudit shape: +// +// { +// "deploy_id": "", +// "team_id": "", +// "failure_stage": "build", +// "error_summary": ": ", +// "source": "worker_autopsy" +// } +// +// The `source` field distinguishes the worker-emitted backstop from the +// api's synchronous emit so an operator triaging duplicate failure emails +// can see which path fired. +func emitDeployFailedAudit(ctx context.Context, db *sql.DB, deploymentID uuid.UUID, reason, event string) error { + var teamID uuid.UUID + err := db.QueryRowContext(ctx, ` + SELECT team_id FROM deployments WHERE id = $1 + `, deploymentID).Scan(&teamID) + if err != nil { + if errors.Is(err, sql.ErrNoRows) { + // Row was already deleted between the autopsy capture and now. + // Nothing to email — silently skip. + return nil + } + return fmt.Errorf("emitDeployFailedAudit: lookup team_id: %w", err) + } + if teamID == uuid.Nil { + // Deployment without a team_id should be impossible (schema NOT NULL) + // but defend anyway — audit_log INSERT would itself fail. + return nil + } + const maxErrorSummary = 256 + summary := reason + if event != "" { + summary = reason + ": " + event + } + if len(summary) > maxErrorSummary { + summary = summary[:maxErrorSummary] + } + meta := map[string]any{ + "deploy_id": deploymentID.String(), + "team_id": teamID.String(), + "failure_stage": "build", + "error_summary": summary, + "source": "worker_autopsy", + } + metaBytes, mErr := json.Marshal(meta) + if mErr != nil { + return fmt.Errorf("emitDeployFailedAudit: marshal metadata: %w", mErr) + } + if _, err := db.ExecContext(ctx, ` + INSERT INTO audit_log (team_id, actor, kind, summary, metadata) + VALUES ($1, $2, $3, $4, $5) + `, teamID, "worker.deploy_failure_autopsy", auditKindDeployFailed, summary, metaBytes); err != nil { + return fmt.Errorf("emitDeployFailedAudit: insert: %w", err) + } + return nil +} + +// (auditKindDeployFailed is declared in deploy_notify_webhook.go — re-used +// here to keep a single source of truth for the kind string. Changes to +// the kind value should land in that file.) + +// autopsyAlreadyPresentWithReason returns true when the deployment_events +// row for this deployment already has a real (non-Unknown) reason captured. +// Used to label the metric outcome as "already_present" when an autopsy +// re-runs on the same row without adding new information. +// +// Fail-open: any error (including ErrNoRows) returns false so the metric +// labels the run as a real capture. The label-correctness is a +// dashboard-quality concern, not a safety concern. +func autopsyAlreadyPresentWithReason(ctx context.Context, db *sql.DB, deploymentID uuid.UUID) bool { + var reason string + err := db.QueryRowContext(ctx, ` + SELECT reason FROM deployment_events + WHERE deployment_id = $1 AND kind = $2 + `, deploymentID, deploymentEventKindFailureAutopsy).Scan(&reason) + if err != nil { + return false + } + return reason != "" && reason != workerFailureReasonUnknown +} + // extractPodFailure reads the container status of a pod and populates reason // and exit code in the result. Checks waiting.reason first (ImagePullBackOff, // CrashLoopBackOff), then terminated.reason (OOMKilled, Error). diff --git a/internal/jobs/deploy_failure_autopsy_log_capture_test.go b/internal/jobs/deploy_failure_autopsy_log_capture_test.go new file mode 100644 index 0000000..18695be --- /dev/null +++ b/internal/jobs/deploy_failure_autopsy_log_capture_test.go @@ -0,0 +1,591 @@ +package jobs + +// deploy_failure_autopsy_log_capture_test.go — coverage for PR 2 of the +// silent-deploy-failure fix (2026-05-30 incident). +// +// Three behaviours pinned per the brief: +// +// 1. TestAutopsy_PodAlive_CapturesLogs — when the app pod is alive, +// 50 tail lines land in +// deployment_events.last_lines. +// 2. TestAutopsy_PodGCd_FallsBackToJobEvent — when the app pod is gone, +// the reason / event are +// derived from the namespace +// events list and the +// last_lines stays empty. +// 3. TestAutopsy_Idempotent — running the autopsy twice +// for the same deployment +// returns nil at the DB layer +// (the unique constraint + +// ON CONFLICT DO UPDATE keeps +// exactly one row). +// +// Plus coverage for the PR 2 surface: build-pod log fallback, error_message +// stamping, audit_log emit, and the outcome metric. + +import ( + "context" + "database/sql" + "errors" + "strings" + "testing" + + sqlmock "github.com/DATA-DOG/go-sqlmock" + "github.com/google/uuid" + corev1 "k8s.io/api/core/v1" + metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" +) + +// ── fake autopsy k8s helpers ─────────────────────────────────────────────────── + +// fakeAutopsyK8sPR2 returns canned data per call type. Each helper closure +// receives the namespace + (for ListPods) label selector so a single fake +// can answer both the app-pod and build-pod queries differently. +type fakeAutopsyK8sPR2 struct { + listPodsFn func(ns, sel string) (*corev1.PodList, error) + listEvFn func(ns string) (*corev1.EventList, error) + getLogsFn func(ns, pod string, tail int64) ([]string, error) + logsCallLog []string +} + +func (f *fakeAutopsyK8sPR2) ListPods(_ context.Context, ns, sel string) (*corev1.PodList, error) { + if f.listPodsFn == nil { + return &corev1.PodList{}, nil + } + return f.listPodsFn(ns, sel) +} + +func (f *fakeAutopsyK8sPR2) ListEvents(_ context.Context, ns string) (*corev1.EventList, error) { + if f.listEvFn == nil { + return &corev1.EventList{}, nil + } + return f.listEvFn(ns) +} + +func (f *fakeAutopsyK8sPR2) GetPodLogs(_ context.Context, ns, pod string, tail int64) ([]string, error) { + f.logsCallLog = append(f.logsCallLog, pod) + if f.getLogsFn == nil { + return nil, nil + } + return f.getLogsFn(ns, pod, tail) +} + +var _ deployAutopsyK8sProvider = (*fakeAutopsyK8sPR2)(nil) + +// TestAutopsy_PodAlive_CapturesLogs is brief-test #1. +func TestAutopsy_PodAlive_CapturesLogs(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + // Build a tail of 50 log lines for the assertion target. + tail := make([]string, 50) + for i := range tail { + tail[i] = "FATAL line " + uuid.NewString()[:4] + } + + k8s := &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { + // The autopsy first queries the APP pod (label instant-app-id=). + // The build-pod fallback uses label job-name=. Distinguish by + // substring — we want the app-pod path to succeed so the build + // fallback never runs. + if strings.Contains(sel, labelInstantAppID) { + return &corev1.PodList{ + Items: []corev1.Pod{*buildPodWithTerminated("OOMKilled", 137)}, + }, nil + } + return &corev1.PodList{}, nil + }, + listEvFn: func(ns string) (*corev1.EventList, error) { return &corev1.EventList{}, nil }, + getLogsFn: func(ns, pod string, tailLines int64) ([]string, error) { + return tail, nil + }, + } + + id := uuid.New() + teamID := uuid.New() + + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) + mock.ExpectExec(`INSERT INTO deployment_events`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(teamID)) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + captureDeploymentAutopsy(context.Background(), db, id, "app-alive", k8s) + + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } + // Build-pod fallback MUST NOT fire when the app-pod path already captured + // logs — the logsCallLog should contain exactly one pod (the app pod). + if len(k8s.logsCallLog) != 1 { + t.Errorf("expected GetPodLogs called once (app pod only); got %d calls: %v", + len(k8s.logsCallLog), k8s.logsCallLog) + } +} + +// TestAutopsy_PodGCd_FallsBackToJobEvent is brief-test #2: app pod is GC'd, +// build pod is GC'd, but namespace events still contain a FailedToPull / +// OOMKilling message. The autopsy MUST populate reason + event from the +// event message and leave last_lines empty. +func TestAutopsy_PodGCd_FallsBackToJobEvent(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + k8s := &fakeAutopsyK8sPR2{ + // Both ListPods queries return empty (both pods GC'd). + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { + return &corev1.PodList{}, nil + }, + // Namespace event surfaces the OOMKilling reason after the pod is gone. + listEvFn: func(ns string) (*corev1.EventList, error) { + return &corev1.EventList{ + Items: []corev1.Event{{ + ObjectMeta: metav1.ObjectMeta{Name: "ev-1"}, + Type: corev1.EventTypeWarning, + Reason: "OOMKilling", + Message: "Memory cgroup out of memory: Killed process 1", + }}, + }, nil + }, + // GetPodLogs should never be called (no pod name) — guarded below. + getLogsFn: func(ns, pod string, tail int64) ([]string, error) { + t.Fatalf("GetPodLogs should not be called when pods are GC'd") + return nil, nil + }, + } + + id := uuid.New() + teamID := uuid.New() + + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) + mock.ExpectExec(`INSERT INTO deployment_events`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(teamID)) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + captureDeploymentAutopsy(context.Background(), db, id, "app-gced", k8s) + + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} + +// TestAutopsy_Idempotent is brief-test #3. Run captureDeploymentAutopsy +// twice for the same deployment. The deployment_events ON CONFLICT DO UPDATE +// clause makes the second insert a no-op-equivalent (sqlmock fires both INSERT +// statements; in real Postgres they both produce 1 affected row but only one +// physical row exists). After the second run, the autopsy's already_present +// detector returns true and outcome flips to "already_present" — which is +// what we assert via the logsCallLog (no second log-tail call should be +// needed because the metric path doesn't re-fetch). +func TestAutopsy_Idempotent(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + k8s := &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { + if strings.Contains(sel, labelInstantAppID) { + return &corev1.PodList{ + Items: []corev1.Pod{*buildPodWithWaiting("CrashLoopBackOff", "boom")}, + }, nil + } + return &corev1.PodList{}, nil + }, + listEvFn: func(ns string) (*corev1.EventList, error) { return &corev1.EventList{}, nil }, + getLogsFn: func(ns, pod string, tail int64) ([]string, error) { return []string{"line"}, nil }, + } + + id := uuid.New() + teamID := uuid.New() + provID := "app-idem" + + // First call: full flow, real capture. + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) + mock.ExpectExec(`INSERT INTO deployment_events`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(teamID)) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + // Second call: already_present pre-check returns CrashLoopBackOff (real reason), + // upsert still fires (idempotent ON CONFLICT), then error_message + audit_log emit. + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnRows(sqlmock.NewRows([]string{"reason"}).AddRow(workerFailureReasonCrashLoopBackOff)) + mock.ExpectExec(`INSERT INTO deployment_events`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(teamID)) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + captureDeploymentAutopsy(context.Background(), db, id, provID, k8s) + captureDeploymentAutopsy(context.Background(), db, id, provID, k8s) + + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} + +// TestAutopsy_BuildPodFallback exercises the new code path: app pod has no +// logs, build pod is reachable. The autopsy MUST query GetPodLogs twice +// (once for the app pod, once for the build pod) and the build-pod logs +// land in last_lines + the reason is upgraded from Unknown to BuildFailed. +func TestAutopsy_BuildPodFallback(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + k8s := &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { + switch { + case strings.Contains(sel, labelInstantAppID): + // App pod present but produces no logs (image-pull stage). + return &corev1.PodList{ + Items: []corev1.Pod{*buildPodWithWaiting("ImagePullBackOff", "")}, + }, nil + case strings.Contains(sel, labelBuildJobName): + // Build pod alive — provides the kaniko stderr tail. + return &corev1.PodList{ + Items: []corev1.Pod{{ + ObjectMeta: metav1.ObjectMeta{Name: "build-x-pod"}, + }}, + }, nil + } + return &corev1.PodList{}, nil + }, + listEvFn: func(ns string) (*corev1.EventList, error) { return &corev1.EventList{}, nil }, + getLogsFn: func(ns, pod string, tail int64) ([]string, error) { + if strings.HasPrefix(pod, "build-") { + return []string{"kaniko: COPY failed", "kaniko: stage 1 errored"}, nil + } + // App pod returns nothing — triggers fallback. + return nil, nil + }, + } + + id := uuid.New() + teamID := uuid.New() + + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) + mock.ExpectExec(`INSERT INTO deployment_events`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(teamID)) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + captureDeploymentAutopsy(context.Background(), db, id, "app-x", k8s) + + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } + // Both pods should have been log-fetched. + if len(k8s.logsCallLog) != 2 { + t.Errorf("expected 2 GetPodLogs calls (app pod + build pod fallback); got %d: %v", + len(k8s.logsCallLog), k8s.logsCallLog) + } +} + +// TestUpdateDeploymentErrorMessage_OnlyUpdatesEmptyColumn pins the +// non-clobber guard: error_message is only stamped when NULL or empty. +func TestUpdateDeploymentErrorMessage_OnlyUpdatesEmptyColumn(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + // Expect the UPDATE to carry the WHERE error_message IS NULL OR ='' guard. + mock.ExpectExec(`UPDATE deployments\s+SET error_message = \$1\s+WHERE id = \$2\s+AND \(error_message IS NULL OR error_message = ''\)`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + if err := updateDeploymentErrorMessage(context.Background(), db, uuid.New(), + workerFailureReasonOOMKilled, + workerFailureHint[workerFailureReasonOOMKilled], + ); err != nil { + t.Fatalf("updateDeploymentErrorMessage: %v", err) + } + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} + +// TestUpdateDeploymentErrorMessage_DBError surfaces the error path. +func TestUpdateDeploymentErrorMessage_DBError(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnError(errors.New("brownout")) + + if err := updateDeploymentErrorMessage(context.Background(), db, uuid.New(), + "Reason", "hint"); err == nil { + t.Fatal("expected error from DB") + } +} + +// TestFirstSentence pins the snippet helper. +func TestFirstSentence(t *testing.T) { + cases := []struct { + in string + maxLen int + want string + }{ + {"", 50, ""}, + {"no period text", 50, "no period text"}, + {"first sentence. second sentence.", 50, "first sentence."}, + {"period beyond maxlen no truncation", 5, "perio"}, + {"short.", 50, "short."}, + } + for _, tc := range cases { + if got := firstSentence(tc.in, tc.maxLen); got != tc.want { + t.Errorf("firstSentence(%q, %d) = %q, want %q", tc.in, tc.maxLen, got, tc.want) + } + } +} + +// TestEmitDeployFailedAudit_NoRow returns nil silently when the deployment +// row was already deleted between capture and audit-emit. +func TestEmitDeployFailedAudit_NoRow(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnError(sql.ErrNoRows) + + if err := emitDeployFailedAudit(context.Background(), db, uuid.New(), "OOMKilled", "msg"); err != nil { + t.Errorf("expected nil on ErrNoRows, got %v", err) + } + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} + +// TestEmitDeployFailedAudit_LookupError surfaces non-ErrNoRows errors. +func TestEmitDeployFailedAudit_LookupError(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnError(errors.New("brownout")) + + if err := emitDeployFailedAudit(context.Background(), db, uuid.New(), "OOMKilled", "msg"); err == nil { + t.Fatal("expected wrapped error on lookup failure") + } +} + +// TestEmitDeployFailedAudit_NilTeamID returns nil silently when team_id +// is the zero UUID (defensive — the schema NOT NULL should make this +// impossible, but the guard prevents an audit_log INSERT failure). +func TestEmitDeployFailedAudit_NilTeamID(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(uuid.Nil)) + + if err := emitDeployFailedAudit(context.Background(), db, uuid.New(), "OOMKilled", "msg"); err != nil { + t.Errorf("expected nil on Nil team_id, got %v", err) + } +} + +// TestEmitDeployFailedAudit_InsertError surfaces the INSERT failure path. +func TestEmitDeployFailedAudit_InsertError(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(uuid.New())) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnError(errors.New("audit table missing")) + + if err := emitDeployFailedAudit(context.Background(), db, uuid.New(), "OOMKilled", "msg"); err == nil { + t.Fatal("expected wrapped insert error") + } +} + +// TestEmitDeployFailedAudit_SummaryTruncation guards the 256-char cap on the +// summary string. +func TestEmitDeployFailedAudit_SummaryTruncation(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + longEvent := strings.Repeat("x", 1024) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(uuid.New())) + mock.ExpectExec(`INSERT INTO audit_log`). + WithArgs( + sqlmock.AnyArg(), // team_id + sqlmock.AnyArg(), // actor + "deploy.failed", + // summary length is capped — match the truncated form. + sqlmock.AnyArg(), + sqlmock.AnyArg(), // metadata json + ). + WillReturnResult(sqlmock.NewResult(0, 1)) + + if err := emitDeployFailedAudit(context.Background(), db, uuid.New(), "OOMKilled", longEvent); err != nil { + t.Fatalf("emitDeployFailedAudit: %v", err) + } +} + +// TestAutopsyAlreadyPresentWithReason covers the three branches: ErrNoRows +// (fresh), empty/Unknown reason (treated as fresh), and a real reason (true). +func TestAutopsyAlreadyPresentWithReason(t *testing.T) { + cases := []struct { + name string + setup func(mock sqlmock.Sqlmock) + want bool + }{ + { + name: "ErrNoRows", + setup: func(m sqlmock.Sqlmock) { + m.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) + }, + want: false, + }, + { + name: "Unknown reason still counts as not present", + setup: func(m sqlmock.Sqlmock) { + m.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnRows(sqlmock.NewRows([]string{"reason"}).AddRow(workerFailureReasonUnknown)) + }, + want: false, + }, + { + name: "Real reason is present", + setup: func(m sqlmock.Sqlmock) { + m.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnRows(sqlmock.NewRows([]string{"reason"}).AddRow(workerFailureReasonOOMKilled)) + }, + want: true, + }, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + tc.setup(mock) + got := autopsyAlreadyPresentWithReason(context.Background(), db, uuid.New()) + if got != tc.want { + t.Errorf("autopsyAlreadyPresentWithReason = %v, want %v", got, tc.want) + } + }) + } +} + +// TestFindBuildPodName covers the three branches: ListPods error (returns ""), +// empty list (""), and a populated list (returns first pod name). +func TestFindBuildPodName(t *testing.T) { + cases := []struct { + name string + k8s *fakeAutopsyK8sPR2 + want string + }{ + { + name: "ListPods error returns empty", + k8s: &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { + return nil, errors.New("brownout") + }, + }, + want: "", + }, + { + name: "empty list returns empty", + k8s: &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { + return &corev1.PodList{}, nil + }, + }, + want: "", + }, + { + name: "first pod name returned", + k8s: &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { + return &corev1.PodList{Items: []corev1.Pod{ + {ObjectMeta: metav1.ObjectMeta{Name: "build-foo-xyz"}}, + }}, nil + }, + }, + want: "build-foo-xyz", + }, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + got := findBuildPodName(context.Background(), tc.k8s, "instant-deploy-x", "x") + if got != tc.want { + t.Errorf("findBuildPodName = %q, want %q", got, tc.want) + } + }) + } +} + +// TestAutopsy_NamespaceMismatch_EarlyReturn covers the early-return path where +// providerID doesn't match the app- shape. The autopsy writes an +// Unknown row and increments the logs_unavailable counter. +func TestAutopsy_NamespaceMismatch_EarlyReturn(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + mock.ExpectExec(`INSERT INTO deployment_events`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + captureDeploymentAutopsy(context.Background(), db, uuid.New(), + "instant-stack-zzz", &fakeAutopsyK8sPR2{}) + + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} diff --git a/internal/jobs/deploy_failure_autopsy_test.go b/internal/jobs/deploy_failure_autopsy_test.go index 3d28c78..9fc39ae 100644 --- a/internal/jobs/deploy_failure_autopsy_test.go +++ b/internal/jobs/deploy_failure_autopsy_test.go @@ -254,9 +254,11 @@ func TestUpsertAutopsyRow_Idempotent(t *testing.T) { // ── captureDeploymentAutopsy integration-style tests ───────────────────────── // TestCaptureDeploymentAutopsy_NilK8s verifies that when the autopsy k8s -// client is nil, captureDeploymentAutopsy still writes an Unknown-reason row. +// client is nil, captureDeploymentAutopsy still writes an Unknown-reason +// autopsy row, attempts the PR 2 already_present check, error_message update, +// and audit_log emit (all fail-soft when sqlmock doesn't expect them). func TestCaptureDeploymentAutopsy_NilK8s(t *testing.T) { - db, mock, err := sqlmock.New() + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) if err != nil { t.Fatalf("sqlmock.New: %v", err) } @@ -265,9 +267,20 @@ func TestCaptureDeploymentAutopsy_NilK8s(t *testing.T) { id := uuid.New() providerID := "app-abc123" - // Expect one upsert with reason=Unknown. + // PR 2 pre-check: already_present query (returns no row → fresh capture). + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) + // Autopsy row upsert. mock.ExpectExec(`INSERT INTO deployment_events`). WillReturnResult(sqlmock.NewResult(0, 1)) + // PR 2 error_message update (only runs when error_message IS NULL or ''). + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + // PR 2 audit emit: team_id lookup + INSERT INTO audit_log. + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(uuid.New())) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) captureDeploymentAutopsy(context.Background(), db, id, providerID, nil) @@ -278,7 +291,7 @@ func TestCaptureDeploymentAutopsy_NilK8s(t *testing.T) { // TestCaptureDeploymentAutopsy_FullCapture verifies that a stubbed k8s // provider with an OOMKilled pod produces an OOMKilled reason in the -// upserted autopsy row. +// upserted autopsy row + the PR 2 error_message UPDATE + audit_log emit. func TestCaptureDeploymentAutopsy_FullCapture(t *testing.T) { db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) if err != nil { @@ -300,16 +313,22 @@ func TestCaptureDeploymentAutopsy_FullCapture(t *testing.T) { logs: nil, } - // Expect an upsert; we inspect the args to confirm OOMKilled is the reason. + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) mock.ExpectExec(`INSERT INTO deployment_events`). WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(uuid.New())) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) captureDeploymentAutopsy(context.Background(), db, id, providerID, stub) if err := mock.ExpectationsWereMet(); err != nil { t.Errorf("unmet sqlmock expectations: %v", err) } - // Verify stub was called (all three methods). if !stub.listPodsCalled { t.Error("expected ListPods to be called") } diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index f45dcfa..3d3a228 100644 --- a/internal/metrics/metrics.go +++ b/internal/metrics/metrics.go @@ -574,6 +574,46 @@ var ( Help: "Kaniko build Jobs detected in Failed state by deploy_status_reconcile (silent-deploy-failure fix, 2026-05-30). Labelled by Job Failed-condition reason.", }, []string{"reason"}) + // ── deploy_failure_autopsy — capture outcome counter (PR 2, 2026-05-30) ── + // + // Increments once per captureDeploymentAutopsy call, labelled by outcome. + // Outcomes: + // + // logs_captured — at least one log line was captured from the app + // pod OR the build pod fallback (the modal success + // path for the silent-deploy-failure fix). + // logs_unavailable — autopsy ran but no log lines could be captured + // (pod already GC'd, image-pull failure, or DB + // write failed). Reason + event fields are still + // populated from k8s state + Job event fallback. + // already_present — pure idempotent re-capture: the deployment_events + // row already had a real (non-Unknown) reason and + // this tick added nothing new. Distinguishes + // "doing useful work" from "looping over old state". + // audit_emit_failed — autopsy row upsert succeeded but the audit_log + // emit (kind=deploy.failed → email forwarder) + // failed. A non-zero rate means failure emails + // are silently dropped. + // + // NR alert (suggested): + // sum(rate(instant_deploy_autopsy_captured_total{outcome="logs_unavailable"}[15m])) > 1 + // for 30+ minutes → P2 page. A sustained rate means autopsies are + // consistently running too late (pods GC'd before capture). Action: + // check if the Job's TTLSecondsAfterFinished was reduced or if the + // reconciler tick interval drifted up. + // sum(rate(instant_deploy_autopsy_captured_total{outcome="audit_emit_failed"}[5m])) > 0 + // → P1 page. Customers are not getting deploy.failed emails for at + // least one tenant; check platform-DB pool saturation. + // + // Catalog row (infra/observability/METRICS-CATALOG.md): + // instant_deploy_autopsy_captured_total | counter | outcome | lazy + // (label families primed in metrics_test.go so /metrics exposes the + // four outcomes from process start). + DeployAutopsyCapturedTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "instant_deploy_autopsy_captured_total", + Help: "deploy_failure_autopsy capture outcomes (PR 2, silent-deploy-failure fix). Labelled by outcome (logs_captured | logs_unavailable | already_present | audit_emit_failed).", + }, []string{"outcome"}) + // ── orphan_sweep_reconciler — reap counters (2026-05-20) ────────────────── // // Every namespace / DB row the orphan-sweep reconciler reaps (or flips to diff --git a/internal/metrics/metrics_test.go b/internal/metrics/metrics_test.go index 0e8c5f2..c3afae3 100644 --- a/internal/metrics/metrics_test.go +++ b/internal/metrics/metrics_test.go @@ -95,6 +95,13 @@ func TestAllMetrics_AreRegistered(t *testing.T) { OrphanSweepReapedTotal.WithLabelValues("team_tombstoned").Add(0) OrphanSweepReapFailedTotal.WithLabelValues("team_tombstoned").Add(0) DeployJobFailedDetectedTotal.WithLabelValues("BackoffLimitExceeded").Add(0) + // Prime all four DeployAutopsyCapturedTotal outcome label values so + // /metrics exposes them from process start (lazy emit otherwise leaves + // the panel empty until the first real autopsy fires). + DeployAutopsyCapturedTotal.WithLabelValues("logs_captured").Add(0) + DeployAutopsyCapturedTotal.WithLabelValues("logs_unavailable").Add(0) + DeployAutopsyCapturedTotal.WithLabelValues("already_present").Add(0) + DeployAutopsyCapturedTotal.WithLabelValues("audit_emit_failed").Add(0) // Gauge vecs ResourceDegradedGauge.WithLabelValues("postgres").Set(0) From 56b61747001b6088143e5c592aa451e548d89808 Mon Sep 17 00:00:00 2001 From: Manas Srivastava Date: Sat, 30 May 2026 16:43:40 +0530 Subject: [PATCH 2/3] fix(autopsy): tighten coverage + use audit_emit_failed metric label MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CI feedback on the parent commit: - lint: const autopsyOutcomeAuditEmitFailed was unused. It is now emitted from the audit-emit error path (paired with the existing WARN log), which is what the constant always documented but the caller didn't actually invoke. - coverage: patch coverage gate (100%) flagged four uncovered branches in deploy_failure_autopsy.go. Each now has a dedicated test: * already_present outcome path → TestAutopsy_IdempotentAlreadyPresentBranch * build-pod fallback reason upgrade Unknown→BuildFailed → TestAutopsy_BuildPodFallback_UpgradesUnknownToBuildFailed * updateDeploymentErrorMessage empty-reason fallback → TestUpdateDeploymentErrorMessage_EmptyReasonFallsBackToUnknown * audit-emit failure metric increment → TestAutopsy_AuditEmitFailed_IncrementsCounter json.Marshal of a map[string]any error path (unreachable for this shape) was simplified to mirror the orphan_sweep_reconciler's emitOrphanAudit pattern (_-ignore). Local diff-cover against origin/master now reports 100% patch coverage on internal/jobs/deploy_failure_autopsy.go. Co-Authored-By: Claude Opus 4.7 (1M context) --- internal/jobs/deploy_failure_autopsy.go | 15 +- ...deploy_failure_autopsy_log_capture_test.go | 166 ++++++++++++++++++ 2 files changed, 174 insertions(+), 7 deletions(-) diff --git a/internal/jobs/deploy_failure_autopsy.go b/internal/jobs/deploy_failure_autopsy.go index ef3f3aa..7b11281 100644 --- a/internal/jobs/deploy_failure_autopsy.go +++ b/internal/jobs/deploy_failure_autopsy.go @@ -382,9 +382,10 @@ func captureDeploymentAutopsy( // normally emits this; the worker is the backstop for the // goroutine-crashed-mid-build case (which IS the 2026-05-30 incident). if err := emitDeployFailedAudit(ctx, db, deploymentID, result.reason, result.event); err != nil { - // audit-emit failure is fail-soft — surfaces in the - // instant_worker_fail_open_total counter but doesn't block the - // rest of the sweep. + // audit-emit failure is fail-soft — increment the audit_emit_failed + // outcome counter so the operator sees missing failure emails on the + // dashboard, and keep the rest of the sweep alive. + metrics.DeployAutopsyCapturedTotal.WithLabelValues(autopsyOutcomeAuditEmitFailed).Inc() slog.Warn("jobs.deploy_failure_autopsy.audit_emit_failed", "deployment_id", deploymentID, "reason", result.reason, @@ -633,10 +634,10 @@ func emitDeployFailedAudit(ctx context.Context, db *sql.DB, deploymentID uuid.UU "error_summary": summary, "source": "worker_autopsy", } - metaBytes, mErr := json.Marshal(meta) - if mErr != nil { - return fmt.Errorf("emitDeployFailedAudit: marshal metadata: %w", mErr) - } + // json.Marshal of a map[string]any with string keys + string values is + // total — unreachable error path. The orphan-sweep audit emit follows + // the same _-ignore pattern (orphan_sweep_reconciler.go:emitOrphanAudit). + metaBytes, _ := json.Marshal(meta) if _, err := db.ExecContext(ctx, ` INSERT INTO audit_log (team_id, actor, kind, summary, metadata) VALUES ($1, $2, $3, $4, $5) diff --git a/internal/jobs/deploy_failure_autopsy_log_capture_test.go b/internal/jobs/deploy_failure_autopsy_log_capture_test.go index 18695be..b9f2905 100644 --- a/internal/jobs/deploy_failure_autopsy_log_capture_test.go +++ b/internal/jobs/deploy_failure_autopsy_log_capture_test.go @@ -589,3 +589,169 @@ func TestAutopsy_NamespaceMismatch_EarlyReturn(t *testing.T) { t.Errorf("unmet expectations: %v", err) } } + +// TestAutopsy_BuildPodFallback_UpgradesUnknownToBuildFailed pins the +// reason-upgrade branch (line 494-499 in deploy_failure_autopsy.go): when the +// app pod has NO useful container state (so extractPodFailure leaves reason +// at Unknown) and the build pod returns logs, the autopsy MUST upgrade +// reason from Unknown to BuildFailed. +func TestAutopsy_BuildPodFallback_UpgradesUnknownToBuildFailed(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + k8s := &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { + switch { + case strings.Contains(sel, labelInstantAppID): + // App pod has NO container statuses — extractPodFailure leaves + // reason at Unknown. + return &corev1.PodList{Items: []corev1.Pod{{ + ObjectMeta: metav1.ObjectMeta{Name: "app-bare"}, + }}}, nil + case strings.Contains(sel, labelBuildJobName): + return &corev1.PodList{Items: []corev1.Pod{{ + ObjectMeta: metav1.ObjectMeta{Name: "build-bare-pod"}, + }}}, nil + } + return &corev1.PodList{}, nil + }, + listEvFn: func(ns string) (*corev1.EventList, error) { return &corev1.EventList{}, nil }, + getLogsFn: func(ns, pod string, tail int64) ([]string, error) { + if strings.HasPrefix(pod, "build-") { + return []string{"kaniko: COPY failed"}, nil + } + return nil, nil // App pod yields nothing. + }, + } + + id := uuid.New() + teamID := uuid.New() + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) + // The upsert is expected to carry reason=BuildFailed. + mock.ExpectExec(`INSERT INTO deployment_events`). + WithArgs( + id, deploymentEventKindFailureAutopsy, + workerFailureReasonBuildFailed, + sqlmock.AnyArg(), sqlmock.AnyArg(), sqlmock.AnyArg(), sqlmock.AnyArg(), + ). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(teamID)) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + captureDeploymentAutopsy(context.Background(), db, id, "app-bare", k8s) + + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} + +// TestAutopsy_IdempotentAlreadyPresentBranch pins the already_present outcome +// (lines 362-366): a re-run where the deployment_events row has a real +// reason AND this tick re-derives Unknown (e.g. pods were reaped between +// ticks) MUST label the metric "already_present" rather than logs_unavailable. +func TestAutopsy_IdempotentAlreadyPresentBranch(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + // k8s state where the autopsy can't derive a real reason this tick + // (no pods at all → reason stays Unknown). + k8s := &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { return &corev1.PodList{}, nil }, + listEvFn: func(ns string) (*corev1.EventList, error) { return &corev1.EventList{}, nil }, + getLogsFn: func(ns, pod string, tail int64) ([]string, error) { return nil, nil }, + } + + id := uuid.New() + teamID := uuid.New() + // Pre-check returns a real reason from a prior tick → preexisting=true. + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnRows(sqlmock.NewRows([]string{"reason"}).AddRow(workerFailureReasonOOMKilled)) + mock.ExpectExec(`INSERT INTO deployment_events`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnRows(sqlmock.NewRows([]string{"team_id"}).AddRow(teamID)) + mock.ExpectExec(`INSERT INTO audit_log`). + WillReturnResult(sqlmock.NewResult(0, 1)) + + captureDeploymentAutopsy(context.Background(), db, id, "app-rerun", k8s) + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} + +// TestUpdateDeploymentErrorMessage_EmptyReasonFallsBackToUnknown pins lines +// 544-546 in updateDeploymentErrorMessage: an empty reason argument is +// rewritten to "Unknown" so the column never holds a bare ": " prefix. +func TestUpdateDeploymentErrorMessage_EmptyReasonFallsBackToUnknown(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + id := uuid.New() + // Assert the stamped string begins with "Unknown: " (the reason fallback fired). + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WithArgs( + // First arg should start with "Unknown: " — sqlmock has no startsWith + // matcher, but the helper string is deterministic when reason=="" + // and hint==workerFailureHint[Unknown], so we match it verbatim. + "Unknown: "+firstSentence(workerFailureHint[workerFailureReasonUnknown], 200), + id, + ). + WillReturnResult(sqlmock.NewResult(0, 1)) + + if err := updateDeploymentErrorMessage(context.Background(), db, id, + "", workerFailureHint[workerFailureReasonUnknown]); err != nil { + t.Fatalf("updateDeploymentErrorMessage: %v", err) + } + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} + +// TestAutopsy_AuditEmitFailed_IncrementsCounter exercises the +// audit_emit_failed outcome path (the lint-fix that's also a real metric): +// when emitDeployFailedAudit returns an error the autopsy still completes +// but the audit_emit_failed counter increments and the warn line fires. +func TestAutopsy_AuditEmitFailed_IncrementsCounter(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherRegexp)) + if err != nil { + t.Fatalf("sqlmock.New: %v", err) + } + defer db.Close() + + id := uuid.New() + k8s := &fakeAutopsyK8sPR2{ + listPodsFn: func(ns, sel string) (*corev1.PodList, error) { return &corev1.PodList{}, nil }, + listEvFn: func(ns string) (*corev1.EventList, error) { return &corev1.EventList{}, nil }, + getLogsFn: func(ns, pod string, tail int64) ([]string, error) { return nil, nil }, + } + mock.ExpectQuery(`SELECT reason FROM deployment_events`). + WillReturnError(sql.ErrNoRows) + mock.ExpectExec(`INSERT INTO deployment_events`). + WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(`UPDATE deployments\s+SET error_message`). + WillReturnResult(sqlmock.NewResult(0, 1)) + // Audit emit fails at the team_id lookup with a non-ErrNoRows error. + mock.ExpectQuery(`SELECT team_id FROM deployments`). + WillReturnError(errors.New("audit lookup brownout")) + + captureDeploymentAutopsy(context.Background(), db, id, "app-audit-fail", k8s) + + if err := mock.ExpectationsWereMet(); err != nil { + t.Errorf("unmet expectations: %v", err) + } +} From 70c2966e298406c86ae0b7ae4e990d3574ddd2c3 Mon Sep 17 00:00:00 2001 From: Manas Srivastava Date: Sat, 30 May 2026 16:57:11 +0530 Subject: [PATCH 3/3] fix: remove duplicate buildJobNamePrefix const (merged via #65) --- internal/jobs/deploy_failure_autopsy.go | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/internal/jobs/deploy_failure_autopsy.go b/internal/jobs/deploy_failure_autopsy.go index 7b11281..f2728b1 100644 --- a/internal/jobs/deploy_failure_autopsy.go +++ b/internal/jobs/deploy_failure_autopsy.go @@ -526,10 +526,9 @@ func findBuildPodName(ctx context.Context, k8s deployAutopsyK8sProvider, ns, app return podList.Items[0].Name } -// buildJobNamePrefix mirrors api/internal/providers/compute/k8s/client.go's -// build Job naming convention: jobName = "build-" + sanitizeName(appID). Kept -// duplicated (no shared import — same pattern the rest of this file uses). -const buildJobNamePrefix = "build-" +// buildJobNamePrefix is declared in deploy_status_reconcile.go (PR #65) as +// `const buildJobNamePrefix = "build-"`. Both files build the kaniko Job +// name the same way: jobName = buildJobNamePrefix + sanitizeName(appID). // updateDeploymentErrorMessage stamps the deployments.error_message column // with a ": " one-liner so row-only readers see a