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

Fix signal handling during machine start on macOS

Author: Luap99

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