Merge pull request #324 from kzys/monitor-vm

Cleanup around Shutdown() and StopVM()

Author: kzys

firecracker-control/local.go

@@ -369,9 +369,17 @@ func (s *local) newShim(ns, vmID, containerdAddress string, shimSocket *net.Unix
 
 	// make sure to wait after start
 	go func() {
-		logger.Debug("waiting on shim process")
-		waitErr := cmd.Wait()
-		logger.WithError(waitErr).Debug("completed waiting on shim process")
+		if err := cmd.Wait(); err != nil {
+			if exitErr, ok := err.(*exec.ExitError); ok {
+				// shim is usually terminated by cancelling the context
+				logger.WithError(exitErr).Debug("shim has been terminated")
+			} else {
+				logger.WithError(err).Error("shim has been unexpectedly terminated")
+			}
+		}
+		if err := os.RemoveAll(shimDir.RootPath()); err != nil {
+			logger.WithError(err).Errorf("failed to remove %q", shimDir.RootPath())
+		}
 	}()
 
 	err = setShimOOMScore(cmd.Process.Pid)

go.mod

@@ -18,7 +18,7 @@ require (
 	github.com/docker/go-events v0.0.0-20170721190031-9461782956ad // indirect
 	github.com/docker/go-metrics v0.0.0-20181218153428-b84716841b82 // indirect
 	github.com/docker/go-units v0.3.3
-	github.com/firecracker-microvm/firecracker-go-sdk v0.17.1-0.20191029213755-dbf9a1e05f09
+	github.com/firecracker-microvm/firecracker-go-sdk v0.19.0
 	github.com/go-ole/go-ole v1.2.4 // indirect
 	github.com/godbus/dbus v0.0.0-20181025153459-66d97aec3384 // indirect
 	github.com/gofrs/uuid v3.2.0+incompatible

go.sum

@@ -59,8 +59,8 @@ github.com/docker/go-metrics v0.0.0-20181218153428-b84716841b82 h1:X0fj836zx99zF
 github.com/docker/go-metrics v0.0.0-20181218153428-b84716841b82/go.mod h1:/u0gXw0Gay3ceNrsHubL3BtdOL2fHf93USgMTe0W5dI=
 github.com/docker/go-units v0.3.3 h1:Xk8S3Xj5sLGlG5g67hJmYMmUgXv5N4PhkjJHHqrwnTk=
 github.com/docker/go-units v0.3.3/go.mod h1:fgPhTUdO+D/Jk86RDLlptpiXQzgHJF7gydDDbaIK4Dk=
-github.com/firecracker-microvm/firecracker-go-sdk v0.17.1-0.20191029213755-dbf9a1e05f09 h1:JDfRpK+V2J1Es+Xm6aMJjCqvA4xv1kuWnJfeSopyDwo=
-github.com/firecracker-microvm/firecracker-go-sdk v0.17.1-0.20191029213755-dbf9a1e05f09/go.mod h1:tVXziw7GjioCKVjI5/agymYxUaqJM6q7cp9e6kwjo8Q=
+github.com/firecracker-microvm/firecracker-go-sdk v0.19.0 h1:Fgb3WhB4q3J5e+ksMBtjVwBTvbDtPAkx7eQulb2BOq8=
+github.com/firecracker-microvm/firecracker-go-sdk v0.19.0/go.mod h1:kW0gxvPpPvMukUxxTO9DrpSlScrtrTDGY3VgjAj/Qwc=
 github.com/globalsign/mgo v0.0.0-20180905125535-1ca0a4f7cbcb h1:D4uzjWwKYQ5XnAvUbuvHW93esHg7F8N/OYeBBcJoTr0=
 github.com/globalsign/mgo v0.0.0-20180905125535-1ca0a4f7cbcb/go.mod h1:xkRDCp4j0OGD1HRkm4kmhM+pmpv3AKq5SU7GMg4oO/Q=
 github.com/go-ole/go-ole v1.2.4 h1:nNBDSCOigTSiarFpYE9J/KtEA1IOW4CNeqT9TQDqCxI=

runtime/service.go

@@ -19,6 +19,7 @@ import (
 	"math"
 	"net"
 	"os"
+	"os/exec"
 	"runtime/debug"
 	"strconv"
 	"strings"
@@ -45,7 +46,6 @@ import (
 	"github.com/gofrs/uuid"
 	ptypes "github.com/gogo/protobuf/types"
 	"github.com/golang/protobuf/ptypes/empty"
-	"github.com/hashicorp/go-multierror"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 	"golang.org/x/sys/unix"
@@ -71,6 +71,7 @@ const (
 	minVsockIOPort          = uint32(11000)
 	firecrackerStartTimeout = 5 * time.Second
 	defaultStopVMTimeout    = 5 * time.Second
+	defaultShutdownTimeout  = 5 * time.Second
 
 	// StartEventName is the topic published to when a VM starts
 	StartEventName = "/firecracker-vm/start"
@@ -548,46 +549,31 @@ func (s *service) mountDrives(requestCtx context.Context, driveMounts []*proto.F
 	return nil
 }
 
-// StopVM will shutdown the firecracker VM and start this shim's shutdown procedure. If the VM has not been
-// created yet and the timeout is hit waiting for it to exist, an error will be returned but the shim will
-// continue to shutdown.
+// StopVM will shutdown the VMM. Unlike Shutdown, this method is exposed to containerd clients.
+// If the VM has not been created yet and the timeout is hit waiting for it to exist, an error will be returned
+// but the shim will continue to shutdown.
 func (s *service) StopVM(requestCtx context.Context, request *proto.StopVMRequest) (_ *empty.Empty, err error) {
+	defer logPanicAndDie(s.logger)
+	s.logger.WithFields(logrus.Fields{"timeout_seconds": request.TimeoutSeconds}).Debug("StopVM")
+
 	timeout := defaultStopVMTimeout
 	if request.TimeoutSeconds > 0 {
 		timeout = time.Duration(request.TimeoutSeconds) * time.Second
 	}
-	timer := time.NewTimer(timeout)
-	defer logPanicAndDie(s.logger)
-	// If something goes wrong here, just shut down ungracefully. This eliminates some scenarios that would result
-	// in the user being unable to shut down the VM.
-	defer func() {
-		if err != nil {
-			s.logger.WithError(err).Error("StopVM error, shim is shutting down ungracefully")
-			s.shimCancel()
-		}
-	}()
 
+	shutdownCtx, shutdownCancel := context.WithTimeout(context.Background(), timeout)
+	defer shutdownCancel()
+
+	defer s.shimCancel()
 	err = s.waitVMReady()
 	if err != nil {
 		return nil, err
 	}
 
-	shutdownCh := make(chan error)
-	go func() {
-		defer close(shutdownCh)
-		_, err := s.Shutdown(requestCtx, &taskAPI.ShutdownRequest{Now: true})
-		shutdownCh <- err
-	}()
-
-	select {
-	case <-timer.C:
-		return nil, status.Error(codes.DeadlineExceeded, "timed out waiting for VM shutdown")
-	case err = <-shutdownCh:
-		if err != nil {
-			return nil, err
-		}
-		return &empty.Empty{}, nil
+	if err = s.shutdown(requestCtx, shutdownCtx, &taskAPI.ShutdownRequest{Now: true}); err != nil {
+		return nil, err
 	}
+	return &empty.Empty{}, nil
 }
 
 // GetVMInfo returns metadata for the VM being managed by this shim. If the VM has not been created yet, this
@@ -1149,54 +1135,71 @@ func (s *service) Connect(requestCtx context.Context, req *taskAPI.ConnectReques
 	return nil, errdefs.ErrNotImplemented
 }
 
-// Shutdown will attempt a graceful shutdown of the shim+VM. The shutdown procedure will only actually take
-// place if "Now" was set to true OR the VM started successfully, all tasks have been deleted and we were
-// told to shutdown when all tasks were deleted. Otherwise the call is just ignored.
+// Shutdown will shutdown of the VMM. Unlike StopVM, this method is only exposed to containerd itself.
 //
-// Shutdown can be called from a few code paths:
-// * If StopVM is called by the user (in which case "Now" is set to true)
-// * After any task is deleted via containerd's API (containerd calls on behalf of the user)
-// * After any task Create call returns an error (containerd calls on behalf of the user)
-// Shutdown is not directly exposed to containerd clients.
+// The shutdown procedure will only actually take place if "Now" was set to true OR
+// the VM started successfully, all tasks have been deleted and we were told to shutdown when all tasks were deleted.
+// Otherwise the call is just ignored.
+//
+// containerd calls this API on behalf of the user in the following cases:
+// * After any task is deleted via containerd's API
+// * After any task Create call returns an error
 func (s *service) Shutdown(requestCtx context.Context, req *taskAPI.ShutdownRequest) (*ptypes.Empty, error) {
 	defer logPanicAndDie(log.G(requestCtx))
-	s.logger.WithFields(logrus.Fields{"task_id": req.ID, "now": req.Now}).Debug("shutdown")
+	s.logger.WithFields(logrus.Fields{"task_id": req.ID, "now": req.Now}).Debug("Shutdown")
 
 	shouldShutdown := req.Now || s.exitAfterAllTasksDeleted && s.taskManager.ShutdownIfEmpty()
 	if !shouldShutdown {
 		return &ptypes.Empty{}, nil
 	}
 
-	// cancel the shim context no matter what, which will result in the VM getting a SIGKILL (if not already
-	// dead from graceful shutdown) and the shim process itself to begin exiting
-	defer s.shimCancel()
+	shutdownCtx, shutdownCancel := context.WithTimeout(context.Background(), defaultShutdownTimeout*time.Second)
+	defer shutdownCancel()
 
-	s.logger.Info("stopping the VM")
+	if err := s.shutdown(requestCtx, shutdownCtx, req); err != nil {
+		return &ptypes.Empty{}, err
+	}
 
-	var shutdownErr error
+	return &ptypes.Empty{}, nil
+}
 
-	_, err := s.agentClient.Shutdown(requestCtx, req)
-	if err != nil {
-		shutdownErr = multierror.Append(shutdownErr, errors.Wrap(err, "failed to shutdown VM Agent"))
-	}
+// shutdown will shutdown the VMM. requestCtx is used to issue requests and shutdownCtx is used for waiting a graceful shutdown procedure.
+// When shutdownCtx's Done channel is closed during the graceful shutdown procedure, the VMM is forcefully killed.
+func (s *service) shutdown(requestCtx, shutdownCtx context.Context, req *taskAPI.ShutdownRequest) error {
+	// cancel the shim at the end, in case even the last StopVMM() doesn't work
+	defer s.shimCancel()
 
-	err = s.machine.StopVMM()
-	if err != nil {
-		shutdownErr = multierror.Append(shutdownErr, errors.Wrap(err, "failed to gracefully stop VM"))
+	s.logger.Info("stopping the VM")
+	if _, err := s.agentClient.Shutdown(requestCtx, req); err != nil {
+		return err
 	}
 
-	err = os.RemoveAll(s.shimDir.RootPath())
-	if err != nil {
-		shutdownErr = multierror.Append(shutdownErr, errors.Wrapf(err, "failed to remove VM dir %q during shutdown", s.shimDir.RootPath()))
-	}
+	shutdownCh := make(chan error)
+	go func() {
+		defer close(shutdownCh)
+		err := s.machine.Wait(shutdownCtx)
+		shutdownCh <- err
+	}()
 
-	if shutdownErr != nil {
-		s.logger.WithError(shutdownErr).Error()
-		return nil, shutdownErr
+	var shutdownErr error
+	select {
+	case shutdownErr = <-shutdownCh:
+		if shutdownErr == nil {
+			s.logger.Info("the VM has been stopped successfully")
+			return nil
+		} else if exitErr, ok := shutdownErr.(*exec.ExitError); ok {
+			s.logger.WithError(exitErr).Error("the VM has been stopped, but not successfully")
+			return exitErr
+		}
+		s.logger.WithError(shutdownErr).Error("the VM returns unknown error")
+	case <-shutdownCtx.Done():
+		s.logger.Error("the VM hasn't been stopped before the context's deadline")
 	}
 
-	s.logger.Info("successfully stopped the VM")
-	return &ptypes.Empty{}, nil
+	if err := s.machine.StopVMM(); err != nil {
+		return err
+	}
+	return shutdownErr
 }
 
 func (s *service) Stats(requestCtx context.Context, req *taskAPI.StatsRequest) (*taskAPI.StatsResponse, error) {

runtime/service_integ_test.go

@@ -140,16 +140,7 @@ func TestShimExitsUponContainerDelete_Isolated(t *testing.T) {
 	err = task.Start(testCtx)
 	require.NoError(t, err, "failed to start task for container %s", containerName)
 
-	shimProcesses, err := internal.WaitForProcessToExist(testCtx, time.Second,
-		func(ctx context.Context, p *process.Process) (bool, error) {
-			processExecutable, err := p.ExeWithContext(ctx)
-			if err != nil {
-				return false, err
-			}
-
-			return filepath.Base(processExecutable) == shimProcessName, nil
-		},
-	)
+	shimProcesses, err := internal.WaitForProcessToExist(testCtx, time.Second, findShim)
 	require.NoError(t, err, "failed waiting for expected shim process %q to come up", shimProcessName)
 	require.Len(t, shimProcesses, 1, "expected only one shim process to exist")
 	shimProcess := shimProcesses[0]
@@ -1228,3 +1219,58 @@ func TestRandomness_Isolated(t *testing.T) {
 		}
 	}
 }
+
+func TestStopVM_Isolated(t *testing.T) {
+	prepareIntegTest(t)
+	require := require.New(t)
+
+	client, err := containerd.New(containerdSockPath, containerd.WithDefaultRuntime(firecrackerRuntime))
+	require.NoError(err, "unable to create client to containerd service at %s, is containerd running?", containerdSockPath)
+	defer client.Close()
+
+	timeout, cancel := context.WithTimeout(context.Background(), 60*time.Second)
+	defer cancel()
+	ctx := namespaces.WithNamespace(timeout, "default")
+
+	image, err := alpineImage(ctx, client, defaultSnapshotterName())
+	require.NoError(err, "failed to get alpine image")
+
+	pluginClient, err := ttrpcutil.NewClient(containerdSockPath + ".ttrpc")
+	require.NoError(err, "failed to create ttrpc client")
+
+	vmID := testNameToVMID(t.Name())
+
+	fcClient := fccontrol.NewFirecrackerClient(pluginClient.Client())
+	_, err = fcClient.CreateVM(ctx, &proto.CreateVMRequest{VMID: vmID})
+	require.NoError(err)
+
+	c, err := client.NewContainer(ctx,
+		"container",
+		containerd.WithSnapshotter(defaultSnapshotterName()),
+		containerd.WithNewSnapshot("snapshot", image),
+		containerd.WithNewSpec(oci.WithProcessArgs("/bin/echo", "-n", "hello"), firecrackeroci.WithVMID(vmID)),
+	)
+	require.NoError(err)
+
+	stdout := startAndWaitTask(ctx, t, c)
+	require.Equal("hello", stdout)
+
+	shimProcesses, err := internal.WaitForProcessToExist(ctx, time.Second, findShim)
+	require.NoError(err, "failed waiting for expected shim process %q to come up", shimProcessName)
+	require.Len(shimProcesses, 1, "expected only one shim process to exist")
+
+	_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: vmID})
+	require.NoError(err)
+
+	err = internal.WaitForPidToExit(ctx, time.Second, shimProcesses[0].Pid)
+	require.NoError(err, "shim hasn't been terminated")
+}
+
+func findShim(ctx context.Context, p *process.Process) (bool, error) {
+	processExecutable, err := p.ExeWithContext(ctx)
+	if err != nil {
+		return false, err
+	}
+
+	return filepath.Base(processExecutable) == shimProcessName, nil
+}

tools/image-builder/Dockerfile.debian-image

@@ -11,7 +11,7 @@
 # express or implied. See the License for the specific language governing
 # permissions and limitations under the License.
 
-FROM debian:stretch-slim
+FROM debian:buster-slim
 
 RUN apt-get update && \
     DEBIAN_FRONTEND=noninteractive apt-get -y install \

tools/image-builder/Makefile

@@ -56,7 +56,7 @@ endif
 	debootstrap \
 		--variant=minbase \
 		--include=udev,systemd,systemd-sysv,procps,libseccomp2,haveged \
-		stretch \
+		buster \
 		"$(WORKDIR)" $(DEBMIRROR)
 	rm -rf "$(WORKDIR)/var/cache/apt/archives" \
 	       "$(WORKDIR)/usr/share/doc" \

tools/image-builder/files_debootstrap/etc/systemd/system/firecracker-agent.service

@@ -15,9 +15,9 @@ Description=Firecracker VM agent
 StartLimitIntervalSec=2
 After=local-fs.target
 Requires=local-fs.target
+SuccessAction=reboot
 
 [Service]
 Type=simple
 WorkingDirectory=/container
 ExecStart=/usr/local/bin/agent
-Restart=always

tools/image-builder/files_debootstrap/sbin/overlay-init

@@ -59,4 +59,4 @@ do_overlay
 
 # invoke the actual system init program and procede with the boot
 # process.
-exec /sbin/init $@
+exec /usr/sbin/init $@