Even StopVM() is timing out, Firecracker process must be killed

Before the change, s.shimCancel() was only called by the goroutine.
So the StopVM() couldn't guarantee that the VMM is killed at the end
of the request.

Signed-off-by: Kazuyoshi Kato <[email protected]>

Author: kzys

runtime/jailer.go

@@ -56,7 +56,7 @@ type jailer interface {
 	// drive file
 	StubDrivesOptions() []FileOpt
 
-	// Stop the jailer as a way that the process can interpreted (e.g. SIGTERM).
+	// Stop the jailer as a way that is visible from the user-level process (e.g. SIGTERM).
 	Stop() error
 
 	// Close will do any necessary cleanup that the jailer has accrued.

runtime/service.go

@@ -74,6 +74,7 @@ const (
 	firecrackerStartTimeout = 5 * time.Second
 	defaultStopVMTimeout    = 5 * time.Second
 	defaultShutdownTimeout  = 5 * time.Second
+	jailerStopTimeout       = 3 * time.Second
 
 	// StartEventName is the topic published to when a VM starts
 	StartEventName = "/firecracker-vm/start"
@@ -1171,54 +1172,80 @@ func (s *service) Shutdown(requestCtx context.Context, req *taskAPI.ShutdownRequ
 	return &ptypes.Empty{}, nil
 }
 
-// shutdown will stop the VMM within the provided timeout. It attempts to shutdown gracefully by having
-// agent stop (which is presumed to cause the VM to begin a reboot) and then waiting for the VMM process
-// to exit (via the s.shimCtx.Done() channel). If that fails, StopVMM will be called to force a shutdown (currently
-// via sending SIGTERM). If that fails, the VMM will still be killed via SIGKILL when the shimCtx is canceled.
 func (s *service) shutdown(
 	requestCtx context.Context,
 	timeout time.Duration,
 	req *taskAPI.ShutdownRequest,
 ) error {
-	shutdownCtx, cancel := context.WithTimeout(requestCtx, timeout)
-	defer cancel()
+	s.logger.Info("stopping the VM")
+
 	go func() {
-		// Once the shutdown procedure is done, the shim needs to shutdown too.
-		// This also ensures that if the VMM is still alive, it will receive a
-		// SIGKILL via exec.CommandContext
-		<-shutdownCtx.Done()
-		s.shimCancel()
+		s.shutdownLoop(requestCtx, timeout, req)
 	}()
 
-	s.logger.Info("stopping the VM")
-
-	// Try to tell agent to exit, causing the VM to begin a reboot. If that
-	// fails, try to forcibly stop the VMM. If that too fails, just cancel
-	// the shutdownCtx to fast-path to the VMM getting SIGKILL.
-	_, shutdownErr := s.agentClient.Shutdown(shutdownCtx, req)
-	if shutdownErr != nil {
-		s.logger.WithError(shutdownErr).Error("failed to shutdown VM agent")
-		stopVMMErr := s.machine.StopVMM()
-		if stopVMMErr != nil {
-			s.logger.WithError(stopVMMErr).Error("failed to forcibly stop VMM")
-			cancel()
-		}
+	err := s.machine.Wait(context.Background())
+	if err == nil {
+		return nil
 	}
+	return status.Error(codes.DeadlineExceeded, fmt.Sprintf("the VMM was killed forcibly: %v", err))
+}
 
-	// wait for the shimCtx to be done, which means the VM has exited and we're ready
-	// to shutdown
-	<-s.shimCtx.Done()
-	if shutdownCtx.Err() == context.DeadlineExceeded {
-		return status.Error(codes.DeadlineExceeded,
-			"timed out waiting for VM shutdown, VMM was sent SIGKILL")
-	}
+// shutdownLoop sends multiple different shutdown requests to stop the VMM.
+// 1) send a request to the in-VM agent, which is presumed to cause the VM to begin a reboot.
+// 2) stop the VM through jailer#Stop(). The signal should be visible from the VMM (e.g. SIGTERM)
+// 3) stop the VM through cancelling the associated context. The signal would not be visible from the VMM (e.g. SIGKILL)
+func (s *service) shutdownLoop(
+	requestCtx context.Context,
+	timeout time.Duration,
+	req *taskAPI.ShutdownRequest,
+) {
+	actions := []struct {
+		name     string
+		shutdown func() error
+		timeout  time.Duration
+	}{
+		{
+			name: "send a request to the in-VM agent",
+			shutdown: func() error {
+				_, err := s.agentClient.Shutdown(requestCtx, req)
+				if err != nil {
+					return err
+				}
+				return nil
+			},
+			timeout: timeout,
+		},
+		{
+			name: "stop the jailer",
+			shutdown: func() error {
+				return s.jailer.Stop()
+			},
+			timeout: jailerStopTimeout,
+		},
+		{
+			name: "cancel the context",
+			shutdown: func() error {
+				s.shimCancel()
+				return nil
+			},
+		},
+	}
+
+	for _, action := range actions {
+		pid, err := s.machine.PID()
+		if pid == 0 && err != nil {
+			break // we have nothing to kill
+		}
 
-	if s.vmExitErr != nil {
-		return status.Error(codes.Internal,
-			fmt.Sprintf("VMM exit errors: %v", s.vmExitErr))
+		s.logger.Debug(action.name)
+		err = action.shutdown()
+		if err != nil {
+			// if sending an request doesn't succeed, don't wait and carry on.
+			s.logger.WithError(err).Errorf("failed to %s", action.name)
+		} else {
+			time.Sleep(action.timeout)
+		}
 	}
-
-	return nil
 }
 
 func (s *service) Stats(requestCtx context.Context, req *taskAPI.StatsRequest) (*taskAPI.StatsResponse, error) {

runtime/service_integ_test.go

@@ -65,7 +65,6 @@ const (
 	firecrackerRuntime     = "aws.firecracker"
 	shimProcessName        = "containerd-shim-aws-firecracker"
 	firecrackerProcessName = "firecracker"
-	jailerProcessName      = "runc"
 
 	defaultVMRootfsPath = "/var/lib/firecracker-containerd/runtime/default-rootfs.img"
 	defaultVMNetDevName = "eth0"
@@ -1365,16 +1364,16 @@ func TestStopVM_Isolated(t *testing.T) {
 	tests := []struct {
 		name            string
 		createVMRequest proto.CreateVMRequest
-		stopFunc        func(ctx context.Context, fcClient fccontrol.FirecrackerService, vmID string)
+		stopFunc        func(ctx context.Context, fcClient fccontrol.FirecrackerService, req proto.CreateVMRequest)
 		withStopVM      bool
 	}{
 		{
 			name:       "Successful",
 			withStopVM: true,
 
 			createVMRequest: proto.CreateVMRequest{},
-			stopFunc: func(ctx context.Context, fcClient fccontrol.FirecrackerService, vmID string) {
-				_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: vmID})
+			stopFunc: func(ctx context.Context, fcClient fccontrol.FirecrackerService, req proto.CreateVMRequest) {
+				_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: req.VMID})
 				require.Equal(status.Code(err), codes.OK)
 			},
 		},
@@ -1390,11 +1389,17 @@ func TestStopVM_Isolated(t *testing.T) {
 					HostPath: "/var/lib/firecracker-containerd/runtime/rootfs-slow-reboot.img",
 				},
 			},
-			stopFunc: func(ctx context.Context, fcClient fccontrol.FirecrackerService, vmID string) {
-				_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: vmID})
+			stopFunc: func(ctx context.Context, fcClient fccontrol.FirecrackerService, req proto.CreateVMRequest) {
+				_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: req.VMID})
 				errCode := status.Code(err)
-				assert.NotEqual(codes.Unknown, errCode, "the error code must not be Unknown")
 				assert.Equal(codes.DeadlineExceeded, errCode, "the error code must be DeadlineExceeded")
+
+				if req.JailerConfig != nil {
+					// No "signal: ..." error with runc since it traps the signal
+					assert.Contains(err.Error(), "exit status 1")
+				} else {
+					assert.Contains(err.Error(), "signal: terminated", "must be 'terminated', not 'killed'")
+				}
 			},
 		},
 
@@ -1404,7 +1409,7 @@ func TestStopVM_Isolated(t *testing.T) {
 			withStopVM: false,
 
 			createVMRequest: proto.CreateVMRequest{},
-			stopFunc: func(ctx context.Context, _ fccontrol.FirecrackerService, _ string) {
+			stopFunc: func(ctx context.Context, _ fccontrol.FirecrackerService, _ proto.CreateVMRequest) {
 				firecrackerProcesses, err := findProcess(ctx, findFirecracker)
 				require.NoError(err, "failed waiting for expected firecracker process %q to come up", firecrackerProcessName)
 				require.Len(firecrackerProcesses, 1, "expected only one firecracker process to exist")
@@ -1426,7 +1431,7 @@ func TestStopVM_Isolated(t *testing.T) {
 					HostPath: "/var/lib/firecracker-containerd/runtime/rootfs-slow-reboot.img",
 				},
 			},
-			stopFunc: func(ctx context.Context, fcClient fccontrol.FirecrackerService, vmID string) {
+			stopFunc: func(ctx context.Context, fcClient fccontrol.FirecrackerService, req proto.CreateVMRequest) {
 				firecrackerProcesses, err := findProcess(ctx, findFirecracker)
 				require.NoError(err, "failed waiting for expected firecracker process %q to come up", firecrackerProcessName)
 				require.Len(firecrackerProcesses, 1, "expected only one firecracker process to exist")
@@ -1439,10 +1444,16 @@ func TestStopVM_Isolated(t *testing.T) {
 				}()
 
 				_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{
-					VMID:           vmID,
+					VMID:           req.VMID,
 					TimeoutSeconds: 10,
 				})
-				require.Contains(err.Error(), "signal: killed", "unexpected error from StopVM")
+
+				if req.JailerConfig != nil {
+					// No "signal: ..." error with runc since it traps the signal
+					assert.Contains(err.Error(), "exit status 137")
+				} else {
+					assert.Contains(err.Error(), "signal: killed")
+				}
 			},
 		},
 	}
@@ -1481,10 +1492,10 @@ func TestStopVM_Isolated(t *testing.T) {
 			require.Len(fcProcesses, 1, "expected only one firecracker process to exist")
 			fcProcess := fcProcesses[0]
 
-			test.stopFunc(ctx, fcClient, vmID)
+			test.stopFunc(ctx, fcClient, createVMRequest)
 
 			// If the function above uses StopVMRequest,
-			// shim gurantees that the underlying Firecracker process is dead
+			// shim guarantees that the underlying Firecracker process is dead
 			// (either gracefully or forcibly) at the end of the request.
 			if test.withStopVM {
 				fcExists, err := process.PidExists(fcProcess.Pid)
@@ -1493,7 +1504,7 @@ func TestStopVM_Isolated(t *testing.T) {
 			}
 
 			// Since the shim is the one which is writing the response,
-			// it cannot gurantee that the itself is dead at the end of the request.
+			// it cannot guarantee that the shim itself is dead at the end of the request.
 			// But it should be dead eventually.
 			err = internal.WaitForPidToExit(ctx, time.Second, shimProcess.Pid)
 			require.NoError(err, "shim hasn't been terminated")