diff --git a/packages/orchestrator/pkg/sandbox/nbd/dispatch.go b/packages/orchestrator/pkg/sandbox/nbd/dispatch.go index 5e3911068a..5d0a575659 100644 --- a/packages/orchestrator/pkg/sandbox/nbd/dispatch.go +++ b/packages/orchestrator/pkg/sandbox/nbd/dispatch.go @@ -8,7 +8,9 @@ import ( "errors" "fmt" "io" + "net" "sync" + "syscall" "time" "go.opentelemetry.io/otel/attribute" @@ -227,8 +229,7 @@ func (d *Dispatch) completeAsync(ctx context.Context, cmd command, perform func( select { case d.fatal <- err: default: - d.logger.Error(ctx, "nbd command failed while the dispatcher was already failing", - append(cmd.fields(), zap.Error(err))...) + d.logCmdFailure(ctx, "nbd command failed while the dispatcher was already failing", cmd, err) } }() } @@ -384,6 +385,33 @@ func (d *Dispatch) Handle(ctx context.Context) error { } } +// isExpectedTeardownError reports whether err is the ordinary consequence of a +// sandbox shutting down rather than a genuine backend or socket failure. When a +// VM exits, in-flight commands observe the cancelled dispatch context +// (context.Canceled / context.DeadlineExceeded) and the reply socket is closed +// under us (net.ErrClosed, or EPIPE / "broken pipe" on a half-closed pipe). +// These are expected during teardown; logging them at Error drowns out the real +// backend failures that Error is meant to surface. +func isExpectedTeardownError(err error) bool { + return errors.Is(err, context.Canceled) || + errors.Is(err, context.DeadlineExceeded) || + errors.Is(err, net.ErrClosed) || + errors.Is(err, syscall.EPIPE) +} + +// logCmdFailure logs a failed NBD command, downgrading expected teardown errors +// to Warn so they cannot mask real failures logged at Error. +func (d *Dispatch) logCmdFailure(ctx context.Context, msg string, cmd command, err error) { + fields := append(cmd.fields(), zap.Error(err)) + if isExpectedTeardownError(err) { + d.logger.Warn(ctx, msg, fields...) + + return + } + + d.logger.Error(ctx, msg, fields...) +} + func (d *Dispatch) cmdRead(ctx context.Context, cmd command) error { if err := d.admit(); err != nil { return err @@ -431,7 +459,7 @@ func (d *Dispatch) cmdRead(ctx context.Context, cmd command) error { // Per-request backend failure: signal it to the NBD client via the // response error byte and keep the dispatch loop alive. Only // writeResponse errors (dead NBD socket) escalate through d.fatal. - d.logger.Error(ctx, "nbd backend read failed", append(cmd.fields(), zap.Error(readErr))...) + d.logCmdFailure(ctx, "nbd backend read failed", cmd, readErr) recordLegFault(ctx) return d.writeResponse(1, cmd.handle, []byte{}) @@ -474,7 +502,7 @@ func (d *Dispatch) cmdWrite(ctx context.Context, cmd command, cmdData []byte) er } if writeErr != nil { - d.logger.Error(ctx, "nbd backend write failed", append(cmd.fields(), zap.Error(writeErr))...) + d.logCmdFailure(ctx, "nbd backend write failed", cmd, writeErr) recordLegFault(ctx) return d.writeResponse(1, cmd.handle, []byte{}) @@ -525,7 +553,7 @@ func (d *Dispatch) cmdWriteZeroes(ctx context.Context, cmd command) error { var respErr uint32 if zeroErr != nil { respErr = 1 - d.logger.Error(ctx, "nbd backend punch failed", append(cmd.fields(), zap.Error(zeroErr))...) + d.logCmdFailure(ctx, "nbd backend punch failed", cmd, zeroErr) recordLegFault(ctx) } diff --git a/packages/orchestrator/pkg/sandbox/nbd/dispatch_teardown_test.go b/packages/orchestrator/pkg/sandbox/nbd/dispatch_teardown_test.go new file mode 100644 index 0000000000..fb790aa8f3 --- /dev/null +++ b/packages/orchestrator/pkg/sandbox/nbd/dispatch_teardown_test.go @@ -0,0 +1,94 @@ +//go:build linux + +package nbd + +import ( + "context" + "errors" + "fmt" + "io" + "net" + "syscall" + "testing" +) + +// Regression for #3274: in-flight NBD reads/writes and reply-socket writes that +// fail because the sandbox is exiting must be classified as expected teardown +// noise (logged at Warn), while genuine backend failures must not be — they stay +// at Error. isExpectedTeardownError is the single predicate both levels hang off, +// so it is the thing worth locking down. +func TestIsExpectedTeardownError(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + err error + want bool + }{ + { + name: "context canceled (dispatch ctx cancelled on VM exit)", + err: context.Canceled, + want: true, + }, + { + name: "context canceled wrapped", + err: fmt.Errorf("read backend: %w", context.Canceled), + want: true, + }, + { + name: "deadline exceeded", + err: context.DeadlineExceeded, + want: true, + }, + { + name: "closed network connection (reply socket closed under us)", + err: net.ErrClosed, + want: true, + }, + { + name: "closed network connection wrapped in OpError", + err: &net.OpError{Op: "write", Net: "unix", Err: net.ErrClosed}, + want: true, + }, + { + name: "broken pipe (EPIPE) wrapped in OpError", + err: &net.OpError{Op: "write", Net: "unix", Err: syscall.EPIPE}, + want: true, + }, + { + name: "bare EPIPE", + err: syscall.EPIPE, + want: true, + }, + { + name: "real backend error must stay Error", + err: errors.New("backing store returned corrupt block"), + want: false, + }, + { + name: "unexpected EOF is a real failure", + err: io.ErrUnexpectedEOF, + want: false, + }, + { + name: "ECONNRESET is not treated as expected teardown", + err: syscall.ECONNRESET, + want: false, + }, + { + name: "nil is not an error", + err: nil, + want: false, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + if got := isExpectedTeardownError(tt.err); got != tt.want { + t.Errorf("isExpectedTeardownError(%v) = %v, want %v", tt.err, got, tt.want) + } + }) + } +}