a73x

ea1d5664

fix(agent): a powered-off guest has no console to replay

a73x   2026-08-09 17:44

Commit message
fix(agent): a powered-off guest has no console to replay

A VM's serial pump lives exactly as long as its guest is powered on. Boot
starts it; Shutdown stops it — through the power button or the SIGTERM behind
it — releasing the replay ring and ending every attached viewer. The next
power-on builds a pump with an empty ring.

That ring is 256 KiB of backlog handed to every viewer on attach, so a pump
outliving its guest would answer for it: the dead boot's login prompt read as
the live one's, by an operator's browser and by the smoke's power-cycle boot
proof alike. A shutdown that FAILED is the exception — the guest may well still
be running, and a running guest keeps its console.

Console history survives a stop on disk: serial.log is one file per VM,
appended across pump lifetimes. Both backends hold the invariant.
internal/agent/cloudhv/cloudhv.go
Old New
@@ -78,7 +78,8 @@ type Provisioner struct {
78 // depending on what the box running the tests is allowed to signal. 78 // depending on what the box running the tests is allowed to signal.
79 signal func(pid int, sig syscall.Signal) error 79 signal func(pid int, sig syscall.Signal) error
80 80
81 // Pumps receives serial-pump lifecycle calls at Boot/Kill. nil = no-op. 81 // Pumps receives serial-pump lifecycle calls at Boot/Shutdown/kill — a VM's
82 // pump lives exactly as long as its guest is powered on. nil = no-op.
82 Pumps PumpHooks 83 Pumps PumpHooks
83 } 84 }
84 85
@@ -379,10 +380,35 @@ func (p *Provisioner) socketClient(vmID string) *http.Client {
379 } 380 }
380 } 381 }
381 382
382 // Shutdown requests a clean shutdown via the cloud-hypervisor power-button API. 383 // Shutdown powers the guest off and takes its serial console with it: a
384 // powered-off guest has no console to replay. The pump's ring is 256 KiB of
385 // backlog replayed to every new viewer, so a pump left running across a stop
386 // would answer for a guest that is not there — the next viewer, or the next
387 // boot proof, reads the dead boot's login prompt as the live one's.
388 //
389 // A shutdown that FAILED leaves the pump alone: the guest may well still be
390 // running, and a running guest keeps its console. On the way back up Boot
391 // re-Ensures the pump, which opens the fresh socket with an empty ring.
392 //
393 // Console history is not lost with the ring. serial.log is opened O_APPEND at
394 // a path fixed per VM, so the next pump continues the same file (rotating once
395 // at 4 MiB) — what a stop costs is the tail of the guest's shutdown sequence,
396 // which is written after the power button is pressed and has no pump left to
397 // drain it.
398 func (p *Provisioner) Shutdown(ctx context.Context, vmID string) error {
399 if err := p.powerOff(ctx, vmID); err != nil {
400 return err
401 }
402 if p.Pumps != nil {
403 p.Pumps.Stop(vmID)
404 }
405 return nil
406 }
407
408 // powerOff requests a clean shutdown via the cloud-hypervisor power-button API.
383 // Falls back to SIGTERM via the PID file if the API call fails or returns a 409 // Falls back to SIGTERM via the PID file if the API call fails or returns a
384 // non-2xx status (e.g. 404/500 when CH is unhealthy or the VM is not running). 410 // non-2xx status (e.g. 404/500 when CH is unhealthy or the VM is not running).
385 func (p *Provisioner) Shutdown(ctx context.Context, vmID string) error { 411 func (p *Provisioner) powerOff(ctx context.Context, vmID string) error {
386 client := p.socketClient(vmID) 412 client := p.socketClient(vmID)
387 req, err := http.NewRequestWithContext(ctx, http.MethodPut, 413 req, err := http.NewRequestWithContext(ctx, http.MethodPut,
388 "http://localhost/api/v1/vm.power-button", nil) 414 "http://localhost/api/v1/vm.power-button", nil)
internal/agent/cloudhv/cloudhv_test.go
Old New
@@ -119,13 +119,14 @@ func TestDestroyStopsPumpAndRemovesSerialSocket(t *testing.T) {
119 assert.True(t, os.IsNotExist(statErr), "stale serial socket must be removed") 119 assert.True(t, os.IsNotExist(statErr), "stale serial socket must be removed")
120 } 120 }
121 121
122 // TestBootEnsuresPump pins the most load-bearing pump hook: Boot must Ensure 122 // TestBootEnsuresPumpAndShutdownStopsIt pins both ends of the pump's lifetime,
123 // the serial pump right after CH starts (a regression here = silently dead 123 // which is exactly the guest's power-on time. Boot must Ensure the pump right
124 // consoles fleet-wide, since reconcile tests fake the whole Provisioner). It 124 // after CH starts (a regression here = silently dead consoles fleet-wide, since
125 // also pins the deliberate asymmetry: Shutdown must NOT stop the pump — the 125 // reconcile tests fake the whole Provisioner), and Shutdown must stop it: the
126 // pump survives VM stop/start (it reconnects to the fresh socket); only Destroy 126 // pump's ring is replayed to every new viewer, so one left running across a stop
127 // (VM destroyed) tears it down. 127 // hands a dead boot's login prompt to whoever attaches next — including the
128 func TestBootEnsuresPump(t *testing.T) { 128 // smoke's power-cycle boot proof.
129 func TestBootEnsuresPumpAndShutdownStopsIt(t *testing.T) {
129 st, err := state.Open(t.TempDir()) 130 st, err := state.Open(t.TempDir())
130 require.NoError(t, err) 131 require.NoError(t, err)
131 132
@@ -145,9 +146,30 @@ func TestBootEnsuresPump(t *testing.T) {
145 assert.Equal(t, []string{vmID}, rec.ensured, "Boot must attach the serial pump") 146 assert.Equal(t, []string{vmID}, rec.ensured, "Boot must attach the serial pump")
146 147
147 // No API socket is listening, so Shutdown falls back to SIGTERM — either 148 // No API socket is listening, so Shutdown falls back to SIGTERM — either
148 // path must leave the pump alone. 149 // path powers the guest off, and a powered-off guest has no console.
149 require.NoError(t, p.Shutdown(context.Background(), vmID)) 150 require.NoError(t, p.Shutdown(context.Background(), vmID))
150 assert.Empty(t, rec.stopped, "Shutdown must NOT stop the pump — it survives VM restarts") 151 assert.Equal(t, []string{vmID}, rec.stopped, "Shutdown must take the console down with the guest")
152 }
153
154 // TestAFailedShutdownLeavesTheConsoleUp is the other side of that invariant.
155 // SIGTERM refused by the kernel proves nothing about the guest, which is very
156 // likely still running — and a running guest keeps its console, or the operator
157 // loses the console at exactly the moment the VM stops answering.
158 func TestAFailedShutdownLeavesTheConsoleUp(t *testing.T) {
159 st, err := state.Open(t.TempDir())
160 require.NoError(t, err)
161 vmID := "vm-stubborn"
162 require.NoError(t, os.MkdirAll(st.VMDir(vmID), 0o755))
163 rec := &pumpRecorder{}
164 p := New(st, "ch", "fw", nil, newFakeNet())
165 p.Pumps = rec
166 require.NoError(t, pidfile.Write(p.pidPath(vmID), 4242, p.bootID()))
167 p.signal = func(int, syscall.Signal) error { return syscall.EPERM }
168
169 // No API socket: the power button is unreachable and the SIGTERM fallback
170 // is refused.
171 require.Error(t, p.Shutdown(context.Background(), vmID))
172 assert.Empty(t, rec.stopped, "a shutdown that did not happen must not take the console")
151 } 173 }
152 174
153 // sparseFile creates a sparse file of the given size and returns its path. 175 // sparseFile creates a sparse file of the given size and returns its path.
internal/agent/serialpump/serialpump.go
Old New
@@ -70,11 +70,15 @@ func (m *Manager) Ensure(vmID string) {
70 m.mu.Lock() 70 m.mu.Lock()
71 defer m.mu.Unlock() 71 defer m.mu.Unlock()
72 if p, ok := m.pumps[vmID]; ok { 72 if p, ok := m.pumps[vmID]; ok {
73 // Pump already running — but it may be parked deep in dial backoff 73 // Pump already running. A pump outlives its console only when the
74 // (up to 30s): Shutdown deliberately leaves the pump alive across VM 74 // hypervisor went away on its own — a crash, or a guest that powered
75 // stop/start, so on restart the VM's fresh socket must not wait out a 75 // itself off — since a stop the fleet asked for stops the pump too. The
76 // stale backoff (unconsumed early boot output is dropped or truncated 76 // fleet restarts such a VM through the backend's Boot, which lands here
77 // by CH). Poke the dial loop to retry now. 77 // on a pump possibly parked deep in dial backoff (up to 30s); the fresh
78 // socket must not wait that out, because unconsumed early boot output is
79 // dropped or truncated by CH. Poke the dial loop to retry now. The ring
80 // rides across that one restart, and should: its last words are what the
81 // guest said as it died, which is what a viewer comes for.
78 select { 82 select {
79 case p.poke <- struct{}{}: 83 case p.poke <- struct{}{}:
80 default: // a poke is already pending 84 default: // a poke is already pending
@@ -95,7 +99,11 @@ func (m *Manager) Ensure(vmID string) {
95 go p.run() 99 go p.run()
96 } 100 }
97 101
98 // Stop tears down the VM's pump (VM destroyed). No-op for unknown VMs. 102 // Stop tears down the VM's pump: the guest was powered off or destroyed, so
103 // its console goes with it — the ring is released and every attached viewer is
104 // ended. The next Ensure (a power-on) builds a pump with an empty ring, which
105 // is what keeps a dead boot's output from answering for a live guest. No-op for
106 // unknown VMs.
99 func (m *Manager) Stop(vmID string) { 107 func (m *Manager) Stop(vmID string) {
100 m.mu.Lock() 108 m.mu.Lock()
101 p := m.pumps[vmID] 109 p := m.pumps[vmID]
@@ -130,7 +138,7 @@ func (m *Manager) Attach(ctx context.Context, vmID string, rw io.ReadWriter, onR
130 p := m.pumps[vmID] 138 p := m.pumps[vmID]
131 m.mu.Unlock() 139 m.mu.Unlock()
132 if p == nil { 140 if p == nil {
133 return fmt.Errorf("no console for vm %q (not running on this host?)", vmID) 141 return fmt.Errorf("no console for vm %q (powered off, or not on this host?)", vmID)
134 } 142 }
135 if onReady != nil { 143 if onReady != nil {
136 if err := onReady(); err != nil { 144 if err := onReady(); err != nil {
internal/agent/serialpump/serialpump_test.go
Old New
@@ -363,11 +363,12 @@ func TestPumpReconnectsAfterSocketRestart(t *testing.T) {
363 writeAll(t, guest2, []byte("B")) 363 writeAll(t, guest2, []byte("B"))
364 } 364 }
365 365
366 // TestEnsurePokesBackedOffPump pins the re-Ensure nudge: Shutdown deliberately 366 // TestEnsurePokesBackedOffPump pins the re-Ensure nudge: a pump whose
367 // leaves the pump alive, so when a VM restarts, Ensure finds an existing pump 367 // hypervisor died on its own — a crash, a guest that powered itself off —
368 // possibly parked deep in dial backoff — the poke must make it re-dial 368 // outlives its console, so when the fleet restarts that VM, Ensure finds an
369 // immediately, or the fresh socket sits unconsumed for up to 30s and early 369 // existing pump possibly parked deep in dial backoff. The poke must make it
370 // boot output is lost. 370 // re-dial immediately, or the fresh socket sits unconsumed for up to 30s and
371 // early boot output is lost.
371 // 372 //
372 // Timing schedule (every wait is a lower bound — time.After never fires 373 // Timing schedule (every wait is a lower bound — time.After never fires
373 // early, so scheduling jitter only pushes dials LATER): 374 // early, so scheduling jitter only pushes dials LATER):
@@ -401,6 +402,80 @@ func TestEnsurePokesBackedOffPump(t *testing.T) {
401 } 402 }
402 } 403 }
403 404
405 // TestPowerOffDropsTheRingAndKeepsTheLog is the pump-lifecycle invariant read
406 // from the console: a guest that has been powered off has nothing to replay.
407 // The backend stops the pump when it stops the guest, so the ring — the backlog
408 // every new viewer is handed on attach — goes with it, and the next boot's
409 // viewer reads that boot alone. Without this, the first boot's login prompt
410 // answers for the second, which is the whole basis of the smoke's power-cycle
411 // boot proof. The history is not lost with the ring: serial.log is one file per
412 // VM, appended across pump lifetimes.
413 func TestPowerOffDropsTheRingAndKeepsTheLog(t *testing.T) {
414 dir := t.TempDir()
415 m := newTestManager(t, dir)
416 sock := filepath.Join(dir, "vm1.serial.sock")
417 logPath := filepath.Join(dir, "vm1.serial.log")
418
419 ch := newFakeCH(t, sock)
420 m.Ensure("vm1")
421 guest := ch.conn(t)
422 writeAll(t, guest, []byte("BOOT-1 login: "))
423 // The first boot must be IN the ring at the moment of the stop, or the test
424 // proves nothing about dropping it.
425 require.Eventually(t, func() bool {
426 b, _ := os.ReadFile(logPath)
427 return string(b) == "BOOT-1 login: "
428 }, ioTimeout, time.Millisecond, "pump never drained the first boot")
429
430 // Power off. Listener before conn, as in TestPumpReconnectsAfterSocketRestart.
431 m.Stop("vm1")
432 ch.ln.Close()
433 guest.Close()
434 if err := os.Remove(sock); err != nil && !os.IsNotExist(err) {
435 t.Fatal(err)
436 }
437 assert.Error(t, m.Attach(t.Context(), "vm1", nil, nil),
438 "a powered-off guest has no console to attach to")
439
440 // Power on: a fresh socket, and Ensure builds a fresh pump on it.
441 ch2 := newFakeCH(t, sock)
442 m.Ensure("vm1")
443 guest2 := ch2.conn(t)
444 writeAll(t, guest2, []byte("BOOT-2"))
445
446 viewer, out, _ := pipeViewer()
447 go m.Attach(t.Context(), "vm1", viewer, nil) //nolint:errcheck
448 assert.Equal(t, "BOOT-2", string(readN(t, out, 6)),
449 "the dead boot must not be replayed to the live one's viewer")
450
451 require.Eventually(t, func() bool {
452 b, _ := os.ReadFile(logPath)
453 return string(b) == "BOOT-1 login: BOOT-2"
454 }, ioTimeout, time.Millisecond, "serial.log must keep the history the ring dropped")
455 }
456
457 // TestPowerOffEndsAttachedViewers pins the other half of Stop's contract. A
458 // viewer watching a VM that powers off must be ended, not left parked on a
459 // channel nothing will ever publish to — its console is genuinely gone, and the
460 // error is what tells the far end (a browser, the smoke's tail) to re-dial.
461 func TestPowerOffEndsAttachedViewers(t *testing.T) {
462 dir := t.TempDir()
463 m := newTestManager(t, dir)
464 ch := newFakeCH(t, filepath.Join(dir, "vm1.serial.sock"))
465 m.Ensure("vm1")
466 guest := ch.conn(t)
467
468 viewer, out, _ := pipeViewer()
469 errc := make(chan error, 1)
470 go func() { errc <- m.Attach(context.Background(), "vm1", viewer, nil) }()
471 writeAll(t, guest, []byte("LIVE\n"))
472 assert.Equal(t, "LIVE\n", string(readN(t, out, 5))) // attached and flowing
473
474 m.Stop("vm1")
475
476 assert.Error(t, recvWithin(t, errc, "Attach never returned after the guest powered off"))
477 }
478
404 func TestStopUnknownVMIsNoop(t *testing.T) { 479 func TestStopUnknownVMIsNoop(t *testing.T) {
405 m := newTestManager(t, t.TempDir()) 480 m := newTestManager(t, t.TempDir())
406 m.Stop("never-started") // must not panic 481 m.Stop("never-started") // must not panic
internal/agent/vfkit/vfkit.go
Old New
@@ -86,7 +86,8 @@ type Provisioner struct {
86 // One, deliberately: see newRESTClient. 86 // One, deliberately: see newRESTClient.
87 rest *http.Client 87 rest *http.Client
88 88
89 // Pumps receives serial-pump lifecycle calls at Boot/kill. nil = no-op. 89 // Pumps receives serial-pump lifecycle calls at Boot/Shutdown/kill — a VM's
90 // pump lives exactly as long as its guest is powered on. nil = no-op.
90 Pumps PumpHooks 91 Pumps PumpHooks
91 } 92 }
92 93
@@ -391,11 +392,27 @@ func (p *Provisioner) Running(vmID string) bool {
391 return p.signal(pid, 0) == nil 392 return p.signal(pid, 0) == nil
392 } 393 }
393 394
394 // Shutdown asks vfkit for a graceful stop — the framework's ACPI power-down, 395 // Shutdown powers the guest off and takes its serial console with it: a
396 // powered-off guest has no console to replay, and a pump left running across a
397 // stop would hand its backlog — a dead boot — to the next viewer as if it were
398 // the live one. cloudhv holds the same invariant and states the reasoning in
399 // full. A shutdown that FAILED leaves the pump alone: the guest may still be
400 // running, and a running guest keeps its console.
401 func (p *Provisioner) Shutdown(ctx context.Context, vmID string) error {
402 if err := p.powerOff(ctx, vmID); err != nil {
403 return err
404 }
405 if p.Pumps != nil {
406 p.Pumps.Stop(vmID)
407 }
408 return nil
409 }
410
411 // powerOff asks vfkit for a graceful stop — the framework's ACPI power-down,
395 // the same request cloud-hypervisor's power-button API makes. Falls back to 412 // the same request cloud-hypervisor's power-button API makes. Falls back to
396 // SIGTERM when the socket is gone or refuses, which covers a vfkit that is 413 // SIGTERM when the socket is gone or refuses, which covers a vfkit that is
397 // unhealthy or a VM that is not running. 414 // unhealthy or a VM that is not running.
398 func (p *Provisioner) Shutdown(ctx context.Context, vmID string) error { 415 func (p *Provisioner) powerOff(ctx context.Context, vmID string) error {
399 body := bytes.NewReader([]byte(`{"state":"Stop"}`)) 416 body := bytes.NewReader([]byte(`{"state":"Stop"}`))
400 req, err := http.NewRequestWithContext(withSocket(ctx, p.sockPath(vmID)), http.MethodPost, "http://vfkit/vm/state", body) 417 req, err := http.NewRequestWithContext(withSocket(ctx, p.sockPath(vmID)), http.MethodPost, "http://vfkit/vm/state", body)
401 if err != nil { 418 if err != nil {
internal/agent/vfkit/vfkit_test.go
Old New
@@ -412,6 +412,38 @@ func TestShutdownFallsBackToSigtermWhenVfkitRefuses(t *testing.T) {
412 assert.NoError(t, p.Shutdown(context.Background(), "vm-1")) 412 assert.NoError(t, p.Shutdown(context.Background(), "vm-1"))
413 } 413 }
414 414
415 // TestShutdownTakesTheConsoleDownWithTheGuest pins the second half of the
416 // pump's lifetime — it lasts exactly as long as the guest is powered on. The
417 // ring is replayed to every new viewer, so a pump left running across a stop
418 // answers for a guest that is not there. cloudhv carries the same test.
419 func TestShutdownTakesTheConsoleDownWithTheGuest(t *testing.T) {
420 p := newTestProv(t, nil)
421 pumps := &fakePumps{}
422 p.Pumps = pumps
423 serveREST(t, p, "vm-1", func(w http.ResponseWriter, _ *http.Request) {
424 w.WriteHeader(http.StatusAccepted)
425 })
426
427 require.NoError(t, p.Shutdown(context.Background(), "vm-1"))
428
429 assert.Equal(t, []string{"vm-1"}, pumps.stopped)
430 }
431
432 // TestAFailedShutdownLeavesTheConsoleUp is its complement: a SIGTERM the kernel
433 // refused proves nothing about the guest, which is very likely still running —
434 // and a running guest keeps its console.
435 func TestAFailedShutdownLeavesTheConsoleUp(t *testing.T) {
436 p := newTestProv(t, nil)
437 pumps := &fakePumps{}
438 p.Pumps = pumps
439 p.signal = func(int, syscall.Signal) error { return syscall.EPERM }
440 writePidfile(t, p, "vm-1", "4321\n"+p.bootID()+"\n")
441
442 // No REST socket: the graceful stop is unreachable and the fallback refused.
443 require.Error(t, p.Shutdown(context.Background(), "vm-1"))
444 assert.Empty(t, pumps.stopped, "a shutdown that did not happen must not take the console")
445 }
446
415 func TestShutdownOfAVMWithNoProcessIsNotAnError(t *testing.T) { 447 func TestShutdownOfAVMWithNoProcessIsNotAnError(t *testing.T) {
416 p := newTestProv(t, nil) 448 p := newTestProv(t, nil)
417 // No socket, no pidfile: reconcile calls Shutdown on every tick past a stop 449 // No socket, no pidfile: reconcile calls Shutdown on every tick past a stop