diff --git a/builder/solver.go b/builder/solver.go index db0a7738d1..3bb3145c69 100644 --- a/builder/solver.go +++ b/builder/solver.go @@ -21,6 +21,7 @@ import ( "github.com/moby/buildkit/util/grpcerrors" "github.com/pkg/errors" "golang.org/x/sync/errgroup" + "google.golang.org/grpc/codes" ) // statusChanSize is used to ensure we consume all BK status messages without @@ -90,15 +91,65 @@ func (s *solver) buildMainMulti( }) err = eg.Wait() + chosen := chooseSolveError(buildErr, err) + if chosen != nil { + return s.withBuildkitFailureContext(chosen) + } + + return nil +} + +// chooseSolveError picks the more informative of the two errgroup results. +// buildErr is from bkClient.Build; monitorErr is from MonitorProgress (which +// also returns errors from earth's own status processing, e.g. NewCommand). +// +// When MonitorProgress aborts the build it cancels the shared errgroup +// context, so bkClient.Build then returns a bare "context canceled" that +// masks the real cause. Prefer a non-cancellation monitorErr in that case — +// otherwise an earth-side self-cancellation is misreported as "BuildKit lost +// the session". +func chooseSolveError(buildErr, monitorErr error) error { + if buildErr != nil && isCanceledErr(buildErr) && monitorErr != nil && !isCanceledErr(monitorErr) { + return errors.Wrap(monitorErr, "earth progress monitor aborted the build") + } + if buildErr != nil { return buildErr } - if err != nil { - return err + return monitorErr +} + +func (s *solver) withBuildkitFailureContext(buildErr error) error { + if !isCanceledErr(buildErr) { + return buildErr } - return nil + if failure, ok := s.logbusSM.FirstFailure(); ok { + return solvermon.NewFirstFailureError(buildErr, failure) + } + + if cancellation, ok := s.logbusSM.FirstCancellation(); ok { + return solvermon.NewFirstCancellationError(buildErr, cancellation) + } + + if details, ok := s.logbusSM.CancellationDetails(); ok { + return solvermon.NewCancellationDetailsError(buildErr, details) + } + + return buildErr +} + +func isCanceledErr(err error) bool { + if errors.Is(err, context.Canceled) { + return true + } + + if grpcErr, ok := grpcerrors.AsGRPCStatus(err); ok && grpcErr.Code() == codes.Canceled { + return true + } + + return false } func (s *solver) newSolveOptMulti( diff --git a/builder/solver_test.go b/builder/solver_test.go new file mode 100644 index 0000000000..bb0598ab81 --- /dev/null +++ b/builder/solver_test.go @@ -0,0 +1,69 @@ +package builder + +import ( + "context" + "testing" + + "github.com/pkg/errors" + "github.com/stretchr/testify/require" +) + +func TestChooseSolveError(t *testing.T) { + t.Parallel() + + const dupMsg = "duplicate command ID" + + realErr := errors.New("failed to create command: " + dupMsg) + canceled := context.Canceled + + tests := map[string]struct { + buildErr error + monitorErr error + wantSubstr string + wantNil bool + }{ + "both nil": { + wantNil: true, + }, + "build error only": { + buildErr: realErr, + wantSubstr: dupMsg, + }, + "monitor error only": { + monitorErr: realErr, + wantSubstr: dupMsg, + }, + "build canceled masks real monitor error": { + // The bug: a real earth-side monitor failure cancels the build, + // and the resulting bare cancellation must not win. + buildErr: canceled, + monitorErr: realErr, + wantSubstr: "earth progress monitor aborted the build", + }, + "both canceled stays canceled": { + buildErr: canceled, + monitorErr: context.Canceled, + wantSubstr: context.Canceled.Error(), + }, + "real build error beats canceled monitor": { + buildErr: realErr, + monitorErr: canceled, + wantSubstr: dupMsg, + }, + } + + for name, tc := range tests { + t.Run(name, func(t *testing.T) { + t.Parallel() + + got := chooseSolveError(tc.buildErr, tc.monitorErr) + if tc.wantNil { + require.NoError(t, got) + return + } + + require.Error(t, got) + require.Contains(t, got.Error(), tc.wantSubstr) + }) + } +} diff --git a/cmd/earthly/app/run.go b/cmd/earthly/app/run.go index 70f9e5b6f2..c2902711c1 100644 --- a/cmd/earthly/app/run.go +++ b/cmd/earthly/app/run.go @@ -14,6 +14,7 @@ import ( "github.com/EarthBuild/earthbuild/cmd/earthly/helper" "github.com/EarthBuild/earthbuild/earthfile2llb" "github.com/EarthBuild/earthbuild/inputgraph" + "github.com/EarthBuild/earthbuild/logbus/solvermon" "github.com/EarthBuild/earthbuild/logstream" "github.com/EarthBuild/earthbuild/util/containerutil" "github.com/EarthBuild/earthbuild/util/errutil" @@ -139,6 +140,34 @@ func (app *EarthApp) run(ctx context.Context, args []string, lastSignal *syncuti return 0 } +// printCancellationOrigin reports which side of the client/daemon boundary a +// canceled solve originated from: if earth's own build context is dead, the +// cancellation began locally and context.Cause names the culprit; if it is +// still alive, the daemon (or the session between them) canceled first. +func (app *EarthApp) printCancellationOrigin(ctx context.Context, lastSignal *syncutil.Signal) { + console := app.BaseCLI.Console() + + if sig := lastSignal.Get(); sig != nil { + console.Warnf("Local cancellation origin: signal %v received by earth\n", sig) + return + } + + if ctx.Err() == nil { + console.Warnf("Local build context is still alive: " + + "the cancellation originated in BuildKit or the session layer, not in earth.\n") + + return + } + + cause := context.Cause(ctx) + if cause != nil && cause.Error() != context.Canceled.Error() { + console.Warnf("Local build context was canceled. Cause: %v\n", cause) + } else { + console.Warnf("Local build context was canceled with no recorded cause: " + + "an earth-side subsystem canceled the build without reporting an error.\n") + } +} + // handleError handles run error, logs it and returns appropriate exit code. func (app *EarthApp) handleError(ctx context.Context, err error, args []string, lastSignal *syncutil.Signal) int { ie, isInterpreterError := earthfile2llb.GetInterpreterError(err) @@ -395,15 +424,89 @@ func (app *EarthApp) handleError(ctx context.Context, err error, args []string, } return 6 + case func() bool { + failureErr, ok := solvermon.AsFirstFailureError(err) + if !ok { + return false + } + + app.BaseCLI.Logbus().Run().SetFatalError( + failureErr.Failure.End, + failureErr.Failure.TargetID, + failureErr.Failure.CommandID, + failureErr.Failure.FailureType, + "", + failureErr.Failure.Error, + ) + app.BaseCLI.Console().Warnf("%s\n", failureErr.Failure.String()) + + return true + }(): + return 1 + case func() bool { + cancelErr, ok := solvermon.AsFirstCancellationError(err) + if !ok { + return false + } + + app.BaseCLI.Logbus().Run().SetEnd(cancelErr.Cancellation.End, logstream.RunStatus_RUN_STATUS_CANCELED) + app.BaseCLI.Console().Warnf( + "BuildKit canceled or lost the solve session while running:\n%s\n"+ + "This usually means the command above was interrupted after an earlier failure, resource event, "+ + "or buildkit/session failure. "+ + "Earth did not receive a more specific root cause from BuildKit.\n", + cancelErr.Cancellation.String(), + ) + app.printCancellationOrigin(ctx, lastSignal) + + return true + }(): + if containerutil.IsLocal(app.BaseCLI.Flags().BuildkitdSettings.BuildkitAddress) && lastSignal.Get() == nil { + app.printCrashLogs(ctx) + } + + return 2 + case func() bool { + detailsErr, ok := solvermon.AsCancellationDetailsError(err) + if !ok { + return false + } + + app.BaseCLI.Logbus().Run().SetEnd(detailsErr.Details.End, logstream.RunStatus_RUN_STATUS_CANCELED) + app.BaseCLI.Console().Warnf( + "BuildKit canceled or lost the solve session.\n%s\n"+ + "Earth did not receive a more specific root cause from BuildKit.\n", + detailsErr.Details.String(), + ) + app.printCancellationOrigin(ctx, lastSignal) + + return true + }(): + if containerutil.IsLocal(app.BaseCLI.Flags().BuildkitdSettings.BuildkitAddress) && lastSignal.Get() == nil { + app.printCrashLogs(ctx) + } + + return 2 case errors.Is(err, context.Canceled), grpcErrOK && grpcErr.Code() == codes.Canceled: app.BaseCLI.Logbus().Run().SetEnd(time.Now(), logstream.RunStatus_RUN_STATUS_CANCELED) - if app.BaseCLI.Flags().Verbose { + showCanceledErr := app.BaseCLI.Flags().Verbose + if grpcErrOK && grpcErr.Message() != "" && grpcErr.Message() != context.Canceled.Error() { + showCanceledErr = true + } + + if !grpcErrOK && err.Error() != context.Canceled.Error() { + showCanceledErr = true + } + + if showCanceledErr { app.BaseCLI.Console().Warnf("Canceled: %v\n", err) } else { app.BaseCLI.Console().Warn("Canceled\n") } + app.printCancellationOrigin(ctx, lastSignal) + if containerutil.IsLocal(app.BaseCLI.Flags().BuildkitdSettings.BuildkitAddress) && lastSignal.Get() == nil { app.printCrashLogs(ctx) } diff --git a/logbus/solvermon/first_failure.go b/logbus/solvermon/first_failure.go new file mode 100644 index 0000000000..a53043812a --- /dev/null +++ b/logbus/solvermon/first_failure.go @@ -0,0 +1,291 @@ +package solvermon + +import ( + "fmt" + "strings" + "time" + + "github.com/EarthBuild/earthbuild/logstream" + "github.com/pkg/errors" +) + +// FirstFailure is the first fatal BuildKit vertex failure observed on the +// status stream. It is kept separately from the final solve error because +// BuildKit may return context canceled after the original failing vertex has +// already been reported. +type FirstFailure struct { + End time.Time + TargetID string + CommandID string + Error string + FailureType logstream.FailureType +} + +const ( + recentOperationLimit = 5 + recentLogLimit = 8 +) + +// OperationSnapshot is a compact, scrubbed BuildKit vertex summary used when +// the solve ends as a bare cancellation. +type OperationSnapshot struct { + OperationStarted time.Time + End time.Time + TargetID string + CommandID string + Operation string + Error string + Status logstream.RunStatus +} + +// LogSnapshot is a scrubbed recent vertex log line. +type LogSnapshot struct { + Timestamp time.Time + Operation string + Text string +} + +// CancellationDetails is best-effort context for a canceled solve when +// BuildKit did not provide a fatal or cancellation-specific vertex error. +type CancellationDetails struct { + End time.Time + Active []OperationSnapshot + Recent []OperationSnapshot + Logs []LogSnapshot +} + +// Empty reports whether no progress context was captured. +func (d CancellationDetails) Empty() bool { + return len(d.Active) == 0 && len(d.Recent) == 0 && len(d.Logs) == 0 +} + +func (d CancellationDetails) String() string { + var b strings.Builder + if len(d.Active) > 0 { + b.WriteString("Last active operations:\n") + + for _, op := range d.Active { + fmt.Fprintf(&b, " - %s\n", op.String()) + } + } + + if len(d.Recent) > 0 { + if b.Len() > 0 { + b.WriteString("\n") + } + + b.WriteString("Recent completed or canceled operations:\n") + + for _, op := range d.Recent { + fmt.Fprintf(&b, " - %s\n", op.String()) + } + } + + if len(d.Logs) > 0 { + if b.Len() > 0 { + b.WriteString("\n") + } + + b.WriteString("Recent output:\n") + + for _, log := range d.Logs { + if log.Operation != "" { + fmt.Fprintf(&b, " - %s: %s\n", log.Operation, log.Text) + } else { + fmt.Fprintf(&b, " - %s\n", log.Text) + } + } + } + + return strings.TrimRight(b.String(), "\n") +} + +func (op OperationSnapshot) String() string { + if op.Error != "" { + return fmt.Sprintf("%s: %s", op.Operation, op.Error) + } + + if op.Operation != "" { + return op.Operation + } + + if op.CommandID != "" { + return op.CommandID + } + + return op.TargetID +} + +func appendWithLimit[T any](items []T, item T, limit int) []T { + items = append(items, item) + if len(items) > limit { + return items[len(items)-limit:] + } + + return items +} + +func splitLogLines(data string) []string { + lines := strings.Split(data, "\n") + + out := make([]string, 0, len(lines)) + + for _, line := range lines { + line = strings.TrimSpace(line) + if line != "" { + out = append(out, line) + } + } + + return out +} + +// FirstFailureError wraps a solve error with the first fatal vertex failure +// observed by the solver monitor. +type FirstFailureError struct { + Cause error + Failure FirstFailure +} + +func (e *FirstFailureError) Error() string { + return e.Failure.Error +} + +func (e *FirstFailureError) Unwrap() error { + return e.Cause +} + +// Is matches against the wrapped cause so callers can keep using errors.Is. +func (e *FirstFailureError) Is(target error) bool { + return errors.Is(e.Cause, target) +} + +// UnwrapCause returns the original solve error. +func (e *FirstFailureError) UnwrapCause() error { + return e.Cause +} + +// NewFirstFailureError wraps cause with the first fatal vertex failure, or +// returns cause unchanged when no failure was recorded. +func NewFirstFailureError(cause error, failure FirstFailure) error { + if failure.Error == "" { + return cause + } + + return &FirstFailureError{ + Cause: cause, + Failure: failure, + } +} + +// AsFirstFailureError extracts a FirstFailureError from err's chain. +func AsFirstFailureError(err error) (*FirstFailureError, bool) { + var failureErr *FirstFailureError + if errors.As(err, &failureErr) { + return failureErr, true + } + + return nil, false +} + +func (f FirstFailure) String() string { + if f.Error != "" { + return f.Error + } + + return fmt.Sprintf("build failed in target %s command %s", f.TargetID, f.CommandID) +} + +// FirstCancellationError wraps a canceled solve with the first canceled vertex +// observed by the solver monitor. +type FirstCancellationError struct { + Cause error + Cancellation FirstFailure +} + +func (e *FirstCancellationError) Error() string { + if e.Cancellation.Error != "" { + return e.Cancellation.Error + } + + return e.Cause.Error() +} + +func (e *FirstCancellationError) Unwrap() error { + return e.Cause +} + +// Is matches against the wrapped cause so callers can keep using errors.Is. +func (e *FirstCancellationError) Is(target error) bool { + return errors.Is(e.Cause, target) +} + +// NewFirstCancellationError wraps cause with the first canceled vertex, or +// returns cause unchanged when no cancellation context was recorded. +func NewFirstCancellationError(cause error, cancellation FirstFailure) error { + if cancellation.Error == "" { + return cause + } + + return &FirstCancellationError{ + Cause: cause, + Cancellation: cancellation, + } +} + +// AsFirstCancellationError extracts a FirstCancellationError from err's chain. +func AsFirstCancellationError(err error) (*FirstCancellationError, bool) { + var cancelErr *FirstCancellationError + if errors.As(err, &cancelErr) { + return cancelErr, true + } + + return nil, false +} + +// CancellationDetailsError wraps a canceled solve with recent progress context +// when no specific root cause was observed. +type CancellationDetailsError struct { + Cause error + Details CancellationDetails +} + +func (e *CancellationDetailsError) Error() string { + if !e.Details.Empty() { + return e.Details.String() + } + + return e.Cause.Error() +} + +func (e *CancellationDetailsError) Unwrap() error { + return e.Cause +} + +// Is matches against the wrapped cause so callers can keep using errors.Is. +func (e *CancellationDetailsError) Is(target error) bool { + return errors.Is(e.Cause, target) +} + +// NewCancellationDetailsError wraps cause with recent progress context, or +// returns cause unchanged when no context was captured. +func NewCancellationDetailsError(cause error, details CancellationDetails) error { + if details.Empty() { + return cause + } + + return &CancellationDetailsError{ + Cause: cause, + Details: details, + } +} + +// AsCancellationDetailsError extracts a CancellationDetailsError from err's chain. +func AsCancellationDetailsError(err error) (*CancellationDetailsError, bool) { + var detailsErr *CancellationDetailsError + if errors.As(err, &detailsErr) { + return detailsErr, true + } + + return nil, false +} diff --git a/logbus/solvermon/solvermon.go b/logbus/solvermon/solvermon.go index d6feee6104..cbe7aa606d 100644 --- a/logbus/solvermon/solvermon.go +++ b/logbus/solvermon/solvermon.go @@ -3,6 +3,7 @@ package solvermon import ( "context" + "slices" "sync" "time" @@ -19,10 +20,15 @@ import ( // SolverMonitor is a buildkit solver monitor. type SolverMonitor struct { - b *logbus.Bus - digests map[digest.Digest]string // digest -> cmdID - vertices map[string]*vertexMonitor // cmdID -> vertexMonitor - mu sync.Mutex + b *logbus.Bus + digests map[digest.Digest]string // digest -> cmdID + vertices map[string]*vertexMonitor // cmdID -> vertexMonitor + active map[string]OperationSnapshot + firstFailure *FirstFailure + firstCancel *FirstFailure + recent []OperationSnapshot + recentLogs []LogSnapshot + mu sync.Mutex } // New creates a new SolverMonitor. @@ -31,9 +37,57 @@ func New(b *logbus.Bus) *SolverMonitor { b: b, digests: make(map[digest.Digest]string), vertices: make(map[string]*vertexMonitor), + active: make(map[string]OperationSnapshot), } } +// FirstFailure returns the first fatal vertex failure observed by the monitor. +func (sm *SolverMonitor) FirstFailure() (FirstFailure, bool) { + sm.mu.Lock() + defer sm.mu.Unlock() + + if sm.firstFailure == nil { + return FirstFailure{}, false + } + + return *sm.firstFailure, true +} + +// FirstCancellation returns the first canceled vertex observed by the monitor. +func (sm *SolverMonitor) FirstCancellation() (FirstFailure, bool) { + sm.mu.Lock() + defer sm.mu.Unlock() + + if sm.firstCancel == nil { + return FirstFailure{}, false + } + + return *sm.firstCancel, true +} + +// CancellationDetails returns recent progress context for a solve that was +// canceled without a fatal or cancellation-specific vertex error. +func (sm *SolverMonitor) CancellationDetails() (CancellationDetails, bool) { + sm.mu.Lock() + defer sm.mu.Unlock() + + details := CancellationDetails{ + End: time.Now(), + Active: make([]OperationSnapshot, 0, len(sm.active)), + Recent: append([]OperationSnapshot(nil), sm.recent...), + Logs: append([]LogSnapshot(nil), sm.recentLogs...), + } + for _, op := range sm.active { + details.Active = append(details.Active, op) + } + + slices.SortFunc(details.Active, func(a, b OperationSnapshot) int { + return a.OperationStarted.Compare(b.OperationStarted) + }) + + return details, !details.Empty() +} + // MonitorProgress processes a channel of buildkit solve statuses. func (sm *SolverMonitor) MonitorProgress(ctx context.Context, ch chan *client.SolveStatus) error { delayedCtx, delayedCancel := context.WithCancel(xcontext.Detach(ctx)) @@ -154,6 +208,10 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error vm.cp.SetStart(*vertex.Started) } + if vertex.Completed == nil { + sm.recordVertexProgress(cmdID, vm, vertex, logstream.RunStatus_RUN_STATUS_UNKNOWN) + } + if vertex.Error != "" { vm.parseError() } @@ -174,8 +232,16 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error } vm.cp.SetEnd(*vertex.Completed, status, vm.errorStr) + sm.recordVertexProgress(cmdID, vm, vertex, status) + + if vm.isCanceled && sm.firstCancel == nil { + sm.firstCancel = sm.failureFromVertex(vm, cmdID, vertex) + } if vm.isFatalError { + if sm.firstFailure == nil { + sm.firstFailure = sm.failureFromVertex(vm, cmdID, vertex) + } // Run this at the end so that we capture any additional log lines. defer bp.SetFatalError( *vertex.Completed, @@ -221,7 +287,64 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error if err != nil { return err } + + sm.recordLog(vm, logLine) } return nil } + +func (sm *SolverMonitor) recordVertexProgress( + cmdID string, + vm *vertexMonitor, + vertex *client.Vertex, + status logstream.RunStatus, +) { + if vertex.Started == nil { + return + } + + snapshot := OperationSnapshot{ + TargetID: vm.meta.TargetID, + CommandID: cmdID, + Operation: vm.operation, + OperationStarted: *vertex.Started, + Status: status, + Error: vm.errorStr, + } + + if vertex.Completed == nil { + sm.active[cmdID] = snapshot + return + } + + snapshot.End = *vertex.Completed + + delete(sm.active, cmdID) + sm.recent = appendWithLimit(sm.recent, snapshot, recentOperationLimit) +} + +func (sm *SolverMonitor) recordLog(vm *vertexMonitor, logLine *client.VertexLog) { + for _, line := range splitLogLines(string(logLine.Data)) { + sm.recentLogs = appendWithLimit(sm.recentLogs, LogSnapshot{ + Operation: vm.operation, + Text: line, + Timestamp: logLine.Timestamp, + }, recentLogLimit) + } +} + +func (sm *SolverMonitor) failureFromVertex(vm *vertexMonitor, cmdID string, vertex *client.Vertex) *FirstFailure { + end := time.Now() + if vertex.Completed != nil { + end = *vertex.Completed + } + + return &FirstFailure{ + End: end, + TargetID: vm.meta.TargetID, + CommandID: cmdID, + Error: stringutil.ScrubCredentialsAll(vm.errorStr), + FailureType: vm.fatalErrorType, + } +} diff --git a/logbus/solvermon/solvermon_test.go b/logbus/solvermon/solvermon_test.go new file mode 100644 index 0000000000..39e8d40939 --- /dev/null +++ b/logbus/solvermon/solvermon_test.go @@ -0,0 +1,230 @@ +package solvermon + +import ( + "context" + "testing" + "time" + + "github.com/EarthBuild/earthbuild/logbus" + "github.com/EarthBuild/earthbuild/logstream" + "github.com/EarthBuild/earthbuild/util/vertexmeta" + "github.com/moby/buildkit/client" + "github.com/opencontainers/go-digest" + "github.com/stretchr/testify/require" +) + +const ( + testTargetID = "target-id" + testTargetName = "+target" +) + +func testVertexName(op string) string { + return (&vertexmeta.VertexMeta{TargetID: testTargetID, TargetName: testTargetName}).ToVertexPrefix() + op +} + +func TestFirstFailureCapturesFirstFatalVertexError(t *testing.T) { + t.Parallel() + + sm := New(logbus.New()) + completed := time.Now() + + err := sm.handleBuildkitStatus(&client.SolveStatus{ + Vertexes: []*client.Vertex{ + { + Digest: digest.FromString("fatal"), + Name: testVertexName("RUN bad"), + Completed: &completed, + Error: `process "bad" did not complete successfully: exit code: 42`, + }, + { + Digest: digest.FromString("later"), + Name: (&vertexmeta.VertexMeta{TargetID: "later-target", TargetName: "+later"}).ToVertexPrefix() + "RUN worse", + Completed: &completed, + Error: `process "worse" did not complete successfully: exit code: 43`, + }, + }, + }) + require.NoError(t, err) + + failure, ok := sm.FirstFailure() + require.True(t, ok) + require.Equal(t, testTargetID, failure.TargetID) + require.Equal(t, logstream.FailureType_FAILURE_TYPE_NONZERO_EXIT, failure.FailureType) + require.Contains(t, failure.Error, "RUN bad") + require.Contains(t, failure.Error, "Exit code 42") + require.NotContains(t, failure.Error, "RUN worse") +} + +func TestFirstFailureIgnoresCancellationOnlyVertexError(t *testing.T) { + t.Parallel() + + sm := New(logbus.New()) + completed := time.Now() + + err := sm.handleBuildkitStatus(&client.SolveStatus{ + Vertexes: []*client.Vertex{ + { + Digest: digest.FromString("canceled"), + Name: testVertexName("RUN bad"), + Completed: &completed, + Error: `process "bad" did not complete successfully: exit code: 137: context canceled: context canceled`, + }, + }, + }) + require.NoError(t, err) + + _, ok := sm.FirstFailure() + require.False(t, ok) + + cancellation, ok := sm.FirstCancellation() + require.True(t, ok) + require.Equal(t, testTargetID, cancellation.TargetID) + require.Contains(t, cancellation.Error, "RUN bad") + require.Contains(t, cancellation.Error, "context canceled") +} + +func TestFirstCancellationCapturesSessionLossVertexError(t *testing.T) { + t.Parallel() + + sm := New(logbus.New()) + completed := time.Now() + + err := sm.handleBuildkitStatus(&client.SolveStatus{ + Vertexes: []*client.Vertex{ + { + Digest: digest.FromString("session-loss"), + Name: (&vertexmeta.VertexMeta{ + TargetID: testTargetID, TargetName: testTargetName, + }).ToVertexPrefix() + "local context .", + Completed: &completed, + Error: "could not access local files without session", + }, + }, + }) + require.NoError(t, err) + + _, ok := sm.FirstFailure() + require.False(t, ok) + + cancellation, ok := sm.FirstCancellation() + require.True(t, ok) + require.Equal(t, testTargetID, cancellation.TargetID) + require.Contains(t, cancellation.Error, "local context .") + require.Contains(t, cancellation.Error, "lost the solve session") + require.Contains(t, cancellation.Error, "could not access local files without session") +} + +func TestCancellationDetailsTracksActiveRecentAndLogs(t *testing.T) { + t.Parallel() + + sm := New(logbus.New()) + started := time.Now() + completed := started.Add(time.Second) + activeDigest := digest.FromString("active") + recentDigest := digest.FromString("recent") + + err := sm.handleBuildkitStatus(&client.SolveStatus{ + Vertexes: []*client.Vertex{ + { + Digest: activeDigest, + Name: testVertexName("RUN sleep"), + Started: &started, + }, + { + Digest: recentDigest, + Name: testVertexName("RUN done"), + Started: &started, + Completed: &completed, + }, + }, + Logs: []*client.VertexLog{ + { + Vertex: activeDigest, + Data: []byte("tail line\n"), + Timestamp: completed, + }, + }, + }) + require.NoError(t, err) + + details, ok := sm.CancellationDetails() + require.True(t, ok) + require.Len(t, details.Active, 1) + require.Equal(t, "RUN sleep", details.Active[0].Operation) + require.Len(t, details.Recent, 1) + require.Equal(t, "RUN done", details.Recent[0].Operation) + require.Len(t, details.Logs, 1) + require.Equal(t, "tail line", details.Logs[0].Text) + require.Contains(t, details.String(), "Last active operations") + require.Contains(t, details.String(), "Recent output") +} + +func TestFirstFailureErrorWrapsCause(t *testing.T) { + t.Parallel() + + cause := context.Canceled + err := NewFirstFailureError(cause, FirstFailure{ + Error: "first failure", + }) + + require.ErrorIs(t, err, context.Canceled) + require.Equal(t, "first failure", err.Error()) + + failureErr, ok := AsFirstFailureError(err) + require.True(t, ok) + require.Equal(t, "first failure", failureErr.Failure.Error) +} + +func TestNewFirstFailureErrorReturnsCauseWithoutFailureMessage(t *testing.T) { + t.Parallel() + + cause := context.Canceled + err := NewFirstFailureError(cause, FirstFailure{}) + + require.ErrorIs(t, err, context.Canceled) + require.NotContains(t, err.Error(), "build failed in target") +} + +func TestFirstCancellationErrorWrapsCause(t *testing.T) { + t.Parallel() + + cause := context.Canceled + err := NewFirstCancellationError(cause, FirstFailure{ + Error: "first cancellation", + }) + + require.ErrorIs(t, err, context.Canceled) + require.Equal(t, "first cancellation", err.Error()) + + cancelErr, ok := AsFirstCancellationError(err) + require.True(t, ok) + require.Equal(t, "first cancellation", cancelErr.Cancellation.Error) +} + +func TestNewFirstCancellationErrorReturnsCauseWithoutCancellationMessage(t *testing.T) { + t.Parallel() + + cause := context.Canceled + err := NewFirstCancellationError(cause, FirstFailure{}) + + require.ErrorIs(t, err, context.Canceled) + require.NotContains(t, err.Error(), "build failed in target") +} + +func TestCancellationDetailsErrorWrapsCause(t *testing.T) { + t.Parallel() + + err := NewCancellationDetailsError(context.Canceled, CancellationDetails{ + End: time.Now(), + Active: []OperationSnapshot{ + {Operation: "RUN active"}, + }, + }) + + require.ErrorIs(t, err, context.Canceled) + require.Contains(t, err.Error(), "RUN active") + + detailsErr, ok := AsCancellationDetailsError(err) + require.True(t, ok) + require.Len(t, detailsErr.Details.Active, 1) +} diff --git a/logbus/solvermon/vertexmon.go b/logbus/solvermon/vertexmon.go index 3afc25c623..423cf34da7 100644 --- a/logbus/solvermon/vertexmon.go +++ b/logbus/solvermon/vertexmon.go @@ -36,7 +36,7 @@ type vertexMonitor struct { isCanceled bool } -var reErrExitCode = regexp.MustCompile(`(?:process ".*" did not complete successfully|error calling LocalhostExec): exit code: (?P[0-9]+)$`) //nolint:lll +var reErrExitCode = regexp.MustCompile(`(?:process ".*" did not complete successfully|error calling LocalhostExec): exit code: (?P[0-9]+)(?:\s+\(.*\))?$`) //nolint:lll var ( errNoExitCodeOMM = errors.New("no exit code, process was killed due to OOM") @@ -74,10 +74,34 @@ var ( reHint = regexp.MustCompile(`^(?P.+?):Hint: .+`) ) +func exitCodeDetail(exitCode int) string { + switch exitCode { + case 126: + return "Exit code 126 conventionally means the command was found but could not be executed. " + + "Check executable permissions, the shebang/interpreter, CPU architecture, noexec mounts, " + + "and container runtime or security restrictions." + default: + if exitCode > 128 { + return fmt.Sprintf( + "Exit code %d, which usually means the process was killed by signal %d", + exitCode, exitCode-128) + } + + return fmt.Sprintf("Exit code %d", exitCode) + } +} + +func isCancellationSymptom(errString string) bool { + return strings.Contains(errString, "context canceled") || + strings.Contains(errString, "no active sessions") || + strings.Contains(errString, "could not access local files without session") || + strings.Contains(errString, "evaluating released result") +} + // determineFatalErrorType returns logstream.FailureType // and whether or not its a Fatal Error. func determineFatalErrorType(errString string, exitCode int, exitParseErr error) (logstream.FailureType, bool) { - if strings.Contains(errString, "context canceled") || errString == "no active sessions" { + if isCancellationSymptom(errString) { return logstream.FailureType_FAILURE_TYPE_UNKNOWN, false } @@ -130,7 +154,7 @@ func formatErrorMessage( return fmt.Sprintf( " The%s command\n"+ " %s\n"+ - " did not complete successfully. Exit code %d", internalStr, operation, exitCode) + " did not complete successfully. %s", internalStr, operation, exitCodeDetail(exitCode)) case logstream.FailureType_FAILURE_TYPE_FILE_NOT_FOUND: m := reErrNotFound.FindStringSubmatch(errString) @@ -157,6 +181,14 @@ func formatErrorMessage( " %s\n"+ "failed: %s", internalStr, operation, errString) default: + if isCancellationSymptom(errString) { + return fmt.Sprintf( + "The%s command\n"+ + " %s\n"+ + "was interrupted because BuildKit canceled or lost the solve session before reporting a root cause.\n"+ + "Original BuildKit error: %s", internalStr, operation, errString) + } + return fmt.Sprintf( "The%s command\n"+ " %s\n"+ @@ -180,6 +212,7 @@ func (vm *vertexMonitor) parseError() { exitCode, err := getExitCode(errString) fatalErrorType, isFatalError := determineFatalErrorType(errString, exitCode, err) formattedError := formatErrorMessage(errString, indentOp, vm.meta.Internal, fatalErrorType, exitCode) + isCanceled := isCancellationSymptom(errString) // Add Error location slString := "" @@ -199,13 +232,22 @@ func (vm *vertexMonitor) parseError() { vm.isFatalError = isFatalError vm.fatalErrorType = fatalErrorType + vm.isCanceled = isCanceled } func (vm *vertexMonitor) Write(dt []byte, ts time.Time, stream int) (int, error) { if stream == BuildkitStatsStream { stats, err := vm.ssp.Parse(dt) if err != nil { - return 0, errors.Wrap(err, "failed decoding stats stream") + // Stats are diagnostic telemetry. A decode failure — e.g. a raw + // or partial frame emitted after the daemon's runc stats + // collector hits EOF — must never abort the build. Returning an + // error here propagates up through MonitorProgress and cancels + // the whole solve, surfacing as a bogus "lost the solve session" + // with the running command killed (exit 137). Drop the bad batch + // and re-sync instead. + vm.ssp.Reset() + return len(dt), nil //nolint:nilerr // stats decode failures are intentionally non-fatal } for _, statsSample := range stats { diff --git a/logbus/solvermon/vertexmon_test.go b/logbus/solvermon/vertexmon_test.go index f033e0acfc..71853434b9 100644 --- a/logbus/solvermon/vertexmon_test.go +++ b/logbus/solvermon/vertexmon_test.go @@ -29,6 +29,13 @@ func TestGetExitCode(t *testing.T) { expectedCode: 123, expectedError: nil, }, + { + name: "match with hinted exit code", + errString: "process \"foo\" did not complete successfully: " + + "exit code: 126 (command was found but could not be executed)", + expectedCode: 126, + expectedError: nil, + }, { name: "match with max uint32", errString: "process \"foo\" did not complete successfully: exit code: 4294967295", @@ -78,6 +85,22 @@ func TestDetermineFatalErrorType(t *testing.T) { expectedType: logstream.FailureType_FAILURE_TYPE_UNKNOWN, expectedFatal: false, }, + { + name: "lost local session", + errString: "could not access local files without session", + exitCode: 0, + parseErr: nil, + expectedType: logstream.FailureType_FAILURE_TYPE_UNKNOWN, + expectedFatal: false, + }, + { + name: "released result after cancellation", + errString: "rpc error: code = Unknown desc = evaluating released result", + exitCode: 0, + parseErr: nil, + expectedType: logstream.FailureType_FAILURE_TYPE_UNKNOWN, + expectedFatal: false, + }, { name: "exit code 123", errString: "process \"foo\" did not complete successfully: exit code: 123", @@ -205,3 +228,23 @@ func TestReErrNotFound(t *testing.T) { }) } } + +func TestFormatErrorExplainsSignalExitCode(t *testing.T) { + t.Parallel() + + msg := FormatError("RUN bad", `process "bad" did not complete successfully: exit code: 137`) + + assert.Contains(t, msg, "Exit code 137") + assert.Contains(t, msg, "signal 9") +} + +func TestFormatErrorExplainsExitCode126(t *testing.T) { + t.Parallel() + + msg := FormatError("RUN bad", `process "bad" did not complete successfully: exit code: 126`) + + assert.Contains(t, msg, "Exit code 126") + assert.Contains(t, msg, "command was found but could not be executed") + assert.Contains(t, msg, "executable permissions") + assert.Contains(t, msg, "shebang/interpreter") +} diff --git a/util/statsstreamparser/parser.go b/util/statsstreamparser/parser.go index 1746671810..66fdd9dd98 100644 --- a/util/statsstreamparser/parser.go +++ b/util/statsstreamparser/parser.go @@ -28,6 +28,16 @@ func New() *Parser { } } +// Reset discards any buffered partial frame and returns the parser to its +// initial state. Used to recover from a desynced or malformed stats stream +// (e.g. when the daemon's runc stats collector hits EOF and emits a partial +// or raw frame) without treating the decode failure as fatal. +func (ssp *Parser) Reset() { + ssp.buf.Reset() + ssp.bsr = binarystream.NewReader(ssp.buf, binary.LittleEndian) + ssp.readProtocolVersion = false +} + // Parse parses stream data containing execution statistics. func (ssp *Parser) Parse(b []byte) ([]*runc.Stats, error) { _, err := ssp.buf.Write(b) diff --git a/util/statsstreamparser/parser_test.go b/util/statsstreamparser/parser_test.go new file mode 100644 index 0000000000..cd41ba68e3 --- /dev/null +++ b/util/statsstreamparser/parser_test.go @@ -0,0 +1,58 @@ +package statsstreamparser + +import ( + "bytes" + "encoding/binary" + "encoding/json" + "testing" + + "github.com/containerd/go-runc" + "github.com/stretchr/testify/require" +) + +// frame builds a valid stats stream frame: [version=1][uint32 LE len][JSON]. +func frame(t *testing.T, s runc.Stats) []byte { + t.Helper() + + j, err := json.Marshal(s) + require.NoError(t, err) + + var b bytes.Buffer + b.WriteByte(0x01) + require.NoError(t, binary.Write(&b, binary.LittleEndian, uint32(len(j)))) //nolint:gosec // test frame length is tiny + b.Write(j) + + return b.Bytes() +} + +func TestParseValidFrame(t *testing.T) { + t.Parallel() + + p := New() + stats, err := p.Parse(frame(t, runc.Stats{})) + require.NoError(t, err) + require.Len(t, stats, 1) +} + +// A malformed frame (raw JSON, first byte '{' = 0x7B = 123) is the exact CI +// failure: the daemon's runc stats collector hit EOF and emitted raw bytes. +// It must be reported as an error, and Reset must let the parser recover so a +// transient desync does not permanently wedge stats collection. +func TestParserRecoversAfterGarbageFrame(t *testing.T) { + t.Parallel() + + p := New() + + _, err := p.Parse(frame(t, runc.Stats{})) + require.NoError(t, err) + + _, err = p.Parse([]byte(`{"malformed":true}`)) + require.Error(t, err) + require.Contains(t, err.Error(), "protocol version 123") + + p.Reset() + + stats, err := p.Parse(frame(t, runc.Stats{})) + require.NoError(t, err, "parser must recover after Reset") + require.Len(t, stats, 1) +}