Skip to content

Commit cf6018f

Browse files
sjmiller609sjmiller609
committed
instances: fix marker parsing and readiness edge cases
1 parent 655c284 commit cf6018f

6 files changed

Lines changed: 131 additions & 22 deletions

File tree

‎lib/instances/create.go‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -410,6 +410,9 @@ func (m *manager) createInstance(
410410

411411
// 17. Record boot start time before launching the VM so marker hydration
412412
// can safely ignore stale sentinels from prior runs.
413+
if err := m.archiveAppLogForBoot(id); err != nil {
414+
log.WarnContext(ctx, "failed to archive app log before create boot", "instance_id", id, "error", err)
415+
}
413416
bootStart := time.Now().UTC()
414417
stored.StartedAt = &bootStart
415418

‎lib/instances/query.go‎

Lines changed: 16 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -140,14 +140,15 @@ func (m *manager) hydrateBootMarkersFromLogs(stored *StoredMetadata) bool {
140140
}
141141

142142
// parseBootMarkers scans app logs (including rotated files) and returns the
143-
// latest observed program-start and guest-agent-ready marker timestamps.
143+
// newest observed program-start and guest-agent-ready marker timestamps.
144144
// When startedAt is provided, files last modified before this boot start are ignored.
145145
func (m *manager) parseBootMarkers(id string, needProgram bool, needAgent bool, startedAt *time.Time) (*time.Time, *time.Time) {
146146
logPaths := m.appLogPathsForMarkerScan(id)
147147

148148
var programStartedAt *time.Time
149149
var guestAgentReadyAt *time.Time
150-
for _, logPath := range logPaths {
150+
for i := len(logPaths) - 1; i >= 0; i-- {
151+
logPath := logPaths[i]
151152
if !fileMayContainCurrentBootMarkers(logPath, startedAt) {
152153
continue
153154
}
@@ -161,17 +162,22 @@ func (m *manager) parseBootMarkers(id string, needProgram bool, needAgent bool,
161162
for scanner.Scan() {
162163
line := scanner.Text()
163164
if ts, ok := parseProgramStartSentinelLine(line); ok {
164-
programStartedAt = &ts
165+
if programStartedAt == nil || ts.After(*programStartedAt) {
166+
t := ts
167+
programStartedAt = &t
168+
}
165169
}
166170
if ts, ok := parseAgentReadySentinelLine(line); ok {
167-
guestAgentReadyAt = &ts
168-
}
169-
if (!needProgram || programStartedAt != nil) && (!needAgent || guestAgentReadyAt != nil) {
170-
_ = f.Close()
171-
return programStartedAt, guestAgentReadyAt
171+
if guestAgentReadyAt == nil || ts.After(*guestAgentReadyAt) {
172+
t := ts
173+
guestAgentReadyAt = &t
174+
}
172175
}
173176
}
174177
_ = f.Close()
178+
if (!needProgram || programStartedAt != nil) && (!needAgent || guestAgentReadyAt != nil) {
179+
return programStartedAt, guestAgentReadyAt
180+
}
175181
}
176182

177183
return programStartedAt, guestAgentReadyAt
@@ -216,10 +222,11 @@ func (m *manager) nowUTC() time.Time {
216222
// (oldest rotated file to newest active file).
217223
func (m *manager) appLogPathsForMarkerScan(id string) []string {
218224
base := m.paths.InstanceAppLog(id)
219-
matches, err := filepath.Glob(base + "*")
225+
rotatedMatches, err := filepath.Glob(base + ".*")
220226
if err != nil {
221227
return []string{base}
222228
}
229+
matches := append([]string{base}, rotatedMatches...)
223230

224231
type logPathWithRank struct {
225232
path string

‎lib/instances/query_test.go‎

Lines changed: 63 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -250,3 +250,66 @@ func TestParseBootMarkers_IgnoresStaleMarkersBeforeBootStart(t *testing.T) {
250250
assert.Equal(t, freshProgram.Format(time.RFC3339Nano), programStartedAt.UTC().Format(time.RFC3339Nano))
251251
assert.Equal(t, freshAgent.Format(time.RFC3339Nano), guestAgentReadyAt.UTC().Format(time.RFC3339Nano))
252252
}
253+
254+
func TestParseBootMarkers_ReturnsLatestMarkerFromNewestLog(t *testing.T) {
255+
t.Parallel()
256+
257+
tmpDir := t.TempDir()
258+
m := &manager{
259+
paths: paths.New(tmpDir),
260+
}
261+
262+
id := "latest-marker-instance"
263+
logPath := m.paths.InstanceAppLog(id)
264+
rotatedLogPath := logPath + ".1"
265+
require.NoError(t, os.MkdirAll(filepath.Dir(logPath), 0o755))
266+
267+
oldProgram := time.Date(2026, 3, 9, 4, 0, 0, 0, time.UTC)
268+
oldAgent := oldProgram.Add(500 * time.Millisecond)
269+
newProgram := oldProgram.Add(3 * time.Second)
270+
newProgramLatest := oldProgram.Add(4 * time.Second)
271+
newAgent := oldProgram.Add(3500 * time.Millisecond)
272+
273+
require.NoError(t, os.WriteFile(rotatedLogPath, []byte(
274+
"HYPEMAN-PROGRAM-START ts="+oldProgram.Format(time.RFC3339Nano)+" mode=exec\n"+
275+
"HYPEMAN-AGENT-READY ts="+oldAgent.Format(time.RFC3339Nano)+"\n",
276+
), 0o644))
277+
278+
require.NoError(t, os.WriteFile(logPath, []byte(
279+
"HYPEMAN-PROGRAM-START ts="+newProgram.Format(time.RFC3339Nano)+" mode=exec\n"+
280+
"HYPEMAN-AGENT-READY ts="+newAgent.Format(time.RFC3339Nano)+"\n"+
281+
"HYPEMAN-PROGRAM-START ts="+newProgramLatest.Format(time.RFC3339Nano)+" mode=exec\n",
282+
), 0o644))
283+
284+
programStartedAt, guestAgentReadyAt := m.parseBootMarkers(id, true, true, nil)
285+
require.NotNil(t, programStartedAt)
286+
require.NotNil(t, guestAgentReadyAt)
287+
assert.Equal(t, newProgramLatest.Format(time.RFC3339Nano), programStartedAt.UTC().Format(time.RFC3339Nano))
288+
assert.Equal(t, newAgent.Format(time.RFC3339Nano), guestAgentReadyAt.UTC().Format(time.RFC3339Nano))
289+
}
290+
291+
func TestAppLogPathsForMarkerScan_IgnoresArchivedLogs(t *testing.T) {
292+
t.Parallel()
293+
294+
tmpDir := t.TempDir()
295+
m := &manager{
296+
paths: paths.New(tmpDir),
297+
}
298+
299+
id := "log-order-instance"
300+
logPath := m.paths.InstanceAppLog(id)
301+
require.NoError(t, os.MkdirAll(filepath.Dir(logPath), 0o755))
302+
303+
for _, p := range []string{
304+
logPath,
305+
logPath + ".1",
306+
logPath + ".2",
307+
logPath + ".prev.12345",
308+
logPath + "-debug-copy",
309+
} {
310+
require.NoError(t, os.WriteFile(p, []byte("x\n"), 0o644))
311+
}
312+
313+
paths := m.appLogPathsForMarkerScan(id)
314+
require.Equal(t, []string{logPath + ".2", logPath + ".1", logPath}, paths)
315+
}

‎lib/instances/restore.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -226,7 +226,7 @@ func (m *manager) restoreInstance(
226226
os.RemoveAll(snapshotDir) // Best effort, ignore errors
227227

228228
// 9. Update timestamp
229-
now := time.Now()
229+
now := time.Now().UTC()
230230
stored.StartedAt = &now
231231

232232
meta = &metadata{StoredMetadata: *stored}

‎lib/system/init/mode_exec.go‎

Lines changed: 28 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -228,22 +228,38 @@ func waitForGuestAgentReady(readyReader *os.File, timeout time.Duration, agentEx
228228
readyErr <- err
229229
}()
230230

231+
agentExitCh := agentExited
232+
var agentExitErr error
231233
timer := time.NewTimer(timeout)
232234
defer timer.Stop()
233235

234-
select {
235-
case err := <-readyErr:
236-
if err != nil {
237-
return fmt.Errorf("failed waiting for guest-agent readiness signal: %w", err)
238-
}
239-
return nil
240-
case err := <-agentExited:
241-
if err == nil {
242-
return fmt.Errorf("guest-agent exited before readiness signal")
236+
for {
237+
select {
238+
case err := <-readyErr:
239+
if err != nil {
240+
if agentExitCh == nil {
241+
if agentExitErr == nil {
242+
return fmt.Errorf("guest-agent exited before readiness signal")
243+
}
244+
return fmt.Errorf("guest-agent exited before readiness signal: %w", agentExitErr)
245+
}
246+
return fmt.Errorf("failed waiting for guest-agent readiness signal: %w", err)
247+
}
248+
return nil
249+
case err := <-agentExitCh:
250+
agentExitErr = err
251+
// Keep waiting for the readiness read to complete. If the agent wrote
252+
// readiness and then exited, the read succeeds and startup proceeds.
253+
agentExitCh = nil
254+
case <-timer.C:
255+
if agentExitCh == nil {
256+
if agentExitErr == nil {
257+
return fmt.Errorf("guest-agent exited before readiness signal")
258+
}
259+
return fmt.Errorf("guest-agent exited before readiness signal: %w", agentExitErr)
260+
}
261+
return fmt.Errorf("timed out after %s waiting for guest-agent readiness signal", timeout)
243262
}
244-
return fmt.Errorf("guest-agent exited before readiness signal: %w", err)
245-
case <-timer.C:
246-
return fmt.Errorf("timed out after %s waiting for guest-agent readiness signal", timeout)
247263
}
248264
}
249265

‎lib/system/init/mode_exec_test.go‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -211,3 +211,23 @@ func TestWaitForGuestAgentReadyProcessExit(t *testing.T) {
211211
require.Error(t, err)
212212
assert.Contains(t, err.Error(), "exited before readiness signal")
213213
}
214+
215+
func TestWaitForGuestAgentReadyReadyWinsAfterExitSignal(t *testing.T) {
216+
t.Parallel()
217+
218+
readyReader, readyWriter, err := os.Pipe()
219+
require.NoError(t, err)
220+
defer readyReader.Close()
221+
defer readyWriter.Close()
222+
223+
agentExited := make(chan error, 1)
224+
agentExited <- errors.New("exit status 1")
225+
226+
go func() {
227+
time.Sleep(25 * time.Millisecond)
228+
_, _ = readyWriter.Write([]byte{1})
229+
}()
230+
231+
err = waitForGuestAgentReady(readyReader, time.Second, agentExited)
232+
require.NoError(t, err)
233+
}

0 commit comments

Comments
 (0)