VM boot & setup timeouts

cmd/imgbuilder/builder/build.go

@@ -53,6 +53,7 @@ func NewBuildContext(logger *slog.Logger, baseISOPath string, outPath string, sh
 		Drives: []vm.DriveConfig{{
 			Path: outPath,
 		}},
+		MemoryAlloc:            512,
 		UnrestrictedNetworking: true,
 		ShowDisplay:            showVMDisplay,
 		InstallBaseUtilities:   true,

cmd/root.go

@@ -26,7 +26,9 @@ func Execute() {
 
 var vmDebugFlag bool
 var unrestrictedNetworkingFlag bool
-var vmMemAllocFlag uint64
+var vmMemAllocFlag uint32
+var vmSSHSetupTimeoutFlag uint32
+var vmOSUpTimeoutFlag uint32
 
 // TODO: Version command.
 
@@ -39,5 +41,7 @@ func init() {
 
 	rootCmd.PersistentFlags().BoolVar(&vmDebugFlag, "vmdebug", false, "Enables the VM debug mode. This will open an accessible VM monitor. You can log in with root user and no password.")
 	rootCmd.PersistentFlags().BoolVar(&unrestrictedNetworkingFlag, "unrestricted-networking", false, "Enables unrestricted networking. This will allow the VM to connect to the internet.")
-	rootCmd.PersistentFlags().Uint64Var(&vmMemAllocFlag, "vm-mem-alloc", 512, "Specifies the VM memory allocation in KiB")
+	rootCmd.PersistentFlags().Uint32Var(&vmMemAllocFlag, "vm-mem-alloc", 512, "Specifies the VM memory allocation in KiB")
+	rootCmd.PersistentFlags().Uint32Var(&vmOSUpTimeoutFlag, "vm-os-up-timeout", 30, "Specifies the VM OS-up timeout in seconds.")
+	rootCmd.PersistentFlags().Uint32Var(&vmSSHSetupTimeoutFlag, "vm-ssh-setup-timeout", 60, "Specifies the VM SSH server setup timeout in seconds. This cannot be lower than the OS-up timeout.")
 }

cmd/utils.go

@@ -10,6 +10,7 @@ import (
 	"runtime"
 	"sync"
 	"syscall"
+	"time"
 
 	"log/slog"
 
@@ -69,6 +70,9 @@ func runVM(passthroughArg string, fn func(context.Context, *vm.VM, *vm.FileManag
 		USBDevices:               passthroughConfig,
 		ExtraPortForwardingRules: forwardPortsRules,
 
+		OSUpTimeout:  time.Duration(vmOSUpTimeoutFlag) * time.Second,
+		SSHUpTimeout: time.Duration(vmSSHSetupTimeoutFlag) * time.Second,
+
 		UnrestrictedNetworking: unrestrictedNetworking,
 		ShowDisplay:            vmDebugFlag,
 	}

utils/errors.go

@@ -8,10 +8,10 @@ import (
 )
 
 func WrapErrWithLog(err error, msg, log string) error {
-	return errors.Wrapf(err, "%v %v", msg, GetLogErrMsg(log))
+	return errors.Wrapf(err, "%v %v", msg, GetLogErrMsg(log, "log"))
 }
 
-func GetLogErrMsg(s string) string {
+func GetLogErrMsg(s string, logLabel string) string {
 	logToInclude := strings.ReplaceAll(s, "\n", "\\n")
 	logToInclude = strings.TrimSuffix(logToInclude, "\\n")
 	logToInclude = ClearUnprintableChars(logToInclude, false)
@@ -22,5 +22,5 @@ func GetLogErrMsg(s string) string {
 		logToInclude = fmt.Sprintf("[%v chars trimmed]", origLogLen) + logToInclude[len(logToInclude)-maxLogLen:]
 	}
 
-	return fmt.Sprintf("(log: '%v')", logToInclude)
+	return fmt.Sprintf("(%v: '%v')", logLabel, logToInclude)
 }

vm/ssh.go

@@ -121,7 +121,7 @@ func (vm *VM) sshSetup() (ssh.Signer, error) {
 		case <-vm.ctx.Done():
 			return nil, vm.ctx.Err()
 		case <-time.After(time.Until(deadline)):
-			return nil, fmt.Errorf("setup command timed out %v", utils.GetLogErrMsg(stdOutErrBuf.String()))
+			return nil, fmt.Errorf("setup command timed out %v", utils.GetLogErrMsg(stdOutErrBuf.String(), "stdout/stderr log"))
 		case data := <-vm.serialStdoutCh:
 			prefix := []byte("SERIAL STATUS: ")
 			stdOutErrBuf.WriteString(utils.ClearUnprintableChars(string(data), true))
@@ -132,7 +132,7 @@ func (vm *VM) sshSetup() (ssh.Signer, error) {
 
 				if data[len(prefix)] != '0' {
 					fmt.Fprintf(os.Stderr, "SSH SETUP FAILURE:\n%v", stdOutErrBuf.String())
-					return nil, fmt.Errorf("non-zero setup command status code: '%v' %v", string(data[len(prefix)]), utils.GetLogErrMsg(stdOutErrBuf.String()))
+					return nil, fmt.Errorf("non-zero setup command status code: '%v' %v", string(data[len(prefix)]), utils.GetLogErrMsg(stdOutErrBuf.String(), "stdout/stderr log"))
 				}
 
 				return sshSigner, nil

vm/vm.go

@@ -43,7 +43,10 @@ type VM struct {
 	serialReader  *bufio.Reader
 	serialWrite   *io.PipeWriter
 	serialWriteMu sync.Mutex
-	stderrBuf     *bytes.Buffer
+	qemuStderrBuf *bytes.Buffer
+
+	osUpTimeout  time.Duration
+	sshUpTimeout time.Duration
 
 	serialStdoutCh chan []byte
 
@@ -61,11 +64,15 @@ type VMConfig struct {
 	CdromImagePath string
 	Drives         []DriveConfig
 
-	MemoryAlloc uint64 // In KiB.
+	MemoryAlloc uint32 // In KiB.
 
 	USBDevices               []USBDevicePassthroughConfig
 	ExtraPortForwardingRules []PortForwardingRule
 
+	// Timeouts
+	OSUpTimeout  time.Duration
+	SSHUpTimeout time.Duration
+
 	// Mostly debug-related options.
 	UnrestrictedNetworking bool
 	ShowDisplay            bool
@@ -175,6 +182,24 @@ func NewVM(logger *slog.Logger, cfg VMConfig) (*VM, error) {
 		return nil, fmt.Errorf("cannot install base utilities with unrestricted networking disabled")
 	}
 
+	// NOTE: The default timeouts below have no relation to the default
+	// timeouts set by the CLI. These work only if no timeout was supplied
+	// in the config programmatically. Defaults set here are quite conservative.
+	osUpTimeout := time.Second * 60
+	if cfg.OSUpTimeout != 0 {
+		osUpTimeout = cfg.OSUpTimeout
+	}
+	sshUpTimeout := time.Second * 120
+	if cfg.SSHUpTimeout != 0 {
+		sshUpTimeout = cfg.SSHUpTimeout
+	}
+
+	if sshUpTimeout < osUpTimeout {
+		return nil, fmt.Errorf("vm ssh setup timeout cannot be lower than os up timeout")
+	}
+
+	// No errors beyond this point.
+
 	sysRead, userWrite := io.Pipe()
 	userRead, sysWrite := io.Pipe()
 
@@ -207,7 +232,10 @@ func NewVM(logger *slog.Logger, cfg VMConfig) (*VM, error) {
 		serialRead:    userRead,
 		serialReader:  userReader,
 		serialWrite:   userWrite,
-		stderrBuf:    stderrBuf,
+		qemuStderrBuf: stderrBuf,
+
+		osUpTimeout:  osUpTimeout,
+		sshUpTimeout: sshUpTimeout,
 	}
 
 	vm.resetSerialStdout()
@@ -235,6 +263,27 @@ func (vm *VM) Run() error {
 		globalErrs = append(globalErrs, err, errors.Wrap(vm.Cancel(), "cancel on error"))
 	}
 
+	bootReadyCh := make(chan struct{})
+
+	go func() {
+		select {
+		case <-time.After(vm.osUpTimeout):
+			vm.logger.Warn("A VM boot timeout detected, consider running with --vmdebug to investigate")
+			globalErrFn(fmt.Errorf("vm boot timeout %v", utils.GetLogErrMsg(string(vm.consumeSerialStdout()), "serial log")))
+		case <-bootReadyCh:
+			vm.logger.Info("The VM is up, setting it up")
+		}
+	}()
+
+	go func() {
+		select {
+		case <-time.After(vm.sshUpTimeout):
+			globalErrFn(fmt.Errorf("vm setup timeout %v", utils.GetLogErrMsg(string(vm.consumeSerialStdout()), "serial log")))
+		case <-vm.sshReadyCh:
+			vm.logger.Info("The VM is ready")
+		}
+	}()
+
 	vm.logger.Info("Booting the VM")
 
 	go func() {
@@ -249,7 +298,8 @@ func (vm *VM) Run() error {
 			return
 		}
 
-		vm.logger.Info("Setting the VM up")
+		// This will disable the timeout-handling goroutine.
+		close(bootReadyCh)
 
 		sshSigner, err := vm.sshSetup()
 		if err != nil {
@@ -284,8 +334,6 @@ func (vm *VM) Run() error {
 
 		// This is to notify everyone waiting for SSH to be up that it's ready to go.
 		close(vm.sshReadyCh)
-
-		vm.logger.Info("The VM is ready")
 	}()
 
 	_, err = vm.cmd.Process.Wait()
@@ -296,14 +344,14 @@ func (vm *VM) Run() error {
 			errors.Wrap(cancelErr, "cancel"),
 		)
 
-		return fmt.Errorf("%w %v", combinedErr, utils.GetLogErrMsg(vm.stderrBuf.String()))
+		return fmt.Errorf("%w %v", combinedErr, utils.GetLogErrMsg(vm.qemuStderrBuf.String(), "qemu stderr log"))
 	}
 
 	combinedErr := multierr.Combine(
 		append(globalErrs, errors.Wrap(cancelErr, "cancel on exit"))...,
 	)
 	if combinedErr != nil {
-		return fmt.Errorf("%w %v", combinedErr, utils.GetLogErrMsg(vm.stderrBuf.String()))
+		return fmt.Errorf("%w %v", combinedErr, utils.GetLogErrMsg(vm.qemuStderrBuf.String(), "qemu stderr log"))
 	}
 
 	return nil
@@ -389,7 +437,7 @@ func (vm *VM) runVMLoginHandler() error {
 	for {
 		select {
 		case <-vm.ctx.Done():
-			return nil
+			return vm.ctx.Err()
 		case <-time.After(time.Second):
 			peek, err := vm.serialReader.Peek(vm.serialReader.Buffered())
 			if err != nil {
@@ -414,6 +462,19 @@ func (vm *VM) resetSerialStdout() {
 	vm.serialStdoutCh = make(chan []byte, 32)
 }
 
+func (vm *VM) consumeSerialStdout() []byte {
+	buf := bytes.NewBuffer(nil)
+
+	for {
+		select {
+		case data := <-vm.serialStdoutCh:
+			buf.Write(data)
+		default:
+			return buf.Bytes()
+		}
+	}
+}
+
 func (vm *VM) DialSSH() (*ssh.Client, error) {
 	if vm.sshConf == nil {
 		return nil, ErrSSHUnavailable