diff --git a/pkg/machine/apple/apple.go b/pkg/machine/apple/apple.go index 329dc16075..63646f868b 100644 --- a/pkg/machine/apple/apple.go +++ b/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 diff --git a/pkg/machine/cleanup.go b/pkg/machine/cleanup.go index 97e45b2c6a..bd5e318b53 100644 --- a/pkg/machine/cleanup.go +++ b/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 { diff --git a/pkg/machine/e2e/start_test.go b/pkg/machine/e2e/start_test.go index 684c40bd61..e468aa3f7b 100644 --- a/pkg/machine/e2e/start_test.go +++ b/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) { diff --git a/pkg/machine/gvproxy_unix.go b/pkg/machine/gvproxy_unix.go index 413867b828..b7708c2bef 100644 --- a/pkg/machine/gvproxy_unix.go +++ b/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 diff --git a/pkg/machine/hyperv/stubber.go b/pkg/machine/hyperv/stubber.go index 334d7a8420..20f3cdd6b0 100644 --- a/pkg/machine/hyperv/stubber.go +++ b/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 diff --git a/pkg/machine/shim/host.go b/pkg/machine/shim/host.go index d1db58b47f..5a9fb027a9 100644 --- a/pkg/machine/shim/host.go +++ b/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 } diff --git a/pkg/machine/wsl/stubber.go b/pkg/machine/wsl/stubber.go index b86adf877a..f93f6fdba5 100644 --- a/pkg/machine/wsl/stubber.go +++ b/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()