Merge pull request firecracker-microvm#425 from kzys/slow-boot

Make CreateVM's timeout configurable

Author: kzys

Makefile

@@ -187,6 +187,10 @@ DEFAULT_RUNC_JAILER_CONFIG_INSTALLPATH?=/etc/containerd/firecracker-runc-config.
 $(DEFAULT_RUNC_JAILER_CONFIG_INSTALLPATH): $(ETC_CONTAINERD) runtime/firecracker-runc-config.json.example
 	install -D -o root -g root -m400 runtime/firecracker-runc-config.json.example $@
 
+ROOTFS_SLOW_BOOT_INSTALLPATH=$(FIRECRACKER_CONTAINERD_RUNTIME_DIR)/rootfs-slow-boot.img
+$(ROOTFS_SLOW_BOOT_INSTALLPATH): tools/image-builder/rootfs-slow-boot.img $(FIRECRACKER_CONTAINERD_RUNTIME_DIR)
+	install -D -o root -g root -m400 $< $@
+
 ROOTFS_SLOW_REBOOT_INSTALLPATH=$(FIRECRACKER_CONTAINERD_RUNTIME_DIR)/rootfs-slow-reboot.img
 $(ROOTFS_SLOW_REBOOT_INSTALLPATH): tools/image-builder/rootfs-slow-reboot.img $(FIRECRACKER_CONTAINERD_RUNTIME_DIR)
 	install -D -o root -g root -m400 $< $@
@@ -204,7 +208,7 @@ install-default-rootfs: $(DEFAULT_ROOTFS_INSTALLPATH)
 install-default-runc-jailer-config: $(DEFAULT_RUNC_JAILER_CONFIG_INSTALLPATH)
 
 .PHONY: install-test-rootfs
-install-test-rootfs: $(ROOTFS_SLOW_REBOOT_INSTALLPATH)
+install-test-rootfs: $(ROOTFS_SLOW_BOOT_INSTALLPATH) $(ROOTFS_SLOW_REBOOT_INSTALLPATH)
 
 ##########################
 # CNI Network

firecracker-control/local.go

@@ -195,8 +195,7 @@ func (s *local) CreateVM(requestCtx context.Context, req *proto.CreateVMRequest)
 
 	resp, err := client.CreateVM(requestCtx, req)
 	if err != nil {
-		err = errors.Wrap(err, "shim CreateVM returned error")
-		s.logger.WithError(err).Error()
+		s.logger.WithError(err).Error("shim CreateVM returned error")
 		return nil, err
 	}
 

internal/vm/vsock.go

@@ -37,10 +37,7 @@ const (
 // VSockDial attempts to connect to the Firecracker host-side vsock at the provided unix
 // path and port. It will retry connect attempts if a temporary error is encountered (up
 // to a fixed timeout) or the provided request is canceled.
-func VSockDial(reqCtx context.Context, logger *logrus.Entry, udsPath string, port uint32) (net.Conn, error) {
-	ctx, cancel := context.WithTimeout(reqCtx, vsockRetryTimeout)
-	defer cancel()
-
+func VSockDial(ctx context.Context, logger *logrus.Entry, udsPath string, port uint32) (net.Conn, error) {
 	tickerCh := time.NewTicker(vsockRetryInterval).C
 	var attemptCount int
 	for {

proto/firecracker.pb.go

@@ -34,6 +34,8 @@ message CreateVMRequest {
     bool ExitAfterAllTasksDeleted = 9;
 
     JailerConfig JailerConfig = 10;
+
+    uint32 TimeoutSeconds = 11;
 }
 
 message CreateVMResponse {

proto/firecracker.proto

@@ -68,12 +68,18 @@ func init() {
 }
 
 const (
-	defaultVsockPort        = 10789
-	minVsockIOPort          = uint32(11000)
-	firecrackerStartTimeout = 5 * time.Second
-	defaultStopVMTimeout    = 5 * time.Second
-	defaultShutdownTimeout  = 5 * time.Second
-	jailerStopTimeout       = 3 * time.Second
+	defaultVsockPort = 10789
+	minVsockIOPort   = uint32(11000)
+
+	// vmReadyTimeout is used to control the time all requests wait a Go channel (vmReady) before calling
+	// Firecracker's API server. The channel is closed once the VM starts.
+	vmReadyTimeout = 5 * time.Second
+
+	defaultCreateVMTimeout = 20 * 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"
@@ -425,7 +431,7 @@ func (s *service) waitVMReady() error {
 	select {
 	case <-s.vmReady:
 		return nil
-	case <-time.After(firecrackerStartTimeout):
+	case <-time.After(vmReadyTimeout):
 		return status.Error(codes.DeadlineExceeded, "timed out waiting for VM start")
 	}
 }
@@ -435,14 +441,21 @@ func (s *service) waitVMReady() error {
 func (s *service) CreateVM(requestCtx context.Context, request *proto.CreateVMRequest) (*proto.CreateVMResponse, error) {
 	defer logPanicAndDie(s.logger)
 
+	timeout := defaultCreateVMTimeout
+	if request.TimeoutSeconds > 0 {
+		timeout = time.Duration(request.TimeoutSeconds) * time.Second
+	}
+	ctxWithTimeout, cancel := context.WithTimeout(requestCtx, timeout)
+	defer cancel()
+
 	var (
 		err       error
 		createRan bool
 		resp      proto.CreateVMResponse
 	)
 
 	s.vmStartOnce.Do(func() {
-		err = s.createVM(requestCtx, request)
+		err = s.createVM(ctxWithTimeout, request)
 		createRan = true
 	})
 
@@ -453,9 +466,13 @@ func (s *service) CreateVM(requestCtx context.Context, request *proto.CreateVMRe
 	// If we failed to create the VM, we have no point in existing anymore, so shutdown
 	if err != nil {
 		s.shimCancel()
-		err = errors.Wrap(err, "failed to create VM")
-		s.logger.WithError(err).Error()
-		return nil, err
+
+		s.logger.WithError(err).Error("failed to create VM")
+
+		if errors.Cause(err) == context.DeadlineExceeded {
+			return nil, status.Errorf(codes.DeadlineExceeded, "VM %q didn't start within %s: %s", request.VMID, timeout, err)
+		}
+		return nil, errors.Wrap(err, "failed to create VM")
 	}
 
 	// creating the VM succeeded, setup monitors and publish events to celebrate

runtime/service.go

@@ -1047,6 +1047,7 @@ func TestDriveMount_Isolated(t *testing.T) {
 			UID: 300000,
 			GID: 300000,
 		},
+		TimeoutSeconds: 60,
 	})
 	require.NoError(t, err, "failed to create vm")
 
@@ -1787,3 +1788,77 @@ func findProcWithName(name string) func(context.Context, *process.Process) (bool
 		return filepath.Base(processExecutable) == name, nil
 	}
 }
+
+func TestCreateVM_Isolated(t *testing.T) {
+	prepareIntegTest(t)
+
+	client, err := containerd.New(containerdSockPath, containerd.WithDefaultRuntime(firecrackerRuntime))
+	require.NoError(t, err, "unable to create client to containerd service at %s, is containerd running?", containerdSockPath)
+	defer client.Close()
+
+	ctx := namespaces.WithNamespace(context.Background(), "default")
+
+	pluginClient, err := ttrpcutil.NewClient(containerdSockPath + ".ttrpc")
+	require.NoError(t, err, "failed to create ttrpc client")
+
+	fcClient := fccontrol.NewFirecrackerClient(pluginClient.Client())
+
+	subtests := []struct {
+		name     string
+		request  proto.CreateVMRequest
+		validate func(*testing.T, error)
+	}{
+		{
+			name:    "Happy Case",
+			request: proto.CreateVMRequest{},
+			validate: func(t *testing.T, err error) {
+				require.NoError(t, err)
+			},
+		},
+		{
+			name: "Slow Root FS",
+			request: proto.CreateVMRequest{
+				RootDrive: &proto.FirecrackerRootDrive{
+					HostPath: "/var/lib/firecracker-containerd/runtime/rootfs-slow-boot.img",
+				},
+			},
+			validate: func(t *testing.T, err error) {
+				require.Error(t, err)
+				assert.Equal(t, codes.DeadlineExceeded, status.Code(err))
+				assert.Contains(t, err.Error(), "didn't start within 20s")
+			},
+		},
+		{
+			name: "Slow Root FS and Longer Timeout",
+			request: proto.CreateVMRequest{
+				RootDrive: &proto.FirecrackerRootDrive{
+					HostPath: "/var/lib/firecracker-containerd/runtime/rootfs-slow-boot.img",
+				},
+				TimeoutSeconds: 60,
+			},
+			validate: func(t *testing.T, err error) {
+				require.NoError(t, err)
+			},
+		},
+	}
+
+	for _, subtest := range subtests {
+		request := subtest.request
+		validate := subtest.validate
+
+		t.Run(subtest.name, func(t *testing.T) {
+			request.VMID = testNameToVMID(t.Name())
+
+			_, err = fcClient.CreateVM(ctx, &request)
+			validate(t, err)
+
+			if err != nil {
+				// No VM to stop.
+				return
+			}
+
+			_, err = fcClient.StopVM(ctx, &proto.StopVMRequest{VMID: request.VMID})
+			require.Equal(t, status.Code(err), codes.OK)
+		})
+	}
+}

runtime/service_integ_test.go

@@ -37,7 +37,7 @@ fi
 touch --reference=debootstrap_stamp --no-create "$(WORKDIR)"
 endef
 
-all: rootfs.img rootfs-slow-reboot.img
+all: rootfs.img rootfs-slow-boot.img rootfs-slow-reboot.img
 
 $(WORKDIR):
 	mkdir $(WORKDIR)
@@ -67,6 +67,13 @@ endif
 rootfs.img: files_common_stamp files_debootstrap_stamp files_ephemeral_stamp
 	mksquashfs "$(WORKDIR)" rootfs.img -noappend
 
+# Intentionally break the rootfs to simulate the case where CreateVM is taking longer than the minimal timeout
+rootfs-slow-boot.img: files_common_stamp files_debootstrap_stamp files_ephemeral_stamp
+	rm -fr tmp/$@
+	cp -a "$(WORKDIR)" tmp/$@
+	echo 'ExecStartPre=/bin/sleep 30' >> tmp/$@/etc/systemd/system/firecracker-agent.service
+	mksquashfs tmp/$@ $@ -noappend
+
 # Intentionally break the rootfs to simulate the case where StopVM is taking longer than the minimal timeout
 rootfs-slow-reboot.img: files_common_stamp files_debootstrap_stamp files_ephemeral_stamp
 	rm -fr tmp/$@
@@ -98,7 +105,7 @@ builder_stamp:
 clean:
 	-rm -f *stamp
 	if [ $(UID) -eq 0 ]; then \
-	  rm -f rootfs.img rootfs-slow-reboot.img ;\
+	  rm -f rootfs.img rootfs-slow-boot.img rootfs-slow-reboot.img ;\
 	else \
 	  $(MAKE) clean-in-docker ;\
 	fi