Repository: code-ready/crc
Pull request #2003 (2021-02-15 13:36:25)

Be sure that crc start ends up with a working cluster
Most of the time, at the end of crc start, the cluster is broken: 3min is not enough. 
@jsliacan solved this in the CI by waiting 3 consecutive running statuses (1min interval). 

This PR replaces the sleep(3 min) by a check of 3 consecutive checks (30s interval). 

It also changes the output of the crc start. It says now why it is waiting (and this is not CRC fault).

I found this PR really needed since we changed the output of crc start. Now if the user clicks on the console URL, it will simply work.

4.6.16 bundle: 

```
INFO Starting OpenShift cluster ... [waiting for the cluster to stabilize] 
INFO 2 operators are progressing: authentication, image-registry 
INFO 3 operators are progressing: authentication, image-registry, operator-lifecycle-manager-packageserver 
INFO 3 operators are progressing: authentication, dns, image-registry 
INFO Operator image-registry is progressing       
INFO 2 operators are not available: authentication, openshift-apiserver 
INFO Operator kube-apiserver is progressing       
INFO Operator kube-apiserver is progressing       
INFO Operator kube-apiserver is progressing       
INFO Operator kube-apiserver is progressing       
INFO Operator kube-apiserver is progressing       
INFO All operators are available. Ensuring stability ... 
INFO Operators are stable (2/3) ...               
INFO Operators are stable (3/3) ...    
```

4.6.15 bundle (4m10s total wait):
```
INFO Starting OpenShift cluster ... [waiting for the cluster to stabilize] 
INFO 7 operators are progressing: authentication, dns, image-registry, network, openshift-controller-manager, operator-lifecycle-manager-packageserver, service-ca 
INFO 7 operators are progressing: authentication, dns, image-registry, network, openshift-controller-manager, operator-lifecycle-manager-packageserver, service-ca 
INFO 4 operators are progressing: authentication, image-registry, openshift-controller-manager, service-ca 
INFO 4 operators are progressing: authentication, console, image-registry, service-ca 
INFO Operator ingress is degraded                 
INFO Operator authentication is progressing       
INFO All operators are available. Ensuring stability ... 
INFO Operators are stable (2/3) ...               
INFO Operators are stable (3/3) ...    
```

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

This pull-request has been approved by: *<a href="https://github.com/code-ready/crc/pull/2003#" 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":[]} -->
gbraad: > Checking stability

This indicates uncertainty.  Can we use availability?
gbraad: > Checking stability

This indicates uncertainty.  Can we use availability?
jsliacan: > This indicates uncertainty. Can we use availability?

In this case, it is probably stability though... We want "availability over time", i.e. stability, imo. But I would maybe suggest to change `Checking stability...` to `Ensuring stability...`. But that's just being petty. 
gbraad: > Ensuring stability

yep... as 'we' can't ensure that. we can only check for it.
although where does this 'stability' come from? what do we check for?
This is why I mentioned availability; but it should include the work 'operator' as this is what is being checked.
guillaumerose: @gbraad @jsliacan I changed the wording with `Ensuring stability`. Check the PR description to see the final output.
guillaumerose: @cfergeau I updated the commit log, it should be better
guillaumerose: I run this couple of times and here are some numbers I got:

```
 level=debug msg="Cluster took 5m5.77392309s to stabilize"
 level=debug msg="Cluster took 3m14.719086407s to stabilize"
 level=debug msg="Cluster took 4m54.412423508s to stabilize"
 level=debug msg="Cluster took 9m53.335788713s to stabilize"
 level=debug msg="Cluster took 7m26.386394568s to stabilize"
 level=debug msg="Cluster took 4m10.586245613s to stabilize"
 level=debug msg="Cluster took 4m4.36198784s to stabilize"
```

I can add code that checks if the state is not ready and is not moving for X minutes, then return an error. This will avoid waiting up to 10min.
gbraad: 7 and 9? Did you use the machine in the meantime?
gbraad: Without reading the commit logs and the description her I understand it was about the state of the operators. This is confirmed by the actual code.

So perhaps it is better not to have any commit logs in that case? And rely on the issue description.

We keep going around in circles. I would like to stress; working code is more important than extensive documentation (git descriptions). If the code I behaviour matches expectations I deem that more important.
gbraad: The original implementation left people guessing about the state and just bailed out and saud; we don't know, we don't wait any longer, it returned to the prompt and let's the user guess if things work.

Anythibg around this change is in line with the reported issues to handle the startup; check state of the operators.

So even if it looks like the command runs longer, it is effectively a much better outcome.
openshift-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/code-ready/crc/pull/2003#pullrequestreview-591110615" title="Approved">gbraad</a>*, *<a href="https://github.com/code-ready/crc/pull/2003#" 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)~~ [gbraad,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: 9min53 and 7min are made with crc_libvirt_4.6.16.crcbundle bundle.
Others are with crc_libvirt_4.6.15.crcbundle (the bundle in the release).

@praveenkumar any thoughts on this?
jsliacan: @guillaumerose , not sure if this helps with deciding, but woopra gives this for start times (with 3min wait regardless of the state of the cluster):

| start duration  [min]    | % of actions |
| ----------- | ----------- |
| 3-4      | 1      |
| 4-5 | 45 |
| 5-6 | 23 |
| 6-7 | 12 |
| 7-8 | 6.5 |
| 8-9 | 4 |
| 9-10 | 2.2 |
| 10-11 | 1.33 |
| 11+ | 1 |

So your PR would be just at the back of the pile. I guess the question is: Those 81% (1+45+23+12) of the users who get a faster start than your new one, do they get a cluster that's not ready? If yes, then it's definitely an improvement. If not, then I guess it's back to the value judgement (better fast with fewer guarantees, or slower with more reliability)? :) Glad to be of no help whatsoever!
openshift-ci-robot: New changes are detected. LGTM label has been removed.
gbraad: > 9min53 and 7min are made with crc_libvirt_4.6.16.crcbundle bundle.
> Others are with crc_libvirt_4.6.15.crcbundle (the bundle in the release).

So this is based on the bundle. Would like to see if a monitoring pipeline would catch that too.
it is concerning that there are clear jumps in startup time for certain bundles.
cfergeau: > I would like to stress; working code is more important than extensive documentation (git descriptions). If the code I behaviour matches expectations I deem that more important.

If the expectations are not explicitly listed in the commit log (or in the issue or in the PR description), then the developer may intend to do one thing, the code may be correct, but doing something different, and the reviewer might expect a 3rd behaviour. If you state what you want to do in the commit log, you remove this ambiguity, and allow to actually check that the code matches expectations.

> So perhaps it is better not to have any commit logs in that case? And rely on the issue description ?

Replace `git log` with numbers that you have to c&p in your browser after opening N tab and going to the issues page? This does not seem very efficient. And the outcome of issues with dozens of comments need to be summarized somewhere.
guillaumerose: CI failed right now when I removed the check on the test side.

```
time="2021-02-16T14:28:03Z" level=info msg="2 operators are progressing: kube-apiserver, operator-lifecycle-manager-packageserver"
time="2021-02-16T14:28:33Z" level=error msg="Cluster is not ready: cluster operators are still not stable after 10m15.219159472s"
```

The cluster is unusable at all if the kube-apiserver is not ready (even after 10min!).

retest this please
jsliacan: > CI failed right now when I removed the check on the test side.

@guillaumerose I think this was the case with one of the older bundles as well (around the time this test went in). I remember first having 3 conseq. 1min waits within 10 mins and failing CI. Then I increased it to 15min. Not sure if it's 4.6.16 specific or if it's a returning issue.
gbraad: > If the expectations are not explicitly listed in the commit log

the expectation match the outcome of what previously existed in the testcase.
praveenkumar: @jsliacan @adrianriobo Can you folks also test this patch to downstream CI, I am just worry about we are using `10m` time now to check if cluster is stable and the CI test used `15m` . This shouldn't impact on the internal CI pipeline which took some time now for being stabilize.  
guillaumerose: What is your final word @jsliacan ? What should be the timeout ? 15min ?
cfergeau: I ran some testing on this, and the wait for 3 consecutive 'good' states still feels quite arbitrary :-/ On initial start, once it's stabilized once, waiting 1 more minute does not seem really useful. On the other hand, on restarts, it's needed, as it very quickly succeed once at the 'stable' check, but then some operators get degraded. There was even one time when right after 3 successful checks, some operators became degraded/restarting (authentication, ...), so `crc start` finished successfully, but `oc get co` was not 'clean'
jsliacan: I spent good time on this today and I'm consistently getting:
- fresh start ~7-9min to stabilize
- start from stop ~4-5min to stabilize (I didn't find any run, out of 10, that passed this and some operator wasn't running in the next 2 minutes as well)
Seems (at the very least) no worse than the original approach in terms of handing over a running cluster. @cfergeau's comment worries me a bit though ...

I don't mind all the output, but it's easy to agree with Christophe about non-monotonicity of the information displayed. 

Patch:
diff --git a/cmd/crc/cmd/config/config.go b/cmd/crc/cmd/config/config.go
index 249b323a1..8c9bbe5fb 100644
--- a/cmd/crc/cmd/config/config.go
+++ b/cmd/crc/cmd/config/config.go
@@ -23,6 +23,7 @@ const (
 	DisableUpdateCheck      = "disable-update-check"
 	ExperimentalFeatures    = "enable-experimental-features"
 	NetworkMode             = "network-mode"
+	HostNetworkAccess       = "host-network-access"
 	HTTPProxy               = "http-proxy"
 	HTTPSProxy              = "https-proxy"
 	NoProxy                 = "no-proxy"
@@ -32,6 +33,15 @@ const (
 )
 
 func RegisterSettings(cfg *config.Config) {
+	validateHostNetworkAccess := func(value interface{}) (bool, string) {
+		mode := network.ParseMode(cfg.Get(NetworkMode).AsString())
+		if mode != network.VSockMode {
+			return false, fmt.Sprintf("%s can only be used with %s set to '%s'",
+				HostNetworkAccess, NetworkMode, network.VSockMode)
+		}
+		return config.ValidateBool(value)
+	}
+
 	// Start command settings in config
 	cfg.AddSetting(Bundle, constants.DefaultBundlePath, config.ValidateBundlePath, config.SuccessfullyApplied,
 		fmt.Sprintf("Bundle path (string, default '%s')", constants.DefaultBundlePath))
@@ -51,6 +61,8 @@ func RegisterSettings(cfg *config.Config) {
 		"Enable experimental features (true/false, default: false)")
 	cfg.AddSetting(NetworkMode, string(network.DefaultMode), network.ValidateMode, network.SuccessfullyAppliedMode,
 		"Network mode (default or vsock)")
+	cfg.AddSetting(HostNetworkAccess, false, validateHostNetworkAccess, config.SuccessfullyApplied,
+		"Allow TCP/IP connections from the CodeReday Containers VM to services running on the host (true/false, default: false)")
 	// Proxy Configuration
 	cfg.AddSetting(HTTPProxy, "", config.ValidateURI, config.SuccessfullyApplied,
 		"HTTP proxy URL (string, like 'http://my-proxy.com:8443')")
diff --git a/cmd/crc/cmd/daemon.go b/cmd/crc/cmd/daemon.go
index 0b656cd45..110c4ea7c 100644
--- a/cmd/crc/cmd/daemon.go
+++ b/cmd/crc/cmd/daemon.go
@@ -12,6 +12,7 @@ import (
 	"syscall"
 	"time"
 
+	cmdConfig "github.com/code-ready/crc/cmd/crc/cmd/config"
 	"github.com/code-ready/crc/pkg/crc/api"
 	"github.com/code-ready/crc/pkg/crc/constants"
 	"github.com/code-ready/gvisor-tap-vsock/pkg/transport"
@@ -45,8 +46,7 @@ var daemonCmd = &cobra.Command{
 				endpoints = append(endpoints, transport.DefaultURL)
 			}
 		}
-
-		err := run(&types.Configuration{
+		virtualNetworkConfig := types.Configuration{
 			Debug:             false, // never log packets
 			CaptureFile:       captureFile(),
 			MTU:               4000, // Large packets slightly improve the performance. Less small packets.
@@ -77,10 +77,6 @@ var daemonCmd = &cobra.Command{
 							Regexp: regexp.MustCompile("crc-(.*?)-master-0"),
 							IP:     net.ParseIP("192.168.126.11"),
 						},
-						{
-							Name: "host",
-							IP:   net.ParseIP(hostVirtualIP),
-						},
 					},
 				},
 			},
@@ -89,10 +85,25 @@ var daemonCmd = &cobra.Command{
 				":6443": "192.168.127.2:6443",
 				":443":  "192.168.127.2:443",
 			},
-			NAT: map[string]string{
-				hostVirtualIP: "127.0.0.1",
-			},
-		}, endpoints)
+		}
+		if config.Get(cmdConfig.HostNetworkAccess).AsBool() {
+			log.Debugf("Enabling host network access")
+			for i := range virtualNetworkConfig.DNS {
+				zone := &virtualNetworkConfig.DNS[i]
+				if zone.Name != "crc.testing." {
+					continue
+				}
+				log.Debugf("Adding \"host\" -> %s DNS record to crc.testing. zone", hostVirtualIP)
+
+				zone.Records = append(zone.Records, types.Record{Name: "host", IP: net.ParseIP(hostVirtualIP)})
+			}
+
+			if virtualNetworkConfig.NAT == nil {
+				virtualNetworkConfig.NAT = make(map[string]string)
+			}
+			virtualNetworkConfig.NAT[hostVirtualIP] = "127.0.0.1"
+		}
+		err := run(&virtualNetworkConfig, endpoints)
 		return err
 	},
 }
diff --git a/pkg/crc/cluster/clusteroperator.go b/pkg/crc/cluster/clusteroperator.go
index 81a8927a4..f1ec234b7 100644
--- a/pkg/crc/cluster/clusteroperator.go
+++ b/pkg/crc/cluster/clusteroperator.go
@@ -3,10 +3,11 @@ package cluster
 import (
 	"encoding/json"
 	"errors"
+	"fmt"
+	"strings"
 
 	"github.com/code-ready/crc/pkg/crc/logging"
 	"github.com/code-ready/crc/pkg/crc/oc"
-
 	openshiftapi "github.com/openshift/api/config/v1"
 )
 
@@ -18,6 +19,39 @@ type Status struct {
 	Degraded    bool
 	Progressing bool
 	Disabled    bool
+
+	progressing []string
+	degraded    []string
+	unavailable []string
+}
+
+func (status *Status) String() string {
+	if len(status.progressing) == 1 {
+		return fmt.Sprintf("Operator %s is progressing", status.progressing[0])
+	} else if len(status.progressing) > 1 {
+		return fmt.Sprintf("%d operators are progressing: %s", len(status.progressing), strings.Join(status.progressing, ", "))
+	}
+
+	if len(status.degraded) == 1 {
+		return fmt.Sprintf("Operator %s is degraded", status.degraded[0])
+	} else if len(status.degraded) > 0 {
+		return fmt.Sprintf("%d operators are degraded: %s", len(status.degraded), strings.Join(status.degraded, ", "))
+	}
+
+	if len(status.unavailable) == 1 {
+		return fmt.Sprintf("Operator %s is not yet available", status.unavailable[0])
+	} else if len(status.unavailable) > 0 {
+		return fmt.Sprintf("%d operators are not available: %s", len(status.unavailable), strings.Join(status.unavailable, ", "))
+	}
+
+	if status.IsReady() {
+		return "All operators are ready"
+	}
+	return "Operators are not ready yet"
+}
+
+func (status *Status) IsReady() bool {
+	return status.Available && !status.Progressing && !status.Degraded && !status.Disabled
 }
 
 func GetClusterOperatorStatus(ocConfig oc.Config, operator string) (*Status, error) {
@@ -61,16 +95,19 @@ func getStatus(ocConfig oc.Config, ignoreClusterOperators, selector []string) (*
 			case "Available":
 				if con.Status != "True" {
 					logging.Debug(c.ObjectMeta.Name, " operator not available, Reason: ", con.Reason)
+					cs.unavailable = append(cs.unavailable, c.ObjectMeta.Name)
 					cs.Available = false
 				}
 			case "Degraded":
 				if con.Status == "True" {
 					logging.Debug(c.ObjectMeta.Name, " operator is degraded, Reason: ", con.Reason)
+					cs.degraded = append(cs.degraded, c.ObjectMeta.Name)
 					cs.Degraded = true
 				}
 			case "Progressing":
 				if con.Status == "True" {
 					logging.Debug(c.ObjectMeta.Name, " operator is still progressing, Reason: ", con.Reason)
+					cs.progressing = append(cs.progressing, c.ObjectMeta.Name)
 					cs.Progressing = true
 				}
 			case "Upgradeable":
diff --git a/pkg/crc/cluster/status.go b/pkg/crc/cluster/status.go
new file mode 100644
index 000000000..9e54c9ef5
--- /dev/null
+++ b/pkg/crc/cluster/status.go
@@ -0,0 +1,48 @@
+package cluster
+
+import (
+	"fmt"
+	"time"
+
+	"github.com/code-ready/crc/pkg/crc/logging"
+	"github.com/code-ready/crc/pkg/crc/oc"
+)
+
+// WaitForClusterStable checks that the cluster is running a number of consecutive times
+func WaitForClusterStable(ocConfig oc.Config, monitoringEnabled bool) error {
+	startTime := time.Now()
+
+	retryDuration := 30 * time.Second
+	retryCount := 20 // 10 minutes
+
+	numConsecutive := 3
+	var count int // holds num of consecutive matches
+
+	for i := 0; i < retryCount; i++ {
+		status, err := GetClusterOperatorsStatus(ocConfig, monitoringEnabled)
+		if err == nil {
+			// update counter for consecutive matches
+			if status.IsReady() {
+				count++
+				if count == 1 {
+					logging.Info("All operators are available. Ensuring stability ...")
+				} else {
+					logging.Infof("Operators are stable (%d/%d) ...", count, numConsecutive)
+				}
+			} else {
+				logging.Info(status.String())
+				count = 0
+			}
+			// break if done
+			if count == numConsecutive {
+				logging.Debugf("Cluster took %s to stabilize", time.Since(startTime))
+				return nil
+			}
+		} else {
+			count = 0
+		}
+		time.Sleep(retryDuration)
+	}
+
+	return fmt.Errorf("cluster operators are still not stable after %s", time.Since(startTime))
+}
diff --git a/pkg/crc/machine/kubeconfig.go b/pkg/crc/machine/kubeconfig.go
index bd7b54476..f026eab3a 100644
--- a/pkg/crc/machine/kubeconfig.go
+++ b/pkg/crc/machine/kubeconfig.go
@@ -36,7 +36,7 @@ func eventuallyWriteKubeconfig(ocConfig oc.Config, ip string, clusterConfig *Clu
 		if err != nil {
 			return &errors.RetriableError{Err: err}
 		}
-		if isReady(status) {
+		if status.IsReady() {
 			return nil
 		}
 		return &errors.RetriableError{Err: goerrors.New("cluster operator authentication not ready")}
@@ -48,10 +48,6 @@ func eventuallyWriteKubeconfig(ocConfig oc.Config, ip string, clusterConfig *Clu
 	return nil
 }
 
-func isReady(status *cluster.Status) bool {
-	return status.Available && !status.Progressing && !status.Degraded && !status.Disabled
-}
-
 func WriteKubeconfig(ip string, clusterConfig *ClusterConfig) error {
 	kubeconfig := getGlobalKubeConfigPath()
 	dir := filepath.Dir(kubeconfig)
diff --git a/pkg/crc/machine/start.go b/pkg/crc/machine/start.go
index bd08f6829..15455223b 100644
--- a/pkg/crc/machine/start.go
+++ b/pkg/crc/machine/start.go
@@ -378,9 +378,11 @@ func (client *client) Start(ctx context.Context, startConfig StartConfig) (*Star
 		}
 	}
 
-	logging.Info("Starting OpenShift cluster ... [waiting 3m]")
+	logging.Info("Starting OpenShift cluster ... [waiting for the cluster to stabilize]")
 
-	time.Sleep(time.Minute * 3)
+	if err := cluster.WaitForClusterStable(ocConfig, client.monitoringEnabled()); err != nil {
+		logging.Errorf("Cluster is not ready: %v", err)
+	}
 
 	waitForProxyPropagation(ocConfig, proxyConfig)
 


Test patch:
diff --git a/pkg/crc/cluster/clusteroperator_test.go b/pkg/crc/cluster/clusteroperator_test.go
index 93491a6cc..02ac9aff2 100644
--- a/pkg/crc/cluster/clusteroperator_test.go
+++ b/pkg/crc/cluster/clusteroperator_test.go
@@ -16,6 +16,7 @@ var (
 	progressing = &Status{
 		Available:   true,
 		Progressing: true,
+		progressing: []string{"authentication"},
 	}
 )
 
diff --git a/test/e2e/crcsuite/crcsuite.go b/test/e2e/crcsuite/crcsuite.go
index bf57677a9..1e13e030c 100644
--- a/test/e2e/crcsuite/crcsuite.go
+++ b/test/e2e/crcsuite/crcsuite.go
@@ -217,44 +217,18 @@ func CheckOutputMatchWithRetry(retryCount int, retryTime string, command string,
 }
 
 // CheckCRCStatus checks that output of status command
-// matches given regex number of consecutive times
+// matches given regex
 func CheckCRCStatus(state string) error {
-	retryDuration := 1 * time.Minute
-	retryCount := 15
-	cmd := "crc status --log-level debug"
-	expression := ""
-	var numConsecutive int
-
+	expression := `.*Running \(v\d+\.\d+\.\d+.*\).*`
 	if state == "stopped" {
-		numConsecutive = 1
 		expression = ".*Stopped.*"
-	} else {
-		numConsecutive = 3
-		expression = `.*Running \(v\d+\.\d+\.\d+.*\).*`
 	}
 
-	var matchErr error
-	var count int // holds num of consecutive matches
-
-	for i := 0; i < retryCount; i++ {
-		execErr := clicumber.ExecuteCommand(cmd)
-		if execErr == nil {
-			matchErr = clicumber.CommandReturnShouldMatch("stdout", expression)
-			// update counter for consecutive matches
-			if matchErr == nil {
-				count++
-			} else {
-				count = 0
-			}
-			// break if done
-			if count == numConsecutive {
-				return nil
-			}
-		}
-		time.Sleep(retryDuration)
+	err := clicumber.ExecuteCommand("crc status --log-level debug")
+	if err != nil {
+		return err
 	}
-
-	return fmt.Errorf("did not get enough consecutive matches: have %d but need %d", count, numConsecutive)
+	return clicumber.CommandReturnShouldMatch("stdout", expression)
 }
 
 func DeleteFileFromCRCHome(fileName string) error {