Repository: kubernetes/minikube
Pull request #8543 (2020-06-24 02:39:53)

Improve error and logging emitted by WaitForAppsRunning
* The WaitForAppsRunning error will now return the list of pods missing.
* During the polling loop, it will also log pod states, which are helplful for debugging.
* Use exponential backoff (starting at 500ms) to avoid DoS attacking the apiserver, useful when running heavily parallelized tests

New logs example:

```
I0623 19:38:47.581134   81217 system_pods.go:90] "kube-scheduler-kindnet-20200623191407-81210" [4c84108b-7cf2-4557-879b-5e07a4b743e6] Running
I0623 19:38:47.581139   81217 system_pods.go:90] "storage-provisioner" [77bc79cf-d311-4b8a-aca9-a1a3acfb6baa] Pending / Ready:ContainersNotReady (containers with unready status: [storage-provisioner]) / ContainersReady:ContainersNotReady (containers with unready status: [storage-provisioner])
0623 19:38:47.581145   81217 system_pods.go:123] expect apps running failed: missing components: kube-dns, kube-proxy
```

New error message example:

`failed to start node: startup failed: wait 20m0s for node: waiting for apps_running: expected k8s-apps: missing components: kube-dns, kube-proxy`



Patch:
diff --git a/pkg/minikube/bootstrapper/bsutil/kverify/system_pods.go b/pkg/minikube/bootstrapper/bsutil/kverify/system_pods.go
index 68cb52c5d..d5c6dc21b 100644
--- a/pkg/minikube/bootstrapper/bsutil/kverify/system_pods.go
+++ b/pkg/minikube/bootstrapper/bsutil/kverify/system_pods.go
@@ -27,7 +27,6 @@ import (
 	"github.com/pkg/errors"
 	core "k8s.io/api/core/v1"
 	meta "k8s.io/apimachinery/pkg/apis/meta/v1"
-	"k8s.io/apimachinery/pkg/util/wait"
 	"k8s.io/client-go/kubernetes"
 	kconst "k8s.io/kubernetes/cmd/kubeadm/app/constants"
 	"k8s.io/minikube/pkg/minikube/bootstrapper"
@@ -36,6 +35,7 @@ import (
 	"k8s.io/minikube/pkg/minikube/cruntime"
 	"k8s.io/minikube/pkg/minikube/logs"
 	"k8s.io/minikube/pkg/minikube/sysinit"
+	"k8s.io/minikube/pkg/util/retry"
 )
 
 // WaitForSystemPods verifies essential pods for running kurnetes is running
@@ -43,10 +43,7 @@ func WaitForSystemPods(r cruntime.Manager, bs bootstrapper.Bootstrapper, cfg con
 	glog.Info("waiting for kube-system pods to appear ...")
 	pStart := time.Now()
 
-	podList := func() (bool, error) {
-		if time.Since(start) > timeout {
-			return false, fmt.Errorf("cluster wait timed out during pod check")
-		}
+	podList := func() error {
 		if time.Since(start) > minLogCheckTime {
 			announceProblems(r, bs, cfg, cr)
 			time.Sleep(kconst.APICallRetryInterval * 5)
@@ -56,19 +53,22 @@ func WaitForSystemPods(r cruntime.Manager, bs bootstrapper.Bootstrapper, cfg con
 		pods, err := client.CoreV1().Pods("kube-system").List(meta.ListOptions{})
 		if err != nil {
 			glog.Warningf("pod list returned error: %v", err)
-			return false, nil
+			return err
 		}
+
 		glog.Infof("%d kube-system pods found", len(pods.Items))
 		for _, pod := range pods.Items {
 			glog.Infof(podStatusMsg(pod))
 		}
 
 		if len(pods.Items) < 2 {
-			return false, nil
+			return fmt.Errorf("only %d pod(s) have shown up", len(pods.Items))
 		}
-		return true, nil
+
+		return nil
 	}
-	if err := wait.PollImmediate(kconst.APICallRetryInterval, timeout, podList); err != nil {
+
+	if err := retry.Local(podList, timeout); err != nil {
 		return fmt.Errorf("apiserver never returned a pod list")
 	}
 	glog.Infof("duration metric: took %s to wait for pod list to return data ...", time.Since(pStart))
@@ -83,11 +83,15 @@ func ExpectAppsRunning(cs *kubernetes.Clientset, expected []string) error {
 	if err != nil {
 		return err
 	}
+	glog.Infof("%d kube-system pods found", len(pods.Items))
 
 	for _, pod := range pods.Items {
+		glog.Infof(podStatusMsg(pod))
+
 		if pod.Status.Phase != core.PodRunning {
 			continue
 		}
+
 		for k, v := range pod.ObjectMeta.Labels {
 			if k == "component" || k == "k8s-app" {
 				found[v] = true
@@ -112,15 +116,12 @@ func WaitForAppsRunning(cs *kubernetes.Clientset, expected []string, timeout tim
 	glog.Info("waiting for k8s-apps to be running ...")
 	start := time.Now()
 
-	checkRunning := func() (bool, error) {
-		if err := ExpectAppsRunning(cs, expected); err != nil {
-			return false, nil
-		}
-		return true, nil
+	checkRunning := func() error {
+		return ExpectAppsRunning(cs, expected)
 	}
 
-	if err := wait.PollImmediate(kconst.APICallRetryInterval, timeout, checkRunning); err != nil {
-		return errors.Wrapf(err, "checking k8s-apps to be running")
+	if err := retry.Local(checkRunning, timeout); err != nil {
+		return errors.Wrapf(err, "expected k8s-apps")
 	}
 	glog.Infof("duration metric: took %s to wait for k8s-apps to be running ...", time.Since(start))
 	return nil
diff --git a/pkg/minikube/cruntime/docker.go b/pkg/minikube/cruntime/docker.go
index dcb8beff9..55e57b3a5 100644
--- a/pkg/minikube/cruntime/docker.go
+++ b/pkg/minikube/cruntime/docker.go
@@ -104,8 +104,6 @@ func (r *Docker) Active() bool {
 
 // Enable idempotently enables Docker on a host
 func (r *Docker) Enable(disOthers, forceSystemd bool) error {
-	containerdWasActive := r.Init.Active("containerd")
-
 	if disOthers {
 		if err := disableOthers(r, r.Runner); err != nil {
 			glog.Warningf("disableOthers: %v", err)
@@ -119,11 +117,6 @@ func (r *Docker) Enable(disOthers, forceSystemd bool) error {
 		return r.Init.Restart("docker")
 	}
 
-	if containerdWasActive && !dockerBoundToContainerd(r.Runner) {
-		// Make sure to use the internal containerd
-		return r.Init.Restart("docker")
-	}
-
 	return r.Init.Start("docker")
 }
 
diff --git a/pkg/util/retry/retry.go b/pkg/util/retry/retry.go
index 18298459b..8bdacf461 100644
--- a/pkg/util/retry/retry.go
+++ b/pkg/util/retry/retry.go
@@ -14,16 +14,31 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
+// Package retry implements wrappers to retry function calls
 package retry
 
 import (
 	"time"
 
 	"github.com/cenkalti/backoff"
+	"github.com/golang/glog"
 )
 
 const defaultMaxRetries = 113
 
+func notify(err error, d time.Duration) {
+	glog.Infof("will retry after %s: %v", d, err)
+}
+
+// Local is back-off retry for local connections
+func Local(callback func() error, maxTime time.Duration) error {
+	b := backoff.NewExponentialBackOff()
+	b.InitialInterval = 250 * time.Millisecond
+	b.RandomizationFactor = 0.25
+	b.Multiplier = 1.25
+	return backoff.RetryNotify(callback, b, notify)
+}
+
 // Expo is exponential backoff retry.
 // initInterval is the initial waiting time to start with.
 // maxTime is the max time allowed to spend on the all the retries.
@@ -40,7 +55,7 @@ func Expo(callback func() error, initInterval time.Duration, maxTime time.Durati
 	b.RandomizationFactor = 0.5
 	b.Multiplier = 1.5
 	bm := backoff.WithMaxRetries(b, maxRetry)
-	return backoff.Retry(callback, bm)
+	return backoff.RetryNotify(callback, bm, notify)
 }
 
 // RetriableError is an error that can be tried again


Test patch:
diff --git a/pkg/minikube/cruntime/cruntime_test.go b/pkg/minikube/cruntime/cruntime_test.go
index 8ed6fddf0..8f5aca6f4 100644
--- a/pkg/minikube/cruntime/cruntime_test.go
+++ b/pkg/minikube/cruntime/cruntime_test.go
@@ -478,16 +478,6 @@ func (f *FakeRunner) systemctl(args []string, root bool) (string, error) { // no
 				return out, nil
 			}
 			return out, fmt.Errorf("%s in state: %v", svc, state)
-		case "cat":
-			f.t.Logf("fake systemctl: %s cat: %v", svc, state)
-			if svc == "docker.service" {
-				out += "[Unit]\n"
-				out += "Description=Docker Application Container Engine\n"
-				out += "Documentation=https://docs.docker.com\n"
-				//out += "BindsTo=containerd.service\n"
-				return out, nil
-			}
-			return out, fmt.Errorf("%s cat unimplemented", svc)
 		default:
 			return out, fmt.Errorf("unimplemented fake action: %q", action)
 		}
@@ -536,14 +526,6 @@ var defaultServices = map[string]serviceState{
 	"containerd":    SvcExited,
 }
 
-// allServices reflects the state of all actual services running at once
-var allServices = map[string]serviceState{
-	"docker":        SvcRunning,
-	"crio":          SvcRunning,
-	"crio-shutdown": SvcExited,
-	"containerd":    SvcRunning,
-}
-
 func TestDisable(t *testing.T) {
 	var tests = []struct {
 		runtime string
@@ -576,43 +558,32 @@ func TestDisable(t *testing.T) {
 
 func TestEnable(t *testing.T) {
 	var tests = []struct {
-		runtime  string
-		services map[string]serviceState
-		want     map[string]serviceState
+		runtime string
+		want    map[string]serviceState
 	}{
-		{"docker", defaultServices,
-			map[string]serviceState{
-				"docker":        SvcRunning,
-				"containerd":    SvcExited,
-				"crio":          SvcExited,
-				"crio-shutdown": SvcExited,
-			}},
-		{"docker", allServices,
-			map[string]serviceState{
-				"docker":        SvcRestarted,
-				"containerd":    SvcExited,
-				"crio":          SvcExited,
-				"crio-shutdown": SvcExited,
-			}},
-		{"containerd", defaultServices,
-			map[string]serviceState{
-				"docker":        SvcExited,
-				"containerd":    SvcRestarted,
-				"crio":          SvcExited,
-				"crio-shutdown": SvcExited,
-			}},
-		{"crio", defaultServices,
-			map[string]serviceState{
-				"docker":        SvcExited,
-				"containerd":    SvcExited,
-				"crio":          SvcRunning,
-				"crio-shutdown": SvcExited,
-			}},
+		{"docker", map[string]serviceState{
+			"docker":        SvcRunning,
+			"containerd":    SvcExited,
+			"crio":          SvcExited,
+			"crio-shutdown": SvcExited,
+		}},
+		{"containerd", map[string]serviceState{
+			"docker":        SvcExited,
+			"containerd":    SvcRestarted,
+			"crio":          SvcExited,
+			"crio-shutdown": SvcExited,
+		}},
+		{"crio", map[string]serviceState{
+			"docker":        SvcExited,
+			"containerd":    SvcExited,
+			"crio":          SvcRunning,
+			"crio-shutdown": SvcExited,
+		}},
 	}
 	for _, tc := range tests {
 		t.Run(tc.runtime, func(t *testing.T) {
 			runner := NewFakeRunner(t)
-			for k, v := range tc.services {
+			for k, v := range defaultServices {
 				runner.services[k] = v
 			}
 			cr, err := New(Config{Type: tc.runtime, Runner: runner})