Merge pull request #577 from kzys/fix-stopvm

Kill Firecracker forcefully if StopVM is hitting its context's timeout

Author: kzys

runtime/service.go

@@ -647,26 +647,10 @@ func (s *service) StopVM(requestCtx context.Context, request *proto.StopVMReques
 		timeout = time.Duration(request.TimeoutSeconds) * time.Second
 	}
 
-	info, err := s.machine.DescribeInstanceInfo(requestCtx)
-	if err != nil {
-		return nil, errors.Wrapf(err, "failed to get instance info %v", info)
-	}
-
-	if *info.State == models.InstanceInfoStatePaused {
-		s.logger.Debug("Instance is in Paused state, force shutdown in progress")
-		err = s.jailer.Stop(true)
-		if err != nil {
-			return nil, errors.Wrap(err, "failed to stop VM in paused State")
-		}
-		return &empty.Empty{}, nil
-	}
-
-	err = s.waitVMReady()
-	if err != nil {
-		return nil, err
-	}
+	ctx, cancel := context.WithTimeout(requestCtx, timeout)
+	defer cancel()
 
-	if err = s.shutdown(requestCtx, timeout, &taskAPI.ShutdownRequest{Now: true}); err != nil {
+	if err = s.terminate(ctx); err != nil {
 		return nil, err
 	}
 	return &empty.Empty{}, nil
@@ -1563,94 +1547,80 @@ func (s *service) Shutdown(requestCtx context.Context, req *taskAPI.ShutdownRequ
 		return &ptypes.Empty{}, nil
 	}
 
-	if err := s.shutdown(requestCtx, defaultShutdownTimeout, req); err != nil {
+	ctx, cancel := context.WithTimeout(requestCtx, defaultShutdownTimeout)
+	defer cancel()
+
+	if err := s.terminate(ctx); err != nil {
 		return &ptypes.Empty{}, err
 	}
 
 	return &ptypes.Empty{}, nil
 }
 
-func (s *service) shutdown(
-	requestCtx context.Context,
-	timeout time.Duration,
-	req *taskAPI.ShutdownRequest,
-) error {
-	s.logger.Info("stopping the VM")
+func (s *service) isPaused(ctx context.Context) (bool, error) {
+	info, err := s.machine.DescribeInstanceInfo(ctx)
+	if err != nil {
+		return false, errors.Wrapf(err, "failed to get instance info %v", info)
+	}
+	return *info.State == models.InstanceInfoStatePaused, nil
+}
 
-	go func() {
-		s.shutdownLoop(requestCtx, timeout, req)
-	}()
+func (s *service) forceTerminate(ctx context.Context) error {
+	s.logger.Errorf("forcefully terminate VM %s", s.vmID)
 
-	var result *multierror.Error
-	if err := s.machine.Wait(context.Background()); err != nil {
-		result = multierror.Append(result, err)
-	}
-	if err := s.cleanup(); err != nil {
-		result = multierror.Append(result, err)
+	err := s.jailer.Stop(true)
+	if err != nil {
+		s.logger.WithError(err).Error("failed to stop")
 	}
 
-	if err := result.ErrorOrNil(); err != nil {
-		return status.Error(codes.Internal, fmt.Sprintf("the VMM was killed forcibly: %v", err))
+	err = s.cleanup()
+	if err != nil {
+		s.logger.WithError(err).Error("failed to cleanup")
 	}
-	return nil
+
+	return status.Errorf(codes.Internal, "forcefully terminated VM %s", s.vmID)
 }
 
-// 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 by SIGTERM",
-			shutdown: func() error {
-				return s.jailer.Stop(false)
-			},
-			timeout: jailerStopTimeout,
-		},
-		{
-			name: "stop the jailer by SIGKILL",
-			shutdown: func() error {
-				return s.jailer.Stop(true)
-			},
-			timeout: jailerStopTimeout,
-		},
+func (s *service) terminate(ctx context.Context) (retErr error) {
+	var success bool
+	defer func() {
+		if !success {
+			retErr = s.forceTerminate(ctx)
+		}
+	}()
+
+	err := s.waitVMReady()
+	if err != nil {
+		s.logger.WithError(err).Error("failed to wait VM")
+		return
 	}
 
-	for _, action := range actions {
-		pid, err := s.machine.PID()
-		if pid == 0 && err != nil {
-			break // we have nothing to kill
-		}
+	paused, err := s.isPaused(ctx)
+	if err != nil {
+		s.logger.WithError(err).Error("failed to check VM")
+		return
+	}
 
-		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)
-		}
+	if paused {
+		s.logger.Error("VM is paused and cannot take requests")
+		return
 	}
+
+	s.logger.Info("gracefully shutdown VM")
+	_, err = s.agentClient.Shutdown(ctx, &taskAPI.ShutdownRequest{ID: s.vmID, Now: true})
+	if err != nil {
+		s.logger.WithError(err).Error("failed to call in-VM agent")
+		return
+	}
+
+	err = s.machine.Wait(ctx)
+	if err != nil {
+		s.logger.WithError(err).Error("failed to wait VM")
+		return
+	}
+
+	success = true
+	return
 }
 
 func (s *service) Stats(requestCtx context.Context, req *taskAPI.StatsRequest) (*taskAPI.StatsResponse, error) {

runtime/service_integ_test.go

@@ -1599,6 +1599,10 @@ func findProcess(
 	return matches, nil
 }
 
+func pidExists(pid int) bool {
+	return syscall.ESRCH.Is(syscall.Kill(pid, 0))
+}
+
 func TestStopVM_Isolated(t *testing.T) {
 	prepareIntegTest(t)
 	require := require.New(t)
@@ -1644,15 +1648,9 @@ func TestStopVM_Isolated(t *testing.T) {
 			},
 			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.Equal(codes.Internal, errCode, "the error code must be Internal")
-
-				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'")
-				}
+				require.Error(err)
+				assert.Equal(codes.Internal, status.Code(err))
+				assert.Contains(err.Error(), "forcefully terminated")
 			},
 		},
 
@@ -1701,12 +1699,10 @@ func TestStopVM_Isolated(t *testing.T) {
 					TimeoutSeconds: 10,
 				})
 
-				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")
-				}
+				require.Error(err)
+				assert.Equal(codes.Internal, status.Code(err))
+				// This is technically not accurate (the test is terminating the VM) though.
+				assert.Contains(err.Error(), "forcefully terminated")
 			},
 		},
 
@@ -1722,7 +1718,30 @@ func TestStopVM_Isolated(t *testing.T) {
 				require.Equal(status.Code(err), codes.OK)
 
 				_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: req.VMID})
-				require.NoError(err)
+				require.Error(err)
+				assert.Equal(codes.Internal, status.Code(err))
+				assert.Contains(err.Error(), "forcefully terminated")
+			},
+		},
+
+		{
+			name:       "Suspend",
+			withStopVM: true,
+
+			createVMRequest: proto.CreateVMRequest{},
+			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")
+				firecrackerProcess := firecrackerProcesses[0]
+
+				err = firecrackerProcess.Suspend()
+				require.NoError(err, "failed to suspend Firecracker")
+
+				_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: req.VMID})
+				require.Error(err)
+				assert.Equal(codes.Internal, status.Code(err))
+				assert.Contains(err.Error(), "forcefully terminated")
 			},
 		},
 	}
@@ -1768,13 +1787,13 @@ func TestStopVM_Isolated(t *testing.T) {
 			// If the function above uses StopVMRequest, all underlying processes must be dead
 			// (either gracefully or forcibly) at the end of the request.
 			if test.withStopVM {
-				fcExists, err := process.PidExists(fcProcess.Pid)
-				require.NoError(err, "failed to find firecracker")
-				require.False(fcExists, "firecracker %s is still there", vmID)
+				fcExists := pidExists(int(fcProcess.Pid))
+				assert.NoError(err, "failed to find firecracker")
+				assert.False(fcExists, "firecracker %s (pid=%d) is still there", vmID, fcProcess.Pid)
 
-				shimExists, err := process.PidExists(shimProcess.Pid)
-				require.NoError(err, "failed to find shim")
-				require.False(shimExists, "shim %s is still there", vmID)
+				shimExists := pidExists(int(shimProcess.Pid))
+				assert.NoError(err, "failed to find shim")
+				assert.False(shimExists, "shim %s (pid=%d) is still there", vmID, shimProcess.Pid)
 			}
 
 			err = internal.WaitForPidToExit(ctx, time.Second, shimProcess.Pid)
@@ -2327,8 +2346,12 @@ func TestPauseResume_Isolated(t *testing.T) {
 		// Ensure the response fields are populated correctly
 		assert.Equal(t, request.VMID, resp.VMID)
 
-		_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: request.VMID})
-		require.Equal(t, status.Code(err), codes.OK)
+		// Resume the VM since state() may pause the VM.
+		_, err = fcClient.ResumeVM(ctx, &proto.ResumeVMRequest{VMID: vmID})
+		require.NoError(t, err)
+
+		_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: vmID})
+		require.NoError(t, err)
 	}
 
 	for _, subtest := range subtests {