From b9d29475ae61dcf258e9447209ecb95c89160d7d Mon Sep 17 00:00:00 2001 From: Rauf Guliyev Date: Thu, 16 Jul 2026 04:09:57 +0000 Subject: [PATCH] fix(orchestrator): drop stale pre-init logs A sandbox resumed from a memory snapshot boots with its clock still set to the snapshot's time, so envd's log exporter (also restored from the snapshot) can emit startup logs stamped with that old time before /init corrects the clock. Record a fresh per-lifecycle timestamp on the host before the sandbox is reachable, and reject any log timestamped more than a minute before it. envd's exporter doesn't retry on rejection, so these stale records are simply dropped instead of forwarded. --- .../pkg/hyperloopserver/handlers/logs.go | 33 ++++++ .../pkg/hyperloopserver/handlers/logs_test.go | 102 ++++++++++++++++++ packages/orchestrator/pkg/sandbox/sandbox.go | 9 +- 3 files changed, 142 insertions(+), 2 deletions(-) create mode 100644 packages/orchestrator/pkg/hyperloopserver/handlers/logs_test.go diff --git a/packages/orchestrator/pkg/hyperloopserver/handlers/logs.go b/packages/orchestrator/pkg/hyperloopserver/handlers/logs.go index 8f3b02ed18..965869e325 100644 --- a/packages/orchestrator/pkg/hyperloopserver/handlers/logs.go +++ b/packages/orchestrator/pkg/hyperloopserver/handlers/logs.go @@ -9,6 +9,7 @@ import ( "fmt" "net" "net/http" + "time" "github.com/gin-gonic/gin" "go.uber.org/zap" @@ -47,6 +48,13 @@ func (h *APIStore) Logs(c *gin.Context) { return } + if hasStaleLogTimestamp(payload, sbx.LifecycleStartedAt) { + h.sendAPIStoreError(c, http.StatusBadRequest, "Log timestamp predates this sandbox's resume") + h.logger.Warn(ctx, "dropping envd log with a stale pre-resume timestamp", logger.WithSandboxID(sbxID)) + + return + } + // Overwrite instanceID, envID, and teamID to avoid spoofing payload["instanceID"] = sbxID payload["envID"] = sbx.Runtime.TemplateID @@ -98,3 +106,28 @@ func (h *APIStore) validatePayloadSandboxID(payload map[string]any, sbxID string return nil } + +// Matches envd's zerolog timestamp format. +const envdTimestampLayout = time.RFC3339Nano + +// Allows normal host/guest clock skew. +const clockSkewTolerance = time.Minute + +// True if timestamp predates resume. +func hasStaleLogTimestamp(payload map[string]any, lifecycleStart time.Time) bool { + if lifecycleStart.IsZero() { + return false + } + + raw, ok := payload["timestamp"].(string) + if !ok { + return false + } + + ts, err := time.Parse(envdTimestampLayout, raw) + if err != nil { + return false + } + + return ts.Before(lifecycleStart.Add(-clockSkewTolerance)) +} diff --git a/packages/orchestrator/pkg/hyperloopserver/handlers/logs_test.go b/packages/orchestrator/pkg/hyperloopserver/handlers/logs_test.go new file mode 100644 index 0000000000..ccc2e51c68 --- /dev/null +++ b/packages/orchestrator/pkg/hyperloopserver/handlers/logs_test.go @@ -0,0 +1,102 @@ +//go:build linux + +package handlers + +import ( + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestHasStaleLogTimestamp(t *testing.T) { + t.Parallel() + + lifecycleStart, err := time.Parse(envdTimestampLayout, "2026-07-16T10:00:00Z") + require.NoError(t, err) + + t.Run("timestamp from the snapshot-restored clock is stale", func(t *testing.T) { + t.Parallel() + + payload := map[string]any{"timestamp": "2026-06-09T08:00:00.123456789Z"} + + assert.True(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) + + t.Run("timestamp after lifecycle start is not stale", func(t *testing.T) { + t.Parallel() + + freshRaw := lifecycleStart.Add(time.Second).Format(envdTimestampLayout) + payload := map[string]any{"timestamp": freshRaw} + + assert.False(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) + + t.Run("timestamp at lifecycle start is not stale", func(t *testing.T) { + t.Parallel() + + payload := map[string]any{"timestamp": lifecycleStart.Format(envdTimestampLayout)} + + assert.False(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) + + t.Run("timestamp at the cutoff is not stale", func(t *testing.T) { + t.Parallel() + + cutoffRaw := lifecycleStart.Add(-clockSkewTolerance).Format(envdTimestampLayout) + payload := map[string]any{"timestamp": cutoffRaw} + + assert.False(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) + + t.Run("timestamp within clock-skew tolerance is not stale", func(t *testing.T) { + t.Parallel() + + withinToleranceRaw := lifecycleStart.Add(-clockSkewTolerance / 2).Format(envdTimestampLayout) + payload := map[string]any{"timestamp": withinToleranceRaw} + + assert.False(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) + + t.Run("timestamp past the cutoff is stale", func(t *testing.T) { + t.Parallel() + + staleRaw := lifecycleStart.Add(-clockSkewTolerance - time.Second).Format(envdTimestampLayout) + payload := map[string]any{"timestamp": staleRaw} + + assert.True(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) + + t.Run("zero lifecycle start disables stale detection", func(t *testing.T) { + t.Parallel() + + payload := map[string]any{"timestamp": "2026-06-09T08:00:00Z"} + + assert.False(t, hasStaleLogTimestamp(payload, time.Time{})) + }) + + t.Run("missing timestamp is not stale", func(t *testing.T) { + t.Parallel() + + payload := map[string]any{"message": "hello"} + + assert.False(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) + + t.Run("non-string timestamp is not stale", func(t *testing.T) { + t.Parallel() + + payload := map[string]any{"timestamp": 12345} + + assert.False(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) + + t.Run("invalid timestamp is not stale", func(t *testing.T) { + t.Parallel() + + payload := map[string]any{"timestamp": "not-a-time"} + + assert.False(t, hasStaleLogTimestamp(payload, lifecycleStart)) + }) +} diff --git a/packages/orchestrator/pkg/sandbox/sandbox.go b/packages/orchestrator/pkg/sandbox/sandbox.go index 2d6a33b3e4..d52651a5c2 100644 --- a/packages/orchestrator/pkg/sandbox/sandbox.go +++ b/packages/orchestrator/pkg/sandbox/sandbox.go @@ -270,6 +270,9 @@ type Sandbox struct { // every time a new Firecracker VM is started. LifecycleID string + // Fresh host timestamp marking lifecycle start. + LifecycleStartedAt time.Time + config cfg.BuilderConfig files *storage.SandboxFiles cleanup *Cleanup @@ -599,7 +602,8 @@ func (f *Factory) CreateSandbox( } sbx := &Sandbox{ - LifecycleID: lifecycleID, + LifecycleID: lifecycleID, + LifecycleStartedAt: time.Now().UTC(), Resources: resources, Metadata: metadata, @@ -1010,7 +1014,8 @@ func (f *Factory) ResumeSandbox( } sbx := &Sandbox{ - LifecycleID: lifecycleID, + LifecycleID: lifecycleID, + LifecycleStartedAt: time.Now().UTC(), Resources: resources, Metadata: metadata,