Skip to content

Commit 9cdcd74

Browse files
committed
fix(orchestrator): preserve stale pre-init envd logs' true timing
Sandboxes resumed from a memory snapshot boot with the guest clock still set to the template's snapshot time. envd's log exporter is restored along with the rest of the VM, so it can send startup logs stamped with that old time before /init corrects the clock. Each sandbox now records a fresh host timestamp when its lifecycle is created. The hyperloop /logs handler compares incoming envd timestamps against it and, if one is more than a minute older, replaces it with the lifecycle start time, keeping the original under original_timestamp instead of dropping it. The one-minute margin avoids touching logs that are only off by ordinary host/guest clock skew.
1 parent 73f4eb5 commit 9cdcd74

3 files changed

Lines changed: 192 additions & 2 deletions

File tree

‎packages/orchestrator/pkg/hyperloopserver/handlers/logs.go‎

Lines changed: 42 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import (
99
"fmt"
1010
"net"
1111
"net/http"
12+
"time"
1213

1314
"github.com/gin-gonic/gin"
1415
"go.uber.org/zap"
@@ -52,6 +53,8 @@ func (h *APIStore) Logs(c *gin.Context) {
5253
payload["envID"] = sbx.Runtime.TemplateID
5354
payload["teamID"] = sbx.Runtime.TeamID
5455

56+
correctStaleTimestamp(payload, sbx.LifecycleStartedAt)
57+
5558
logs, err := json.Marshal(payload)
5659
if err != nil {
5760
h.sendAPIStoreError(c, http.StatusInternalServerError, "Error when parsing logs payload")
@@ -98,3 +101,42 @@ func (h *APIStore) validatePayloadSandboxID(payload map[string]any, sbxID string
98101

99102
return nil
100103
}
104+
105+
// envdTimestampLayout matches zerolog's TimeFieldFormat in envd's logger.
106+
const envdTimestampLayout = time.RFC3339Nano
107+
108+
// staleTimestampSlack tolerates normal host/guest clock skew so we only
109+
// override timestamps that are actually stale, not ones a second or two off.
110+
const staleTimestampSlack = time.Minute
111+
112+
// correctStaleTimestamp fixes up envd log records still carrying the guest's
113+
// pre-resume clock. envd's log exporter survives the memory snapshot and can
114+
// flush pre-init logs before /init corrects the guest clock, so those
115+
// records land with a stale timestamp.
116+
//
117+
// lifecycleStart (Sandbox.LifecycleStartedAt) is set fresh per lifecycle
118+
// before the sandbox is reachable, so unlike GetStartedAt() it can't itself
119+
// be stale. Anything older than lifecycleStart (minus slack) gets overridden
120+
// with it, and the original value is kept under "original_timestamp".
121+
//
122+
// No-op if lifecycleStart is zero or "timestamp" isn't a parseable string.
123+
func correctStaleTimestamp(payload map[string]any, lifecycleStart time.Time) {
124+
if lifecycleStart.IsZero() {
125+
return
126+
}
127+
128+
raw, ok := payload["timestamp"].(string)
129+
if !ok {
130+
return
131+
}
132+
133+
ts, err := time.Parse(envdTimestampLayout, raw)
134+
if err != nil {
135+
return
136+
}
137+
138+
if ts.Before(lifecycleStart.Add(-staleTimestampSlack)) {
139+
payload["original_timestamp"] = raw
140+
payload["timestamp"] = lifecycleStart.UTC().Format(envdTimestampLayout)
141+
}
142+
}
Lines changed: 137 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,137 @@
1+
//go:build linux
2+
3+
package handlers
4+
5+
import (
6+
"testing"
7+
"time"
8+
9+
"github.com/stretchr/testify/assert"
10+
"github.com/stretchr/testify/require"
11+
)
12+
13+
func TestCorrectStaleTimestamp(t *testing.T) {
14+
t.Parallel()
15+
16+
lifecycleStart, err := time.Parse(envdTimestampLayout, "2026-07-16T10:00:00Z")
17+
require.NoError(t, err)
18+
19+
t.Run("overrides a timestamp from before the corrected clock", func(t *testing.T) {
20+
t.Parallel()
21+
22+
staleRaw := "2026-06-09T08:00:00.123456789Z"
23+
payload := map[string]any{"timestamp": staleRaw}
24+
25+
correctStaleTimestamp(payload, lifecycleStart)
26+
27+
assert.Equal(t, lifecycleStart.Format(envdTimestampLayout), payload["timestamp"])
28+
assert.Equal(t, staleRaw, payload["original_timestamp"])
29+
})
30+
31+
t.Run("leaves a post-correction timestamp untouched", func(t *testing.T) {
32+
t.Parallel()
33+
34+
freshRaw := lifecycleStart.Add(time.Second).Format(envdTimestampLayout)
35+
payload := map[string]any{"timestamp": freshRaw}
36+
37+
correctStaleTimestamp(payload, lifecycleStart)
38+
39+
assert.Equal(t, freshRaw, payload["timestamp"])
40+
assert.NotContains(t, payload, "original_timestamp")
41+
})
42+
43+
t.Run("leaves a timestamp exactly at lifecycleStart untouched", func(t *testing.T) {
44+
t.Parallel()
45+
46+
boundaryRaw := lifecycleStart.Format(envdTimestampLayout)
47+
payload := map[string]any{"timestamp": boundaryRaw}
48+
49+
correctStaleTimestamp(payload, lifecycleStart)
50+
51+
assert.Equal(t, boundaryRaw, payload["timestamp"])
52+
assert.NotContains(t, payload, "original_timestamp")
53+
})
54+
55+
t.Run("leaves a timestamp exactly at the slack cutoff untouched", func(t *testing.T) {
56+
t.Parallel()
57+
58+
// Before is strict, so the cutoff itself must not be overridden.
59+
cutoffRaw := lifecycleStart.Add(-staleTimestampSlack).Format(envdTimestampLayout)
60+
payload := map[string]any{"timestamp": cutoffRaw}
61+
62+
correctStaleTimestamp(payload, lifecycleStart)
63+
64+
assert.Equal(t, cutoffRaw, payload["timestamp"])
65+
assert.NotContains(t, payload, "original_timestamp")
66+
})
67+
68+
t.Run("leaves a slightly earlier timestamp within slack untouched", func(t *testing.T) {
69+
t.Parallel()
70+
71+
// Ordinary clock skew, not a stale guest clock - shouldn't override.
72+
withinSlackRaw := lifecycleStart.Add(-staleTimestampSlack / 2).Format(envdTimestampLayout)
73+
payload := map[string]any{"timestamp": withinSlackRaw}
74+
75+
correctStaleTimestamp(payload, lifecycleStart)
76+
77+
assert.Equal(t, withinSlackRaw, payload["timestamp"])
78+
assert.NotContains(t, payload, "original_timestamp")
79+
})
80+
81+
t.Run("overrides a timestamp just beyond the slack window", func(t *testing.T) {
82+
t.Parallel()
83+
84+
staleRaw := lifecycleStart.Add(-staleTimestampSlack - time.Second).Format(envdTimestampLayout)
85+
payload := map[string]any{"timestamp": staleRaw}
86+
87+
correctStaleTimestamp(payload, lifecycleStart)
88+
89+
assert.Equal(t, lifecycleStart.Format(envdTimestampLayout), payload["timestamp"])
90+
assert.Equal(t, staleRaw, payload["original_timestamp"])
91+
})
92+
93+
t.Run("is a no-op when lifecycleStart is zero", func(t *testing.T) {
94+
t.Parallel()
95+
96+
staleRaw := "2026-06-09T08:00:00Z"
97+
payload := map[string]any{"timestamp": staleRaw}
98+
99+
correctStaleTimestamp(payload, time.Time{})
100+
101+
assert.Equal(t, staleRaw, payload["timestamp"])
102+
assert.NotContains(t, payload, "original_timestamp")
103+
})
104+
105+
t.Run("is a no-op when timestamp is missing", func(t *testing.T) {
106+
t.Parallel()
107+
108+
payload := map[string]any{"message": "hello"}
109+
110+
correctStaleTimestamp(payload, lifecycleStart)
111+
112+
assert.NotContains(t, payload, "timestamp")
113+
assert.NotContains(t, payload, "original_timestamp")
114+
})
115+
116+
t.Run("is a no-op when timestamp is not a string", func(t *testing.T) {
117+
t.Parallel()
118+
119+
payload := map[string]any{"timestamp": 12345}
120+
121+
correctStaleTimestamp(payload, lifecycleStart)
122+
123+
assert.Equal(t, 12345, payload["timestamp"])
124+
assert.NotContains(t, payload, "original_timestamp")
125+
})
126+
127+
t.Run("is a no-op when timestamp is unparseable", func(t *testing.T) {
128+
t.Parallel()
129+
130+
payload := map[string]any{"timestamp": "not-a-time"}
131+
132+
correctStaleTimestamp(payload, lifecycleStart)
133+
134+
assert.Equal(t, "not-a-time", payload["timestamp"])
135+
assert.NotContains(t, payload, "original_timestamp")
136+
})
137+
}

‎packages/orchestrator/pkg/sandbox/sandbox.go‎

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -270,6 +270,15 @@ type Sandbox struct {
270270
// every time a new Firecracker VM is started.
271271
LifecycleID string
272272

273+
// LifecycleStartedAt is the host-clock time (UTC) this lifecycle's
274+
// Sandbox was constructed, set once before it's registered in the
275+
// network map. Unlike Metadata.startedAt, which is caller-seeded and
276+
// can carry over the previous lifecycle's value across a checkpoint,
277+
// this is always fresh. Used by correctStaleTimestamp in
278+
// hyperloopserver/handlers/logs.go to catch envd logs still carrying
279+
// the pre-resume guest clock.
280+
LifecycleStartedAt time.Time
281+
273282
config cfg.BuilderConfig
274283
files *storage.SandboxFiles
275284
cleanup *Cleanup
@@ -599,7 +608,8 @@ func (f *Factory) CreateSandbox(
599608
}
600609

601610
sbx := &Sandbox{
602-
LifecycleID: lifecycleID,
611+
LifecycleID: lifecycleID,
612+
LifecycleStartedAt: time.Now().UTC(),
603613

604614
Resources: resources,
605615
Metadata: metadata,
@@ -1010,7 +1020,8 @@ func (f *Factory) ResumeSandbox(
10101020
}
10111021

10121022
sbx := &Sandbox{
1013-
LifecycleID: lifecycleID,
1023+
LifecycleID: lifecycleID,
1024+
LifecycleStartedAt: time.Now().UTC(),
10141025

10151026
Resources: resources,
10161027
Metadata: metadata,

0 commit comments

Comments
 (0)