From ed0917633298538b1cc20cbfe3dcaf1ef8ed2c9c Mon Sep 17 00:00:00 2001 From: AdaAibaby <8872412+adababys@users.noreply.github.com> Date: Fri, 23 Oct 2026 16:17:44 +0800 Subject: [PATCH] fix(orchestrator): log expected NBD teardown errors at Warn, not Error MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When a Firecracker VM exits, in-flight NBD commands and the reply socket fail in predictable ways that are not backend faults: - cmdRead/cmdWrite/cmdWriteZeroes select on the dispatch context, so an in-flight backend call observes context.Canceled (or DeadlineExceeded) the moment the sandbox is torn down. - completeAsync's reply-socket write fails with "use of closed network connection" (net.ErrClosed) or "broken pipe" (EPIPE) once the client side is gone. All four paths logged these at Error, so every normal teardown with in-flight I/O produced a burst of ERROR lines that drown out the real backend failures Error is meant to surface (#3274). Introduce isExpectedTeardownError (context.Canceled, context.DeadlineExceeded, net.ErrClosed, syscall.EPIPE) and route all four failure logs through a new logCmdFailure helper that downgrades those to Warn and keeps everything else at Error. Genuine backend errors (corrupt block, ECONNRESET, unexpected EOF) still surface at Error. Adds dispatch_teardown_test.go: a table-driven test over the classifier covering wrapped context errors, net.ErrClosed/EPIPE inside *net.OpError (how a closed-socket write actually surfaces), and the negatives that must stay Error. Scope note: this PR revives only the NBD-dispatch half of the closed #3277. Its other half — the FC metrics flusher select-race guard (#3275) — is already fixed on main by 50c64bee8 ("stop flushing Firecracker metrics after the VM exits"), so it is intentionally left out. #3275 is CLOSED COMPLETED; #3274 is still open. Adapted to main's refactor (single completeAsync error log, command.fields(), injected d.logger). Closes #3274. Supersedes #3277. --- .../orchestrator/pkg/sandbox/nbd/dispatch.go | 38 +++++++- .../pkg/sandbox/nbd/dispatch_teardown_test.go | 94 +++++++++++++++++++ 2 files changed, 127 insertions(+), 5 deletions(-) create mode 100644 packages/orchestrator/pkg/sandbox/nbd/dispatch_teardown_test.go 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) + } + }) + } +}