Repository: code-ready/crc
Pull request #2303 (2021-05-05 07:09:18)

Remove differences between machine creation and machine start
This removes the branch `if !exists { start the VM this way } else { start the VM this other way }` in machine.Start.

It simplifies the code but also ensures a just created VM can be launched again. 
In the future, we could add a `machine.Create` method that can be call at setup time. It would radically change the UX: no more error like `Machine doesnt not exist. Use 'crc start' to create it`

openshift-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/code-ready/crc/pull/2303#" title="Author self-approved">guillaumerose</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=code-ready%2Fcrc).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/code-ready/crc/blob/master/OWNERS)~~ [guillaumerose]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
praveenkumar: This looks a good cleanup but also we are going to run some of the code path which really don't require if vm is stop, I still need to gather data around time it takes now `start => stop => start` and how previously it was taking.
openshift-ci[bot]: @guillaumerose: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
ci/prow/integration-crc | 8bbb5be8ed8b33e0ff1bff35f1de62591b34f4b3 | [link](https://prow.ci.openshift.org/view/gs/origin-ci-test/pr-logs/pull/code-ready_crc/2303/pull-ci-code-ready-crc-master-integration-crc/1390565761654722560) | `/test integration-crc`

[Full PR test history](https://prow.ci.openshift.org/pr-history?org=code-ready&repo=crc&pr=2303). [Your PR dashboard](https://prow.ci.openshift.org/pr?query=is:pr+state:open+author:guillaumerose).

<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository. I understand the commands that are listed [here](https://go.k8s.io/bot-commands).
</details>
<!-- test report -->
guillaumerose: /retest
openshift-ci[bot]: @guillaumerose: The following tests **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
ci/prow/integration-crc | 8bbb5be8ed8b33e0ff1bff35f1de62591b34f4b3 | [link](https://prow.ci.openshift.org/view/gs/origin-ci-test/pr-logs/pull/code-ready_crc/2303/pull-ci-code-ready-crc-master-integration-crc/1390565761654722560) | `/test integration-crc`
ci/prow/e2e-crc | 8bbb5be8ed8b33e0ff1bff35f1de62591b34f4b3 | [link](https://prow.ci.openshift.org/view/gs/origin-ci-test/pr-logs/pull/code-ready_crc/2303/pull-ci-code-ready-crc-master-e2e-crc/1390565761587613696) | `/test e2e-crc`

[Full PR test history](https://prow.ci.openshift.org/pr-history?org=code-ready&repo=crc&pr=2303). [Your PR dashboard](https://prow.ci.openshift.org/pr?query=is:pr+state:open+author:guillaumerose).

<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository. I understand the commands that are listed [here](https://go.k8s.io/bot-commands).
</details>
<!-- test report -->
openshift-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/code-ready/crc/pull/2303#pullrequestreview-654250365" title="Approved">cfergeau</a>*, *<a href="https://github.com/code-ready/crc/pull/2303#" title="Author self-approved">guillaumerose</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=code-ready%2Fcrc).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/code-ready/crc/blob/master/OWNERS)~~ [cfergeau,guillaumerose]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
guillaumerose: /retest
retest this please

Patch:
diff --git a/pkg/crc/logging/inmemory.go b/pkg/crc/logging/inmemory.go
index 756014739..8d48f9256 100644
--- a/pkg/crc/logging/inmemory.go
+++ b/pkg/crc/logging/inmemory.go
@@ -2,6 +2,7 @@ package logging
 
 import (
 	"container/ring"
+	"sync"
 
 	"github.com/sirupsen/logrus"
 )
@@ -9,6 +10,7 @@ import (
 // This hook keeps in memory n messages from error to info level
 type inMemoryHook struct {
 	messages *ring.Ring
+	lock     sync.RWMutex
 }
 
 func newInMemoryHook(size int) *inMemoryHook {
@@ -22,12 +24,16 @@ func (h *inMemoryHook) Levels() []logrus.Level {
 }
 
 func (h *inMemoryHook) Fire(entry *logrus.Entry) error {
+	h.lock.Lock()
+	defer h.lock.Unlock()
 	h.messages.Value = entry.Message
 	h.messages = h.messages.Next()
 	return nil
 }
 
 func (h *inMemoryHook) Messages() []string {
+	h.lock.RLock()
+	defer h.lock.RUnlock()
 	var ret []string
 	h.messages.Do(func(elem interface{}) {
 		if str, ok := elem.(string); ok {
diff --git a/pkg/crc/machine/start.go b/pkg/crc/machine/start.go
index 3d2da678d..c4ec0b265 100644
--- a/pkg/crc/machine/start.go
+++ b/pkg/crc/machine/start.go
@@ -141,13 +141,10 @@ func (client *client) Start(ctx context.Context, startConfig types.StartConfig)
 		return nil, err
 	}
 
-	var crcBundleMetadata *bundle.CrcBundleInfo
-
 	libMachineAPIClient, cleanup := createLibMachineClient()
 	defer cleanup()
 
 	// Pre-VM start
-	var host *host.Host
 	exists, err := client.Exists()
 	if err != nil {
 		return nil, errors.Wrap(err, "Cannot determine if VM exists")
@@ -162,98 +159,88 @@ func (client *client) Start(ctx context.Context, startConfig types.StartConfig)
 			return nil, errors.Wrap(err, "Failed to ask for pull secret")
 		}
 
-		machineConfig := config.MachineConfig{
-			Name:        client.name,
-			BundleName:  filepath.Base(startConfig.BundlePath),
-			CPUs:        startConfig.CPUs,
-			Memory:      startConfig.Memory,
-			DiskSize:    startConfig.DiskSize,
-			NetworkMode: client.networkMode(),
-		}
-
-		crcBundleMetadata, err = getCrcBundleInfo(startConfig.BundlePath)
+		crcBundleMetadata, err := getCrcBundleInfo(startConfig.BundlePath)
 		if err != nil {
 			return nil, errors.Wrap(err, "Error getting bundle metadata")
 		}
 
-		if client.useVSock() {
-			if err := exposePorts(); err != nil {
-				return nil, err
-			}
-		}
-
 		logging.Infof("Creating CodeReady Containers VM for OpenShift %s...", crcBundleMetadata.GetOpenshiftVersion())
 
-		// Retrieve metadata info
-		machineConfig.ImageSourcePath = crcBundleMetadata.GetDiskImagePath()
-		machineConfig.ImageFormat = crcBundleMetadata.GetDiskImageFormat()
-		machineConfig.SSHKeyPath = crcBundleMetadata.GetSSHKeyPath()
-		machineConfig.KernelCmdLine = crcBundleMetadata.GetKernelCommandLine()
-		machineConfig.Initramfs = crcBundleMetadata.GetInitramfsPath()
-		machineConfig.Kernel = crcBundleMetadata.GetKernelPath()
-
-		host, err = createHost(ctx, libMachineAPIClient, machineConfig)
-		if err != nil {
+		machineConfig := config.MachineConfig{
+			Name:            client.name,
+			BundleName:      filepath.Base(startConfig.BundlePath),
+			CPUs:            startConfig.CPUs,
+			Memory:          startConfig.Memory,
+			DiskSize:        startConfig.DiskSize,
+			NetworkMode:     client.networkMode(),
+			ImageSourcePath: crcBundleMetadata.GetDiskImagePath(),
+			ImageFormat:     crcBundleMetadata.GetDiskImageFormat(),
+			SSHKeyPath:      crcBundleMetadata.GetSSHKeyPath(),
+			KernelCmdLine:   crcBundleMetadata.GetKernelCommandLine(),
+			Initramfs:       crcBundleMetadata.GetInitramfsPath(),
+			Kernel:          crcBundleMetadata.GetKernelPath(),
+		}
+		if err := createHost(libMachineAPIClient, machineConfig); err != nil {
 			return nil, errors.Wrap(err, "Error creating machine")
 		}
-	} else { // exists
-		host, err = libMachineAPIClient.Load(client.name)
-		if err != nil {
-			return nil, errors.Wrap(err, "Error loading machine")
-		}
-
-		crcBundleMetadata, err = getBundleMetadataFromDriver(host.Driver)
-		if err != nil {
-			return nil, errors.Wrap(err, "Error loading bundle metadata")
-		}
-		bundleName := crcBundleMetadata.GetBundleName()
-		if bundleName != filepath.Base(startConfig.BundlePath) {
-			logging.Debugf("Bundle '%s' was requested, but the existing VM is using '%s'",
-				filepath.Base(startConfig.BundlePath), bundleName)
-			return nil, fmt.Errorf("Bundle '%s' was requested, but the existing VM is using '%s'",
-				filepath.Base(startConfig.BundlePath),
-				bundleName)
-		}
-		vmState, err := host.Driver.GetState()
-		if err != nil {
-			return nil, errors.Wrap(err, "Error getting the machine state")
-		}
-		if vmState == state.Running {
-			logging.Infof("A CodeReady Containers VM for OpenShift %s is already running", crcBundleMetadata.GetOpenshiftVersion())
-			clusterConfig, err := getClusterConfig(crcBundleMetadata)
-			if err != nil {
-				return nil, errors.Wrap(err, "Cannot create cluster configuration")
-			}
+	} else {
+		telemetry.SetStartType(ctx, telemetry.StartStartType)
+	}
 
-			telemetry.SetStartType(ctx, telemetry.AlreadyRunningStartType)
-			return &types.StartResult{
-				Status:         vmState,
-				ClusterConfig:  *clusterConfig,
-				KubeletStarted: true,
-			}, nil
-		}
+	host, err := libMachineAPIClient.Load(client.name)
+	if err != nil {
+		return nil, errors.Wrap(err, "Error loading machine")
+	}
 
-		if _, err := bundle.Use(bundleName); err != nil {
-			return nil, err
+	crcBundleMetadata, err := getBundleMetadataFromDriver(host.Driver)
+	if err != nil {
+		return nil, errors.Wrap(err, "Error loading bundle metadata")
+	}
+	bundleName := crcBundleMetadata.GetBundleName()
+	if bundleName != filepath.Base(startConfig.BundlePath) {
+		logging.Debugf("Bundle '%s' was requested, but the existing VM is using '%s'",
+			filepath.Base(startConfig.BundlePath), bundleName)
+		return nil, fmt.Errorf("Bundle '%s' was requested, but the existing VM is using '%s'",
+			filepath.Base(startConfig.BundlePath),
+			bundleName)
+	}
+	vmState, err := host.Driver.GetState()
+	if err != nil {
+		return nil, errors.Wrap(err, "Error getting the machine state")
+	}
+	if vmState == state.Running {
+		logging.Infof("A CodeReady Containers VM for OpenShift %s is already running", crcBundleMetadata.GetOpenshiftVersion())
+		clusterConfig, err := getClusterConfig(crcBundleMetadata)
+		if err != nil {
+			return nil, errors.Wrap(err, "Cannot create cluster configuration")
 		}
 
-		if client.useVSock() {
-			if err := exposePorts(); err != nil {
-				return nil, err
-			}
-		}
+		telemetry.SetStartType(ctx, telemetry.AlreadyRunningStartType)
+		return &types.StartResult{
+			Status:         vmState,
+			ClusterConfig:  *clusterConfig,
+			KubeletStarted: true,
+		}, nil
+	}
 
-		telemetry.SetStartType(ctx, telemetry.StartStartType)
+	if _, err := bundle.Use(bundleName); err != nil {
+		return nil, err
+	}
 
-		logging.Infof("Starting CodeReady Containers VM for OpenShift %s...", crcBundleMetadata.GetOpenshiftVersion())
+	logging.Infof("Starting CodeReady Containers VM for OpenShift %s...", crcBundleMetadata.GetOpenshiftVersion())
 
-		if err := client.updateVMConfig(startConfig, libMachineAPIClient, host); err != nil {
-			return nil, errors.Wrap(err, "Could not update CRC VM configuration")
+	if client.useVSock() {
+		if err := exposePorts(); err != nil {
+			return nil, err
 		}
+	}
 
-		if err := host.Driver.Start(); err != nil {
-			return nil, errors.Wrap(err, "Error starting stopped VM")
-		}
+	if err := client.updateVMConfig(startConfig, libMachineAPIClient, host); err != nil {
+		return nil, errors.Wrap(err, "Could not update CRC VM configuration")
+	}
+
+	if err := startHost(ctx, libMachineAPIClient, host); err != nil {
+		return nil, errors.Wrap(err, "Error starting machine")
 	}
 
 	if runtime.GOOS == "darwin" && client.useVSock() {
@@ -268,7 +255,7 @@ func (client *client) Start(ctx context.Context, startConfig types.StartConfig)
 	}
 
 	// Post-VM start
-	vmState, err := host.Driver.GetState()
+	vmState, err = host.Driver.GetState()
 	if err != nil {
 		return nil, errors.Wrap(err, "Error getting the state")
 	}
@@ -521,15 +508,53 @@ func makeDaemonVisibleToHyperkit(name string) error {
 	return nil
 }
 
-func createHost(ctx context.Context, api libmachine.API, machineConfig config.MachineConfig) (*host.Host, error) {
+func createHost(api *libmachine.Client, machineConfig config.MachineConfig) error {
 	vm, err := newHost(api, machineConfig)
 	if err != nil {
-		return nil, fmt.Errorf("Error creating new host: %s", err)
+		return fmt.Errorf("Error creating new host: %s", err)
+	}
+
+	logging.Debug("Running pre-create checks...")
+
+	if err := vm.Driver.PreCreateCheck(); err != nil {
+		return errors.Wrap(err, "error with pre-create check")
 	}
-	if err := api.Create(ctx, vm); err != nil {
-		return nil, fmt.Errorf("Error creating the VM: %s", err)
+
+	if err := api.Save(vm); err != nil {
+		return fmt.Errorf("Error saving host to store before attempting creation: %s", err)
 	}
-	return vm, nil
+
+	logging.Debug("Creating machine...")
+
+	if err := vm.Driver.Create(); err != nil {
+		return fmt.Errorf("Error in driver during machine creation: %s", err)
+	}
+
+	logging.Debug("Machine successfully created")
+	return nil
+}
+
+func startHost(ctx context.Context, api *libmachine.Client, vm *host.Host) error {
+	if err := vm.Driver.Start(); err != nil {
+		return fmt.Errorf("Error in driver during machine start: %s", err)
+	}
+
+	if err := api.Save(vm); err != nil {
+		return fmt.Errorf("Error saving host to store after attempting creation: %s", err)
+	}
+
+	logging.Debug("Waiting for machine to be running, this may take a few minutes...")
+	if err := crcerrors.RetryAfterWithContext(ctx, 3*time.Minute, host.MachineInState(vm.Driver, state.Running), 3*time.Second); err != nil {
+		return fmt.Errorf("Error waiting for machine to be running: %s", err)
+	}
+
+	logging.Debug("Machine is up and running!")
+
+	if err := api.SetExists(vm.Name); err != nil {
+		logging.Debug("Failed to record VM existence")
+	}
+
+	return nil
 }
 
 func addNameServerToInstance(sshRunner *crcssh.Runner, ns string) error {
diff --git a/pkg/libmachine/host/host.go b/pkg/libmachine/host/host.go
index da8d1b375..9319df22f 100644
--- a/pkg/libmachine/host/host.go
+++ b/pkg/libmachine/host/host.go
@@ -43,17 +43,6 @@ func (h *Host) runActionForState(action func() error, desiredState state.State)
 	return crcerrors.RetryAfter(3*time.Minute, MachineInState(h.Driver, desiredState), 3*time.Second)
 }
 
-func (h *Host) Start() error {
-	log.Debugf("Starting %q...", h.Name)
-	if err := h.runActionForState(h.Driver.Start, state.Running); err != nil {
-		return err
-	}
-
-	log.Debugf("Machine %q was started.", h.Name)
-
-	return nil
-}
-
 func (h *Host) Stop() error {
 	log.Debugf("Stopping %q...", h.Name)
 	if err := h.runActionForState(h.Driver.Stop, state.Stopped); err != nil {
diff --git a/pkg/libmachine/libmachine.go b/pkg/libmachine/libmachine.go
index 5609b3524..d5ff56b2c 100644
--- a/pkg/libmachine/libmachine.go
+++ b/pkg/libmachine/libmachine.go
@@ -1,27 +1,19 @@
 package libmachine
 
 import (
-	"context"
 	"encoding/json"
-	"fmt"
 	"io"
-	"time"
 
-	crcerrors "github.com/code-ready/crc/pkg/crc/errors"
-	log "github.com/code-ready/crc/pkg/crc/logging"
 	"github.com/code-ready/crc/pkg/drivers/hyperv"
 	"github.com/code-ready/crc/pkg/libmachine/host"
 	"github.com/code-ready/crc/pkg/libmachine/persist"
 	"github.com/code-ready/machine/libmachine/drivers"
 	rpcdriver "github.com/code-ready/machine/libmachine/drivers/rpc"
-	"github.com/code-ready/machine/libmachine/state"
-	"github.com/pkg/errors"
 )
 
 type API interface {
 	io.Closer
 	NewHost(driverName string, driverPath string, rawDriver []byte) (*host.Host, error)
-	Create(ctx context.Context, h *host.Host) error
 	persist.Store
 }
 
@@ -85,55 +77,6 @@ func (api *Client) Load(name string) (*host.Host, error) {
 	return h, nil
 }
 
-// Create is the wrapper method which covers all of the boilerplate around
-// actually creating, provisioning, and persisting an instance in the store.
-func (api *Client) Create(ctx context.Context, h *host.Host) error {
-	log.Debug("Running pre-create checks...")
-
-	if err := h.Driver.PreCreateCheck(); err != nil {
-		return errors.Wrap(err, "error with pre-create check")
-	}
-
-	if err := api.Save(h); err != nil {
-		return fmt.Errorf("Error saving host to store before attempting creation: %s", err)
-	}
-
-	log.Debug("Creating machine...")
-
-	if err := api.performCreate(ctx, h); err != nil {
-		return fmt.Errorf("Error creating machine: %s", err)
-	}
-
-	log.Debug("Machine successfully created")
-	if err := api.SetExists(h.Name); err != nil {
-		log.Debug("Failed to record VM existence")
-	}
-
-	return nil
-}
-
-func (api *Client) performCreate(ctx context.Context, h *host.Host) error {
-	if err := h.Driver.Create(); err != nil {
-		return fmt.Errorf("Error in driver during machine creation: %s", err)
-	}
-
-	if err := h.Driver.Start(); err != nil {
-		return fmt.Errorf("Error in driver during machine start: %s", err)
-	}
-
-	if err := api.Save(h); err != nil {
-		return fmt.Errorf("Error saving host to store after attempting creation: %s", err)
-	}
-
-	log.Debug("Waiting for machine to be running, this may take a few minutes...")
-	if err := crcerrors.RetryAfterWithContext(ctx, 3*time.Minute, host.MachineInState(h.Driver, state.Running), 3*time.Second); err != nil {
-		return fmt.Errorf("Error waiting for machine to be running: %s", err)
-	}
-
-	log.Debug("Machine is up and running!")
-	return nil
-}
-
 func (api *Client) Close() error {
 	return api.clientDriverFactory.Close()
 }


Test patch:
diff --git a/pkg/crc/logging/inmemory_test.go b/pkg/crc/logging/inmemory_test.go
index 3061878aa..9a13eac6d 100644
--- a/pkg/crc/logging/inmemory_test.go
+++ b/pkg/crc/logging/inmemory_test.go
@@ -21,3 +21,26 @@ func TestAddLogs(t *testing.T) {
 
 	assert.Equal(t, []string{"message 5", "message 6", "message 7", "message 8", "message 9"}, memory.Messages())
 }
+
+func TestRace(t *testing.T) {
+	memory := newInMemoryHook(5)
+
+	done := make(chan bool)
+	go func() {
+		for i := 0; i < 10000; i++ {
+			_ = memory.Fire(&logrus.Entry{
+				Message: "my message",
+			})
+		}
+		done <- true
+	}()
+
+	for {
+		select {
+		case <-done:
+			return
+		default:
+			assert.GreaterOrEqual(t, len(memory.Messages()), 0)
+		}
+	}
+}
diff --git a/test/e2e/crcsuite/crcsuite.go b/test/e2e/crcsuite/crcsuite.go
index 23ea89b4f..64dce8af5 100644
--- a/test/e2e/crcsuite/crcsuite.go
+++ b/test/e2e/crcsuite/crcsuite.go
@@ -188,6 +188,7 @@ func RemoveCRCHome() error {
 }
 
 func CheckHTTPResponseWithRetry(retryCount int, retryWait string, address string, expectedStatusCode int) error {
+	var err error
 
 	retryDuration, err := time.ParseDuration(retryWait)
 	if err != nil {
@@ -203,15 +204,15 @@ func CheckHTTPResponseWithRetry(retryCount int, retryWait string, address string
 	var resp *http.Response
 	for i := 0; i < retryCount; i++ {
 		resp, err = client.Get(address)
-		if err != nil {
-			return err
-		}
-		if resp.StatusCode == expectedStatusCode {
+		if err == nil && resp.StatusCode == expectedStatusCode {
 			return nil
 		}
 		time.Sleep(retryDuration)
 	}
 
+	if err != nil {
+		return err
+	}
 	return fmt.Errorf("got %d as Status Code instead of expected %d", resp.StatusCode, expectedStatusCode)
 }