Merge pull request #28991 from l0rd/fix-machine-start-signal-handling

Fix signal handling during machine start on macOS

pkg/machine/apple/apple.go

@@ -9,6 +9,7 @@ import (
 	"net"
 	"os"
 	"os/exec"
+	"os/signal"
 	"syscall"
 	"time"
 
@@ -72,17 +73,14 @@ func StartGenericAppleVM(mc *vmconfigs.MachineConfig, cmdBinary string, bootload
 		return nil, nil, err
 	}
 	// Set user networking with gvproxy
-
 	gvproxySocket, err := mc.GVProxySocket()
 	if err != nil {
 		return nil, nil, err
 	}
-
 	// Wait on gvproxy to be running and aware
 	if err := sockets.WaitForSocketWithBackoffs(gvProxyMaxBackoffAttempts, gvProxyWaitBackoff, gvproxySocket.GetPath(), "gvproxy"); err != nil {
 		return nil, nil, err
 	}
-
 	netDevice.SetUnixSocketPath(gvproxySocket.GetPath())
 
 	// create a one-time virtual machine for starting because we dont want all this information in the
@@ -244,24 +242,62 @@ func StartGenericAppleVM(mc *vmconfigs.MachineConfig, cmdBinary string, bootload
 		return nil, nil, err
 	}
 
-	returnFunc := func() error {
+	// Start a goroutine that will evenutally propagate a
+	// terminate signal to the VM process.
+	// If the user decides to abort `podman machine start`
+	// while the VM is starting, we want the VM to be stopped
+	// too. Or the machine will be left in an inconsistent
+	// state. Note that the goroutine will wait until the
+	// the main goroutine completes.
+	term := make(chan os.Signal, 1)
+	signal.Notify(term, os.Interrupt, syscall.SIGTERM)
+	// Get the PID first because cmd.Process will
+	// be released in the main thread
+	pid := cmd.Process.Pid
+	go func() {
+		<-term
+		logrus.Debugf("Termination signal forwarded to the VM process (PID: %d)\n", pid)
+		p, err := os.FindProcess(pid)
+		if err != nil {
+			logrus.Errorf("Failed to find process %d: %v", pid, err)
+			return
+		}
+		err = p.Signal(os.Interrupt)
+		if err != nil {
+			logrus.Errorf("Termination signal received, but terminating the VM process (PID: %d) failed: %v", pid, err)
+			return
+		}
+		// Wait and release the resources associated with the process
+		if _, err := p.Wait(); err != nil {
+			logrus.Debugf("Failed waiting for the process after terminating it: %v", err)
+		}
+	}()
+
+	// waitForReadyFunc is the callback that the caller of StartVM()
+	// uses to block its execution until the the VM is ready or an error
+	// occurs
+	waitForReadyFunc := func() error {
 		processErrChan := make(chan error)
 		ctx, cancel := context.WithCancel(context.Background())
 		defer cancel()
+		// The VM readiness will be communicated on readyChan. In the
+		// meantime, the following goroutine checks every 500ms that the VM
+		// process is running. If it's not, returns an error on processErrChan.
 		go func() {
 			defer close(processErrChan)
+			ticker := time.NewTicker(500 * time.Millisecond)
+			defer ticker.Stop()
 			for {
-				select {
-				case <-ctx.Done():
-					return
-				default:
-				}
 				if err := CheckProcessRunning(cmdBinary, cmd.Process.Pid); err != nil {
 					processErrChan <- err
 					return
 				}
-				// lets poll status every half second
-				time.Sleep(500 * time.Millisecond)
+				select {
+				case <-ctx.Done():
+					logrus.Debug("VM waitForReadyFunc goroutine: ctx done")
+					return
+				case <-ticker.C:
+				}
 			}
 		}()
 
@@ -279,7 +315,26 @@ func StartGenericAppleVM(mc *vmconfigs.MachineConfig, cmdBinary string, bootload
 		}
 		return nil
 	}
-	return cmd.Process.Release, returnFunc, nil
+
+	// releaseCmdFunc is the callback that the caller of StartVM()
+	// uses to release the resources associated with cmd.Process.
+	// It's important to execute it after waitForReadyFunc completes,
+	// otherwise cmd.Process methods won't work anymore.
+	relCmdFunc := func() error {
+		if err := cmd.Process.Release(); err != nil {
+			logrus.Errorf("error releasing VM Start command associated resources: %v", err)
+		}
+		if ignitionSocket != nil {
+			if err := ignitionSocket.Delete(); err != nil {
+				logrus.Errorf("unable to delete ignition socket: %v", err)
+			}
+		}
+		if err := readySocket.Delete(); err != nil {
+			logrus.Errorf("unable to delete ready socket: %v", err)
+		}
+		return nil
+	}
+	return relCmdFunc, waitForReadyFunc, nil
 }
 
 // CheckProcessRunning checks non blocking if the pid exited

pkg/machine/cleanup.go

@@ -1,8 +1,10 @@
 package machine
 
 import (
+	"fmt"
 	"os"
 	"os/signal"
+	"slices"
 	"sync"
 	"syscall"
 
@@ -22,7 +24,7 @@ func (c *CleanupCallback) CleanIfErr(err *error) {
 	c.clean()
 }
 
-func (c *CleanupCallback) CleanOnSignal() {
+func (c *CleanupCallback) CleanOnSignal(quiet bool) {
 	ch := make(chan os.Signal, 1)
 	signal.Notify(ch, os.Interrupt, syscall.SIGTERM)
 
@@ -31,28 +33,41 @@ func (c *CleanupCallback) CleanOnSignal() {
 		return
 	}
 
+	if !quiet {
+		fmt.Println("Received a terminate signal")
+	}
 	c.clean()
+	if !quiet {
+		fmt.Println("Machine command rollback completed")
+	}
 	os.Exit(1)
 }
 
 func (c *CleanupCallback) clean() {
+	// When a term signal is received the cleanup can be invoked
+	// concurrently in 2 goroutines:
+	//
+	//    - signal flow: a termination signal is received and the
+	//                   goroutine where CleanOnSignal() is running is
+	//                   unblocked and starts invoking the callbacks
+	//    - error flow: an error is returned in the main goroutine, after
+	//                  the signal is received, and CleanIfErr() is invoked,
+	//                  but c.Funcs has been set to nil and therefore no
+	//                  callbacks is exec in this goroutine
+	//
+	// When this is the case the second goroutine should be blocked until
+	// the first goroutine comples the cleanup. c.Funcs is also set to nil
+	// so that cleanup doesn't happen twice.
 	c.mu.Lock()
-	// Claim exclusive usage by copy and resetting to nil
 	funcs := c.Funcs
 	c.Funcs = nil
-	c.mu.Unlock()
-
-	// Already claimed or none set
-	if funcs == nil {
-		return
-	}
-
-	// Cleanup functions can now exclusively be run
-	for _, cleanfunc := range funcs {
+	// Cleanup functions invoked in reverse registration order
+	for _, cleanfunc := range slices.Backward(funcs) {
 		if err := cleanfunc(); err != nil {
 			logrus.Error(err)
 		}
 	}
+	c.mu.Unlock()
 }
 
 func CleanUp() CleanupCallback {

pkg/machine/e2e/start_test.go

@@ -5,8 +5,10 @@ import (
 	"fmt"
 	"net"
 	"net/url"
+	"os/exec"
 	"strconv"
 	"sync"
+	"syscall"
 	"time"
 
 	jsoniter "github.com/json-iterator/go"
@@ -349,6 +351,65 @@ var _ = Describe("podman machine start", func() {
 		Expect(sshCertFile).To(Exit(0))
 		Expect(sshCertFile.outputToString()).To(Equal(certFileName))
 	})
+	It("start interrupted by SIGTERM while waiting for VM start", func() {
+		if !isVmtype(define.AppleHvVirt) && !isVmtype(define.LibKrun) {
+			Skip("SIGTERM interruption is supported on macOS only")
+		}
+		// Use the provider binary to pgrep the VM process
+		var vmProcess string
+		switch testProvider.VMType() {
+		case define.AppleHvVirt:
+			vmProcess = "vfkit"
+		case define.LibKrun:
+			vmProcess = "krunkit"
+		default:
+		}
+
+		i := new(initMachine)
+		initSession, err := mb.setCmd(i.withImage(mb.imagePath)).run()
+		Expect(err).ToNot(HaveOccurred())
+		Expect(initSession).To(Exit(0))
+
+		s := new(startMachine)
+		startSession, err := mb.setCmd(s).runWithoutWait()
+		Expect(err).ToNot(HaveOccurred())
+
+		// Wait 45s for the VM process spawned by `podman machine start`
+		Eventually(func() error {
+			_, err := exec.Command("pgrep", vmProcess).Output()
+			return err
+		}, 45*time.Second, 500*time.Millisecond).Should(Succeed())
+
+		// Send a term signal now (podman machine start is waiting for
+		// the VM process readiness)
+		startSession.Signal(syscall.SIGTERM)
+
+		// Wait 30s for the podman machine start process to return (no deadlock)
+		Eventually(startSession, 30*time.Second).Should(Exit())
+		Expect(startSession.ExitCode()).ToNot(Equal(0))
+
+		// Wait 30s for the VM process to return (SIGTERM has been forwarded)
+		Eventually(func() error {
+			_, err := exec.Command("pgrep", vmProcess).Output()
+			return err
+		}, 30*time.Second, 500*time.Millisecond).ShouldNot(Succeed())
+
+		// Verify machine state is Stopped
+		inspect := new(inspectMachine)
+		inspectSession, err := mb.setCmd(inspect.withFormat("{{.State}}")).run()
+		Expect(err).ToNot(HaveOccurred())
+		Expect(inspectSession).To(Exit(0))
+		Expect(inspectSession.outputToString()).To(Equal(define.Stopped))
+
+		// Verify no orphan gvproxy
+		_, err = pgrep("gvproxy")
+		Expect(err).To(HaveOccurred(), "gvproxy should not be running after SIGTERM cleanup")
+
+		// Restart without interrupting and confirm that completes without error
+		startSession, err = mb.setCmd(s).run()
+		Expect(err).ToNot(HaveOccurred())
+		Expect(startSession).To(Exit(0))
+	})
 })
 
 func mapToPort(uris []string) ([]string, error) {

pkg/machine/gvproxy_unix.go

@@ -5,6 +5,7 @@ package machine
 import (
 	"errors"
 	"fmt"
+	"os"
 	"syscall"
 	"time"
 
@@ -42,10 +43,10 @@ func backoffForProcess(p *psutil.Process) error {
 		// double the time
 		sleepInterval += sleepInterval
 	}
-	return fmt.Errorf("process %d has not ended", p.Pid)
+	return fmt.Errorf("process has not ended (PID %d)", p.Pid)
 }
 
-// / waitOnProcess takes a pid and sends a sigterm to it. it then waits for the
+// waitOnProcess takes a pid and sends a sigterm to it. it then waits for the
 // process to not exist.  if the sigterm does not end the process after an interval,
 // then sigkill is sent.  it also waits for the process to exit after the sigkill too.
 func waitOnProcess(processID int) error {
@@ -64,7 +65,35 @@ func waitOnProcess(processID int) error {
 		return nil
 	}
 
-	if err := p.Kill(); err != nil {
+	// Start a goroutine that waits until the gvproxy process completes.
+	// This is necessary to reaps the process and so that Process.IsRunning()
+	// in backoffForProcess() returns false. Otherwise the process will
+	// be defunct and backoffForProcess fails because Process.IsRunning()
+	// returns true
+	go func() {
+		gv, err := os.FindProcess(processID)
+		if err != nil {
+			logrus.Errorf("failed to find process %d: %v", processID, err)
+			return
+		}
+		if _, err = gv.Wait(); err != nil {
+			logrus.Debugf("gvproxy exited: %v", err)
+		}
+	}()
+
+	if err = p.Terminate(); err != nil {
+		if errors.Is(err, syscall.ESRCH) {
+			logrus.Debugf("Gvproxy already dead, exiting cleanly")
+			return nil
+		}
+		return err
+	}
+
+	if err = backoffForProcess(p); err == nil {
+		return nil
+	}
+
+	if err = p.Kill(); err != nil {
 		if errors.Is(err, syscall.ESRCH) {
 			logrus.Debugf("Gvproxy already dead, exiting cleanly")
 			return nil

pkg/machine/hyperv/stubber.go

@@ -64,7 +64,7 @@ func (h HyperVStubber) CreateVM(_ define.CreateVMOpts, mc *vmconfigs.MachineConf
 	callbackFuncs := machine.CleanUp()
 	defer callbackFuncs.CleanIfErr(&err)
 	callbackFuncs.Add(createErrorLogCallback(&err))
-	go callbackFuncs.CleanOnSignal()
+	go callbackFuncs.CleanOnSignal(false)
 
 	hwConfig := hypervctl.HardwareConfig{
 		CPUs:     uint16(mc.Resources.CPUs),
@@ -220,7 +220,7 @@ func (h HyperVStubber) MountVolumesToVM(mc *vmconfigs.MachineConfig, _ bool) err
 	)
 	callbackFuncs := machine.CleanUp()
 	defer callbackFuncs.CleanIfErr(&err)
-	go callbackFuncs.CleanOnSignal()
+	go callbackFuncs.CleanOnSignal(true)
 
 	if len(mc.Mounts) == 0 {
 		return nil
@@ -568,7 +568,7 @@ func (h HyperVStubber) StartVM(mc *vmconfigs.MachineConfig) (func() error, func(
 	callbackFuncs := machine.CleanUp()
 	defer callbackFuncs.CleanIfErr(&err)
 	callbackFuncs.Add(createErrorLogCallback(&err))
-	go callbackFuncs.CleanOnSignal()
+	go callbackFuncs.CleanOnSignal(true)
 
 	if mc.IsFirstBoot() {
 		// this is added because if the machine does not start

pkg/machine/shim/host.go

@@ -6,12 +6,11 @@ import (
 	"fmt"
 	"io"
 	"os"
-	"os/signal"
 	"path"
 	"path/filepath"
 	"runtime"
 	"strings"
-	"syscall"
+	"sync"
 	"time"
 
 	"github.com/hashicorp/go-multierror"
@@ -86,7 +85,10 @@ func Init(opts machineDefine.InitOptions, mp vmconfigs.VMProvider) error {
 			callbackFuncs.CleanIfErr(&err)
 		}
 	}()
-	go callbackFuncs.CleanOnSignal()
+	// The following goroutine will block waiting
+	// for a termination signal. If no signal is received
+	// the routine is aborted when the main goroutine terminates.
+	go callbackFuncs.CleanOnSignal(false)
 
 	dirs, err := env.GetMachineDirs(mp.VMType())
 	if err != nil {
@@ -464,21 +466,52 @@ func stopLocked(mc *vmconfigs.MachineConfig, mp vmconfigs.VMProvider, dirs *mach
 }
 
 func Start(mc *vmconfigs.MachineConfig, mp vmconfigs.VMProvider, opts machine.StartOptions, updateSystemConn *bool) error {
-	var updateDefaultConnection bool
+	var (
+		err                     error
+		updateDefaultConnection bool
+	)
 
 	defaultBackoff := 500 * time.Millisecond
 	maxBackoffs := 6
-	signalChanClosed := false
+
+	// startup rollaback functions
+	// called if an error occurs or if a
+	// a termination signal is sent
+	callbackFuncs := machine.CleanUp()
+	defer callbackFuncs.CleanIfErr(&err)
+	// The following goroutine will block waiting
+	// for a termination signal. If no signal is received
+	// the routine is aborted when the main goroutine terminates.
+	go callbackFuncs.CleanOnSignal(opts.Quiet)
 
 	dirs, err := env.GetMachineDirs(mp.VMType())
 	if err != nil {
 		return err
 	}
+
 	if !opts.ReExec {
 		mc.Lock()
-		defer mc.Unlock()
+		// Use sync.Once to ensure that `mc.Unlock()` is called
+		// only once.
+		// Otherwise, when errors occur, it's called twice and panics:
+		//   - defer mcunlock()
+		//   - defer callbackFuncs.CleanIfErr()
+		var mcUnlockOnce sync.Once
+		mcunlock := func() error { //nolint: unparam
+			mcUnlockOnce.Do(func() {
+				logrus.Debug("unlocking machine config")
+				mc.Unlock()
+			})
+			return nil
+		}
+		callbackFuncs.Add(mcunlock)
+		// callbackFuncs are invoked when errors occurs or term signals
+		// are received. Thus we need to defer mcunlock for when Start()
+		// completes successfully
+		defer func() { _ = mcunlock() }()
 	}
-	if err := mc.Refresh(); err != nil {
+
+	if err = mc.Refresh(); err != nil {
 		return fmt.Errorf("reload config: %w", err)
 	}
 
@@ -498,7 +531,21 @@ func Start(mc *vmconfigs.MachineConfig, mp vmconfigs.VMProvider, opts machine.St
 			return err
 		}
 		startLock.Lock()
-		defer startLock.Unlock()
+		// Use sync.Once to ensure that `startLock.Unlock()` is called
+		// only once.
+		// Otherwise, when errors occur, it's called twice and panics:
+		//   - defer startLockUnlock()
+		//   - defer callbackFuncs.CleanIfErr()
+		var startLockOnce sync.Once
+		startLockUnlock := func() error { //nolint: unparam
+			startLockOnce.Do(startLock.Unlock)
+			return nil
+		}
+		callbackFuncs.Add(startLockUnlock)
+		// callbackFuncs are invoked when errors occurs or term signals
+		// are received. Thus we need to defer startLockUnlock for when
+		// Start() completes successfully
+		defer func() { _ = startLockUnlock() }()
 
 		if err := checkExclusiveActiveVM(mp, mc); err != nil {
 			return err
@@ -540,42 +587,27 @@ func Start(mc *vmconfigs.MachineConfig, mp vmconfigs.VMProvider, opts machine.St
 		}
 	}
 
-	// if the machine cannot continue starting due to a signal, ensure the state
-	// reflects the machine is no longer starting
-	signalChan := make(chan os.Signal, 1)
-	signal.Notify(signalChan, os.Interrupt, syscall.SIGTERM, syscall.SIGPIPE)
-	go func() {
-		sig, ok := <-signalChan
-		if ok {
-			mc.Starting = false
-			logrus.Error("signal received when starting the machine: ", sig)
-
-			if err := mc.Write(); err != nil {
-				logrus.Error(err)
-			}
-
-			os.Exit(1)
-		}
-	}()
-
 	// Set starting to true
 	mc.Starting = true
-	if err := mc.Write(); err != nil {
+	if err = mc.Write(); err != nil {
+		mc.Starting = false
 		logrus.Error(err)
 	}
 
 	// Set starting to false on exit
-	defer func() {
+	startingFalse := func() error {
 		mc.Starting = false
-		if err := mc.Write(); err != nil {
-			logrus.Error(err)
+		if writeErr := mc.Write(); writeErr != nil {
+			logrus.Error("Error writing machine starting state to false: ", writeErr)
+			return writeErr
 		}
-
-		if !signalChanClosed {
-			signal.Stop(signalChan)
-			close(signalChan)
-		}
-	}()
+		return nil
+	}
+	callbackFuncs.Add(startingFalse)
+	// callbackFuncs are invoked when errors occurs or term signals
+	// are received. Thus we need to defer startingFalse for when
+	// Start() completes successfully
+	defer func() { _ = startingFalse() }()
 
 	gvproxyPidFile, err := dirs.RuntimeDir.AppendToNewVMFile("gvproxy.pid", nil)
 	if err != nil {
@@ -588,42 +620,41 @@ func Start(mc *vmconfigs.MachineConfig, mp vmconfigs.VMProvider, opts machine.St
 		return err
 	}
 
-	callBackFuncs := machine.CleanUp()
-	defer callBackFuncs.CleanIfErr(&err)
-	go callBackFuncs.CleanOnSignal()
-
-	// Clean up gvproxy if start fails
-	cleanGV := func() error {
-		return machine.CleanupGVProxy(*gvproxyPidFile)
+	// Stop gvproxy if Start() fails or termination signal is received
+	cleanGv := func() error {
+		if cleanGvErr := machine.CleanupGVProxy(*gvproxyPidFile); cleanGvErr != nil {
+			return fmt.Errorf("unable to clean up gvproxy: %w", cleanGvErr)
+		}
+		return nil
 	}
-	callBackFuncs.Add(cleanGV)
+	callbackFuncs.Add(cleanGv)
 
 	// if there are generic things that need to be done, a preStart function could be added here
 	// should it be extensive
 
-	// releaseFunc is if the provider starts a vm using a go command
-	// and we still need control of it while it is booting until the ready
-	// socket is tripped
-	releaseCmd, WaitForReady, err := mp.StartVM(mc)
+	// StartVM spawns the VM process and returns two callback functions:
+	// - releaseCmd: releases any resource associated with the VM
+	//               Cmd.Process (typically cmd.Process.Release())
+	// - waitForReady: waits until the VM process is ready and returns an
+	//                 error it fails to start
+	releaseCmd, waitForReady, err := mp.StartVM(mc)
 	if err != nil {
 		return err
 	}
-
-	if WaitForReady == nil {
+	if releaseCmd != nil { // some providers can return nil here (hyperv)
+		callbackFuncs.Add(releaseCmd)
+		// callbackFuncs are invoked when errors occurs or term signals
+		// are received. Thus we need to defer releaseCmd for when
+		// Start() completes successfully
+		defer func() { _ = releaseCmd() }()
+	}
+	if waitForReady == nil {
 		return errors.New("no valid wait function returned")
 	}
-
-	if err := WaitForReady(); err != nil {
+	if err = waitForReady(); err != nil {
 		return err
 	}
 
-	if releaseCmd != nil && releaseCmd() != nil { // some providers can return nil here (hyperv)
-		if err := releaseCmd(); err != nil {
-			// I think it is ok for a "light" error?
-			logrus.Error(err)
-		}
-	}
-
 	if !opts.NoInfo && !mc.HostUser.Rootful {
 		machine.PrintRootlessWarning(mc.Name)
 	}
@@ -650,17 +681,12 @@ func Start(mc *vmconfigs.MachineConfig, mp vmconfigs.VMProvider, opts machine.St
 		return errors.New(msg)
 	}
 
-	// now that the machine has transitioned into the running state, we don't need a goroutine listening for SIGINT or SIGTERM to handle state
-	signal.Stop(signalChan)
-	close(signalChan)
-	signalChanClosed = true
-
-	if err := proxyenv.ApplyProxies(mc); err != nil {
+	if err = proxyenv.ApplyProxies(mc); err != nil {
 		return err
 	}
 
 	// mount the volumes to the VM
-	if err := mp.MountVolumesToVM(mc, opts.Quiet); err != nil {
+	if err = mp.MountVolumesToVM(mc, opts.Quiet); err != nil {
 		return err
 	}
 

pkg/machine/wsl/stubber.go

@@ -30,7 +30,7 @@ func (w WSLStubber) CreateVM(opts define.CreateVMOpts, mc *vmconfigs.MachineConf
 	// cleanup half-baked files if init fails at any point
 	callbackFuncs := machine.CleanUp()
 	defer callbackFuncs.CleanIfErr(&err)
-	go callbackFuncs.CleanOnSignal()
+	go callbackFuncs.CleanOnSignal(false)
 	mc.WSLHypervisor = new(vmconfigs.WSLConfig)
 
 	_ = setupWslProxyEnv()