More observability

Author: sjmiller609

lib/hypervisor/cloudhypervisor/process.go

@@ -4,8 +4,10 @@ import (
 	"context"
 	"fmt"
 	"syscall"
+	"time"
 
 	"github.com/onkernel/hypeman/lib/hypervisor"
+	"github.com/onkernel/hypeman/lib/logger"
 	"github.com/onkernel/hypeman/lib/paths"
 	"github.com/onkernel/hypeman/lib/vmm"
 	"gvisor.dev/gvisor/pkg/cleanup"
@@ -100,17 +102,22 @@ func (s *Starter) StartVM(ctx context.Context, p *paths.Paths, version string, s
 // RestoreVM starts Cloud Hypervisor and restores VM state from a snapshot.
 // The VM is in paused state after restore; caller should call Resume() to continue execution.
 func (s *Starter) RestoreVM(ctx context.Context, p *paths.Paths, version string, socketPath string, snapshotPath string) (int, hypervisor.Hypervisor, error) {
+	log := logger.FromContext(ctx)
+	startTime := time.Now()
+
 	// Validate version
 	chVersion := vmm.CHVersion(version)
 	if !vmm.IsVersionSupported(chVersion) {
 		return 0, nil, fmt.Errorf("unsupported cloud-hypervisor version: %s", version)
 	}
 
 	// 1. Start the Cloud Hypervisor process
+	processStartTime := time.Now()
 	pid, err := vmm.StartProcess(ctx, p, chVersion, socketPath)
 	if err != nil {
 		return 0, nil, fmt.Errorf("start process: %w", err)
 	}
+	log.DebugContext(ctx, "CH process started", "pid", pid, "duration_ms", time.Since(processStartTime).Milliseconds())
 
 	// Setup cleanup to kill the process if subsequent steps fail
 	cu := cleanup.Make(func() {
@@ -125,6 +132,7 @@ func (s *Starter) RestoreVM(ctx context.Context, p *paths.Paths, version string,
 	}
 
 	// 3. Restore from snapshot via HTTP API
+	restoreAPIStart := time.Now()
 	sourceURL := "file://" + snapshotPath
 	restoreConfig := vmm.RestoreConfig{
 		SourceUrl: sourceURL,
@@ -137,9 +145,11 @@ func (s *Starter) RestoreVM(ctx context.Context, p *paths.Paths, version string,
 	if resp.StatusCode() != 204 {
 		return 0, nil, fmt.Errorf("restore failed with status %d: %s", resp.StatusCode(), string(resp.Body))
 	}
+	log.DebugContext(ctx, "CH restore API complete", "duration_ms", time.Since(restoreAPIStart).Milliseconds())
 
 	// Success - release cleanup to prevent killing the process
 	cu.Release()
+	log.DebugContext(ctx, "CH restore complete", "pid", pid, "total_duration_ms", time.Since(startTime).Milliseconds())
 	return pid, hv, nil
 }
 

lib/hypervisor/qemu/process.go

@@ -16,6 +16,7 @@ import (
 
 	"github.com/digitalocean/go-qemu/qmp/raw"
 	"github.com/onkernel/hypeman/lib/hypervisor"
+	"github.com/onkernel/hypeman/lib/logger"
 	"github.com/onkernel/hypeman/lib/paths"
 	"gvisor.dev/gvisor/pkg/cleanup"
 )
@@ -185,6 +186,9 @@ func (s *Starter) StartVM(ctx context.Context, p *paths.Paths, version string, s
 // RestoreVM starts QEMU and restores VM state from a snapshot.
 // The VM is in paused state after restore; caller should call Resume() to continue execution.
 func (s *Starter) RestoreVM(ctx context.Context, p *paths.Paths, version string, socketPath string, snapshotPath string) (int, hypervisor.Hypervisor, error) {
+	log := logger.FromContext(ctx)
+	startTime := time.Now()
+
 	// Get binary path
 	binaryPath, err := s.GetBinaryPath(p, version)
 	if err != nil {
@@ -201,10 +205,12 @@ func (s *Starter) RestoreVM(ctx context.Context, p *paths.Paths, version string,
 
 	// Load saved VM config from snapshot directory
 	// QEMU requires exact same command-line args as when snapshot was taken
+	configLoadStart := time.Now()
 	config, err := loadVMConfig(snapshotPath)
 	if err != nil {
 		return 0, nil, fmt.Errorf("load vm config from snapshot: %w", err)
 	}
+	log.DebugContext(ctx, "loaded VM config from snapshot", "duration_ms", time.Since(configLoadStart).Milliseconds())
 
 	instanceDir := filepath.Dir(socketPath)
 
@@ -249,11 +255,13 @@ func (s *Starter) RestoreVM(ctx context.Context, p *paths.Paths, version string,
 	cmd.Stdout = vmmLogFile
 	cmd.Stderr = vmmLogFile
 
+	processStartTime := time.Now()
 	if err := cmd.Start(); err != nil {
 		return 0, nil, fmt.Errorf("start qemu: %w", err)
 	}
 
 	pid := cmd.Process.Pid
+	log.DebugContext(ctx, "QEMU process started", "pid", pid, "duration_ms", time.Since(processStartTime).Milliseconds())
 
 	// Setup cleanup to kill the process if subsequent steps fail
 	cu := cleanup.Make(func() {
@@ -262,13 +270,15 @@ func (s *Starter) RestoreVM(ctx context.Context, p *paths.Paths, version string,
 	defer cu.Clean()
 
 	// Wait for socket to be ready
+	socketWaitStart := time.Now()
 	if err := waitForSocket(socketPath, 10*time.Second); err != nil {
 		vmmLogPath := filepath.Join(logsDir, "vmm.log")
 		if logData, readErr := os.ReadFile(vmmLogPath); readErr == nil && len(logData) > 0 {
 			return 0, nil, fmt.Errorf("%w; vmm.log: %s", err, string(logData))
 		}
 		return 0, nil, err
 	}
+	log.DebugContext(ctx, "QMP socket ready", "duration_ms", time.Since(socketWaitStart).Milliseconds())
 
 	// Create QMP client
 	hv, err := New(socketPath)
@@ -279,12 +289,15 @@ func (s *Starter) RestoreVM(ctx context.Context, p *paths.Paths, version string,
 	// Wait for incoming migration to complete
 	// QEMU loads the migration data from the exec subprocess
 	// After loading, VM is in paused state and ready for 'cont'
+	migrationWaitStart := time.Now()
 	if err := waitForMigrationComplete(hv.client, 30*time.Second); err != nil {
 		return 0, nil, fmt.Errorf("wait for migration: %w", err)
 	}
+	log.DebugContext(ctx, "migration complete", "duration_ms", time.Since(migrationWaitStart).Milliseconds())
 
 	// Success - release cleanup to prevent killing the process
 	cu.Release()
+	log.DebugContext(ctx, "QEMU restore complete", "pid", pid, "total_duration_ms", time.Since(startTime).Milliseconds())
 	return pid, hv, nil
 }
 

lib/instances/restore.go

@@ -56,16 +56,33 @@ func (m *manager) restoreInstance(
 
 	// 4. Recreate TAP device if network enabled
 	if stored.NetworkEnabled {
+		var networkSpan trace.Span
+		if m.metrics != nil && m.metrics.tracer != nil {
+			ctx, networkSpan = m.metrics.tracer.Start(ctx, "RestoreNetwork")
+		}
 		log.DebugContext(ctx, "recreating network for restore", "instance_id", id, "network", "default")
 		if err := m.networkManager.RecreateAllocation(ctx, id); err != nil {
+			if networkSpan != nil {
+				networkSpan.End()
+			}
 			log.ErrorContext(ctx, "failed to recreate network", "instance_id", id, "error", err)
 			return nil, fmt.Errorf("recreate network: %w", err)
 		}
+		if networkSpan != nil {
+			networkSpan.End()
+		}
 	}
 
 	// 5. Transition: Standby → Paused (start hypervisor + restore)
-	log.DebugContext(ctx, "restoring from snapshot", "instance_id", id, "snapshot_dir", snapshotDir)
+	var restoreSpan trace.Span
+	if m.metrics != nil && m.metrics.tracer != nil {
+		ctx, restoreSpan = m.metrics.tracer.Start(ctx, "RestoreFromSnapshot")
+	}
+	log.DebugContext(ctx, "restoring from snapshot", "instance_id", id, "snapshot_dir", snapshotDir, "hypervisor", stored.HypervisorType)
 	pid, hv, err := m.restoreFromSnapshot(ctx, stored, snapshotDir)
+	if restoreSpan != nil {
+		restoreSpan.End()
+	}
 	if err != nil {
 		log.ErrorContext(ctx, "failed to restore from snapshot", "instance_id", id, "error", err)
 		// Cleanup network on failure
@@ -80,8 +97,15 @@ func (m *manager) restoreInstance(
 	stored.HypervisorPID = &pid
 
 	// 6. Transition: Paused → Running (resume)
+	var resumeSpan trace.Span
+	if m.metrics != nil && m.metrics.tracer != nil {
+		ctx, resumeSpan = m.metrics.tracer.Start(ctx, "ResumeVM")
+	}
 	log.DebugContext(ctx, "resuming VM", "instance_id", id)
 	if err := hv.Resume(ctx); err != nil {
+		if resumeSpan != nil {
+			resumeSpan.End()
+		}
 		log.ErrorContext(ctx, "failed to resume VM", "instance_id", id, "error", err)
 		// Cleanup on failure
 		hv.Shutdown(ctx)
@@ -91,6 +115,9 @@ func (m *manager) restoreInstance(
 		}
 		return nil, fmt.Errorf("resume vm failed: %w", err)
 	}
+	if resumeSpan != nil {
+		resumeSpan.End()
+	}
 
 	// 8. Delete snapshot after successful restore
 	log.DebugContext(ctx, "deleting snapshot after successful restore", "instance_id", id)