From 1e9a2405b54b56f85bc3c0a98a7d93d1fba64051 Mon Sep 17 00:00:00 2001 From: AdaAibaby <8872412+adababys@users.noreply.github.com> Date: Fri, 23 Oct 2026 12:10:53 +0800 Subject: [PATCH] fix(orchestrator): log expected post-crash NBD flush EIO/ENXIO at warn, not error Every sandbox ending - kill, pause, checkpoint hand-off, crash - converges on the cleanup in setupSandboxLifecycle, which calls sbx.Close. On a VM crash or OOM-kill the NBD device is left in error state, so Close's rootfs flush (fsync plus BLKFLSBUF on the nbd device) returns EIO (device error) or ENXIO (already disconnected). Nothing is lost - the VM already exited - yet every abnormal exit logged this at ERROR ("failed to cleanup sandbox, will remove from cache"), drowning real cleanup failures in expected noise. Classify EIO/ENXIO at this post-exit cleanup site as expected and log them at Warn; everything else stays ERROR. A genuine disk error on flush such as ENOSPC is NOT suppressed and still surfaces as ERROR. Crucially this is scoped to the post-exit cleanup only: Sandbox.Shutdown (pause/snapshot) flushes the rootfs through its own path and still treats EIO as a hard error, so a corrupt template can never be published silently. That boundary, and the choice to handle this at the call site rather than inside NBDProvider.Close, follow the review on the original attempt (#3276). The error reaches the call site wrapped several layers deep (Sandbox.Close -> cleanup.Run -> errors.Join -> NBDProvider.Close -> path flush), all via percent-w / errors.Join, so errors.Is reaches the underlying syscall.Errno; verified by a test that matches a realistically deep-wrapped EIO/ENXIO and rejects ENOSPC and generic errors. Extracted as isExpectedPostCrashFlushError for isolation. Rebased onto current main (the cleanup site moved but is unchanged in shape). Closes #3273. Supersedes #3276. --- .../pkg/server/post_crash_flush_test.go | 41 +++++++++++++++++++ packages/orchestrator/pkg/server/sandboxes.go | 25 ++++++++++- 2 files changed, 65 insertions(+), 1 deletion(-) create mode 100644 packages/orchestrator/pkg/server/post_crash_flush_test.go diff --git a/packages/orchestrator/pkg/server/post_crash_flush_test.go b/packages/orchestrator/pkg/server/post_crash_flush_test.go new file mode 100644 index 0000000000..0da4191658 --- /dev/null +++ b/packages/orchestrator/pkg/server/post_crash_flush_test.go @@ -0,0 +1,41 @@ +package server + +import ( + "errors" + "fmt" + "syscall" + "testing" + + "github.com/stretchr/testify/assert" +) + +// wrapLikeCleanup reproduces the real wrapping depth a flush error reaches the +// cleanup call site through: path flush -> NBDProvider.Close -> cleanup.Run's +// errors.Join -> Sandbox.Close. +func wrapLikeCleanup(inner error) error { + flush := fmt.Errorf("sync NBD device: %w", inner) + cow := fmt.Errorf("error flushing cow device: %w", flush) + joined := errors.Join(cow) + return fmt.Errorf("failed to cleanup sandbox: %w", joined) +} + +func TestIsExpectedPostCrashFlushError(t *testing.T) { + t.Parallel() + + for name, tc := range map[string]struct { + err error + want bool + }{ + "EIO deep-wrapped": {wrapLikeCleanup(syscall.EIO), true}, + "ENXIO deep-wrapped": {wrapLikeCleanup(syscall.ENXIO), true}, + "EIO bare": {syscall.EIO, true}, + "disk full (ENOSPC)": {wrapLikeCleanup(syscall.ENOSPC), false}, + "generic error": {wrapLikeCleanup(errors.New("boom")), false}, + "nil": {nil, false}, + } { + t.Run(name, func(t *testing.T) { + t.Parallel() + assert.Equal(t, tc.want, isExpectedPostCrashFlushError(tc.err)) + }) + } +} diff --git a/packages/orchestrator/pkg/server/sandboxes.go b/packages/orchestrator/pkg/server/sandboxes.go index 6abe238390..94c30e4b16 100644 --- a/packages/orchestrator/pkg/server/sandboxes.go +++ b/packages/orchestrator/pkg/server/sandboxes.go @@ -2426,6 +2426,18 @@ func (s *Server) sandboxAlreadyRunning(ctx context.Context, sandboxID, execution return status.Errorf(codes.AlreadyExists, "sandbox '%s' is already running on this node: %s", sandboxID, cause) } +// isExpectedPostCrashFlushError reports whether a sandbox Close error is the +// expected consequence of flushing an NBD device whose VM has already exited. +// After a crash or OOM-kill the device is in error state, so the rootfs flush +// (fsync + BLKFLSBUF on /dev/nbdX) returns EIO or ENXIO; the data is already +// gone with the VM, so at the post-exit cleanup these are noise, not failures. +// The error is wrapped several layers deep (cleanup.Run -> errors.Join -> +// NBDProvider.Close -> path flush), all with %w/errors.Join, so errors.Is +// reaches the underlying syscall.Errno. +func isExpectedPostCrashFlushError(err error) bool { + return errors.Is(err, syscall.EIO) || errors.Is(err, syscall.ENXIO) +} + // setupSandboxLifecycle starts the goroutine that waits for the sandbox to end // and tears it down. releaseTemplate lifts this sandbox's pin on its template; // it runs after the sandbox is closed, on every ending (kill, pause, checkpoint @@ -2465,7 +2477,18 @@ func (s *Server) setupSandboxLifecycle(ctx context.Context, sbx *sandbox.Sandbox cleanupErr := sbx.Close(ctx) if cleanupErr != nil { - sbxlogger.I(sbx).Error(ctx, "failed to cleanup sandbox, will remove from cache", zap.Error(cleanupErr)) + if isExpectedPostCrashFlushError(cleanupErr) { + // Every ending passes here, including a VM crash / OOM-kill. After + // the VM dies the NBD device is in error state, so Close's flush of + // /dev/nbdX (fsync + BLKFLSBUF) returns EIO (device error) or ENXIO + // (already disconnected). Nothing is lost — the VM already exited — + // so this is expected noise, not a cleanup failure; log it at Warn. + // Sandbox.Shutdown() (pause/snapshot) flushes through a different + // path and still surfaces a genuine EIO as an error. + sbxlogger.I(sbx).Warn(ctx, "sandbox device flush failed after VM exit (expected, ignoring)", zap.Error(cleanupErr)) + } else { + sbxlogger.I(sbx).Error(ctx, "failed to cleanup sandbox, will remove from cache", zap.Error(cleanupErr)) + } } closeErr := s.proxy.RemoveFromPool(sbx.LifecycleID)