From 96e35e0d70b3ec7d2f842abf0e292e2ff30213be Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Mon, 28 Sep 2020 11:17:59 -0700 Subject: [PATCH 1/4] Add 'docker status' check, improve deadline-exceeded error message --- pkg/minikube/registry/drvs/docker/docker.go | 73 +++++++++++++++------ 1 file changed, 54 insertions(+), 19 deletions(-) diff --git a/pkg/minikube/registry/drvs/docker/docker.go b/pkg/minikube/registry/drvs/docker/docker.go index ed2716a2df..d2a4f88e8a 100644 --- a/pkg/minikube/registry/drvs/docker/docker.go +++ b/pkg/minikube/registry/drvs/docker/docker.go @@ -27,6 +27,7 @@ import ( "github.com/docker/machine/libmachine/drivers" "github.com/golang/glog" + "github.com/pkg/errors" "k8s.io/minikube/pkg/drivers/kic" "k8s.io/minikube/pkg/drivers/kic/oci" "k8s.io/minikube/pkg/minikube/config" @@ -86,34 +87,60 @@ func status() registry.State { ctx, cancel := context.WithTimeout(context.Background(), 6*time.Second) defer cancel() - // Quickly returns an error code if server is not running cmd := exec.CommandContext(ctx, oci.Docker, "version", "--format", "{{.Server.Os}}-{{.Server.Version}}") o, err := cmd.Output() - output := string(o) - if strings.Contains(output, "windows-") { - return registry.State{Error: oci.ErrWindowsContainers, Installed: true, Healthy: false, Fix: "Change container type to \"linux\" in Docker Desktop settings", Doc: docURL + "#verify-docker-container-type-is-linux"} + if err != nil { + if ctx.Err() == context.DeadlineExceeded { + err = errors.Wrapf(err, "deadline exceeded running %q", strings.Join(cmd.Args, " ")) + } - } - if err == nil { - glog.Infof("docker version: %s", output) - return checkNeedsImprovement() - } + glog.Warningf("docker version returned error: %v", err) - glog.Warningf("docker returned error: %v", err) + if exitErr, ok := err.(*exec.ExitError); ok { + stderr := strings.TrimSpace(string(exitErr.Stderr)) + newErr := fmt.Errorf(`%q %v: %s`, strings.Join(cmd.Args, " "), exitErr, stderr) + + return suggestFix(stderr, newErr) + } - // Basic timeout - if ctx.Err() == context.DeadlineExceeded { - glog.Warningf("%q timed out. ", strings.Join(cmd.Args, " ")) return registry.State{Error: err, Installed: true, Healthy: false, Fix: "Restart the Docker service", Doc: docURL} } - if exitErr, ok := err.(*exec.ExitError); ok { - stderr := strings.TrimSpace(string(exitErr.Stderr)) - newErr := fmt.Errorf(`%q %v: %s`, strings.Join(cmd.Args, " "), exitErr, stderr) - return suggestFix(stderr, newErr) + glog.Infof("docker version: %s", o) + if strings.Contains(string(o), "windows-") { + return registry.State{Error: oci.ErrWindowsContainers, Installed: true, Healthy: false, Fix: "Change container type to \"linux\" in Docker Desktop settings", Doc: docURL + "#verify-docker-container-type-is-linux"} } - return registry.State{Error: err, Installed: true, Healthy: false, Doc: docURL} + ctx, cancel = context.WithTimeout(context.Background(), 6*time.Second) + defer cancel() + + // Why run "info"? On some releases (Docker Desktop v19.03.12), "version" returns exit code 0 even if Docker is down. + cmd = exec.CommandContext(ctx, oci.Docker, "info") + o, err = cmd.Output() + if err != nil { + if ctx.Err() == context.DeadlineExceeded { + err = errors.Wrapf(err, "deadline exceeded running %q", strings.Join(cmd.Args, " ")) + } + + glog.Warningf("docker info returned error: %v", err) + + if exitErr, ok := err.(*exec.ExitError); ok { + stderr := strings.TrimSpace(string(exitErr.Stderr)) + newErr := fmt.Errorf(`%q %v: %s`, strings.Join(cmd.Args, " "), exitErr, stderr) + + if strings.Contains(stderr, "errors pretty printing info") || dockerNotRunning(string(o)) { + return registry.State{Error: err, Installed: true, Running: false, Healthy: false, Fix: "Start the Docker service", Doc: docURL} + } + + return suggestFix(stderr, newErr) + } + + return registry.State{Error: err, Installed: true, Healthy: false, Fix: "Restart the Docker service", Doc: docURL} + } + + glog.Infof("docker info: %s", o) + + return checkNeedsImprovement() } // checkNeedsImprovement if overlay mod is installed on a system @@ -121,6 +148,7 @@ func checkNeedsImprovement() registry.State { if runtime.GOOS == "linux" { return checkOverlayMod() } + return registry.State{Installed: true, Healthy: true} } @@ -128,15 +156,18 @@ func checkNeedsImprovement() registry.State { func checkOverlayMod() registry.State { if _, err := os.Stat("/sys/module/overlay"); err == nil { glog.Info("overlay module found") + return registry.State{Installed: true, Healthy: true} } if _, err := os.Stat("/sys/module/overlay2"); err == nil { glog.Info("overlay2 module found") + return registry.State{Installed: true, Healthy: true} } glog.Warningf("overlay modules were not found") + return registry.State{NeedsImprovement: true, Installed: true, Healthy: true, Fix: "enable the overlay Linux kernel module using 'modprobe overlay'"} } @@ -150,10 +181,14 @@ func suggestFix(stderr string, err error) registry.State { return registry.State{Error: err, Installed: true, Running: false, Healthy: false, Fix: "Start the Docker service. If Docker is already running, you may need to reset Docker to factory settings with: Settings > Reset.", Doc: "https://github.com/docker/for-win/issues/1825#issuecomment-450501157"} } - if strings.Contains(stderr, "Cannot connect") || strings.Contains(stderr, "refused") || strings.Contains(stderr, "Is the docker daemon running") || strings.Contains(stderr, "docker daemon is not running") { + if dockerNotRunning(stderr) { return registry.State{Error: err, Installed: true, Running: false, Healthy: false, Fix: "Start the Docker service", Doc: docURL} } // We don't have good advice, but at least we can provide a good error message return registry.State{Error: err, Installed: true, Running: true, Healthy: false, Doc: docURL} } + +func dockerNotRunning(s string) bool { + return strings.Contains(s, "Cannot connect") || strings.Contains(s, "refused") || strings.Contains(s, "Is the docker daemon running") || strings.Contains(s, "docker daemon is not running") +} From 1ffd800c299bf75da0a019173651866d158a6b18 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Mon, 28 Sep 2020 11:27:05 -0700 Subject: [PATCH 2/4] Add comment --- pkg/minikube/registry/drvs/docker/docker.go | 1 + 1 file changed, 1 insertion(+) diff --git a/pkg/minikube/registry/drvs/docker/docker.go b/pkg/minikube/registry/drvs/docker/docker.go index d2a4f88e8a..acbff3010d 100644 --- a/pkg/minikube/registry/drvs/docker/docker.go +++ b/pkg/minikube/registry/drvs/docker/docker.go @@ -128,6 +128,7 @@ func status() registry.State { stderr := strings.TrimSpace(string(exitErr.Stderr)) newErr := fmt.Errorf(`%q %v: %s`, strings.Join(cmd.Args, " "), exitErr, stderr) + // Oddly enough, the underlying connection error is in stdout rather than stderr if strings.Contains(stderr, "errors pretty printing info") || dockerNotRunning(string(o)) { return registry.State{Error: err, Installed: true, Running: false, Healthy: false, Fix: "Start the Docker service", Doc: docURL} } From 8eaa3ee4f3bd102f379f94b9303f1929edba9f28 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Tue, 29 Sep 2020 09:19:14 -0700 Subject: [PATCH 3/4] Use oci.CachedDaemonInfo for status check --- pkg/drivers/kic/oci/cli_runner.go | 6 ++-- pkg/drivers/kic/oci/info.go | 23 +++++++++------ pkg/minikube/registry/drvs/docker/docker.go | 32 ++++----------------- 3 files changed, 25 insertions(+), 36 deletions(-) diff --git a/pkg/drivers/kic/oci/cli_runner.go b/pkg/drivers/kic/oci/cli_runner.go index 9a5cabd567..9799c7391b 100644 --- a/pkg/drivers/kic/oci/cli_runner.go +++ b/pkg/drivers/kic/oci/cli_runner.go @@ -144,9 +144,11 @@ func runCmd(cmd *exec.Cmd, warnSlow ...bool) (*RunResult, error) { } } - if exitError, ok := err.(*exec.ExitError); ok { - rr.ExitCode = exitError.ExitCode() + if ex, ok := err.(*exec.ExitError); ok { + glog.Warningf("%s returned with exit code %s", rr.Command(), ex.ExitCode()) + rr.ExitCode = ex.ExitCode() } + // Decrease log spam if elapsed > (1 * time.Second) { glog.Infof("Completed: %s: (%s)", rr.Command(), elapsed) diff --git a/pkg/drivers/kic/oci/info.go b/pkg/drivers/kic/oci/info.go index e13d641a1e..e58a122967 100644 --- a/pkg/drivers/kic/oci/info.go +++ b/pkg/drivers/kic/oci/info.go @@ -22,20 +22,24 @@ import ( "strings" "time" + "github.com/golang/glog" "github.com/pkg/errors" ) // SysInfo Info represents common system Information between docker and podman that minikube cares type SysInfo struct { - CPUs int // CPUs is Number of CPUs - TotalMemory int64 // TotalMemory Total available ram - OSType string // container's OsType (windows or linux) - Swarm bool // Weather or not the docker swarm is active - StorageDriver string // the storage driver for the daemon (for example overlay2) + CPUs int // CPUs is Number of CPUs + TotalMemory int64 // TotalMemory Total available ram + OSType string // container's OsType (windows or linux) + Swarm bool // Weather or not the docker swarm is active + StorageDriver string // the storage driver for the daemon (for example overlay2) + Errors []string // any server issues } -var cachedSysInfo *SysInfo -var cachedSysInfoErr *error +var ( + cachedSysInfo *SysInfo + cachedSysInfoErr *error +) // CachedDaemonInfo will run and return a docker/podman info only once per minikube run time. to avoid performance func CachedDaemonInfo(ociBin string) (SysInfo, error) { @@ -58,7 +62,7 @@ func DaemonInfo(ociBin string) (SysInfo, error) { return *cachedSysInfo, err } d, err := dockerSystemInfo() - cachedSysInfo = &SysInfo{CPUs: d.NCPU, TotalMemory: d.MemTotal, OSType: d.OSType, Swarm: d.Swarm.LocalNodeState == "active", StorageDriver: d.Driver} + cachedSysInfo = &SysInfo{CPUs: d.NCPU, TotalMemory: d.MemTotal, OSType: d.OSType, Swarm: d.Swarm.LocalNodeState == "active", StorageDriver: d.Driver, Errors: d.ServerErrors} return *cachedSysInfo, err } @@ -163,6 +167,7 @@ type dockerSysInfo struct { SecurityOptions []string `json:"SecurityOptions"` ProductLicense string `json:"ProductLicense"` Warnings interface{} `json:"Warnings"` + ServerErrors []string ClientInfo struct { Debug bool `json:"Debug"` Plugins []interface{} `json:"Plugins"` @@ -245,6 +250,7 @@ func dockerSystemInfo() (dockerSysInfo, error) { return ds, errors.Wrapf(err, "unmarshal docker system info") } + glog.Infof("docker info: %+v", ds) return ds, nil } @@ -264,5 +270,6 @@ func podmanSystemInfo() (podmanSysInfo, error) { if err := json.Unmarshal([]byte(strings.TrimSpace(rawJSON)), &ps); err != nil { return ps, errors.Wrapf(err, "unmarshal podman system info") } + glog.Infof("podman info: %+v", ps) return ps, nil } diff --git a/pkg/minikube/registry/drvs/docker/docker.go b/pkg/minikube/registry/drvs/docker/docker.go index acbff3010d..38a325a6aa 100644 --- a/pkg/minikube/registry/drvs/docker/docker.go +++ b/pkg/minikube/registry/drvs/docker/docker.go @@ -111,35 +111,15 @@ func status() registry.State { return registry.State{Error: oci.ErrWindowsContainers, Installed: true, Healthy: false, Fix: "Change container type to \"linux\" in Docker Desktop settings", Doc: docURL + "#verify-docker-container-type-is-linux"} } - ctx, cancel = context.WithTimeout(context.Background(), 6*time.Second) - defer cancel() - - // Why run "info"? On some releases (Docker Desktop v19.03.12), "version" returns exit code 0 even if Docker is down. - cmd = exec.CommandContext(ctx, oci.Docker, "info") - o, err = cmd.Output() + si, err := oci.CachedDaemonInfo("docker") if err != nil { - if ctx.Err() == context.DeadlineExceeded { - err = errors.Wrapf(err, "deadline exceeded running %q", strings.Join(cmd.Args, " ")) - } - - glog.Warningf("docker info returned error: %v", err) - - if exitErr, ok := err.(*exec.ExitError); ok { - stderr := strings.TrimSpace(string(exitErr.Stderr)) - newErr := fmt.Errorf(`%q %v: %s`, strings.Join(cmd.Args, " "), exitErr, stderr) - - // Oddly enough, the underlying connection error is in stdout rather than stderr - if strings.Contains(stderr, "errors pretty printing info") || dockerNotRunning(string(o)) { - return registry.State{Error: err, Installed: true, Running: false, Healthy: false, Fix: "Start the Docker service", Doc: docURL} - } - - return suggestFix(stderr, newErr) - } - - return registry.State{Error: err, Installed: true, Healthy: false, Fix: "Restart the Docker service", Doc: docURL} + // No known fix because we haven't yet seen a failure here + return registry.State{Error: errors.Wrap(err, "docker info"), Installed: true, Healthy: false, Doc: docURL} } - glog.Infof("docker info: %s", o) + for _, serr := range si.Errors { + return suggestFix(serr, fmt.Errorf("docker info error: %s", serr)) + } return checkNeedsImprovement() } From 91a32541e827528bc84b0f933a234e551debda54 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Tue, 29 Sep 2020 09:49:30 -0700 Subject: [PATCH 4/4] Use %d for exit code --- pkg/drivers/kic/oci/cli_runner.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/drivers/kic/oci/cli_runner.go b/pkg/drivers/kic/oci/cli_runner.go index 9799c7391b..7169e12bdb 100644 --- a/pkg/drivers/kic/oci/cli_runner.go +++ b/pkg/drivers/kic/oci/cli_runner.go @@ -145,7 +145,7 @@ func runCmd(cmd *exec.Cmd, warnSlow ...bool) (*RunResult, error) { } if ex, ok := err.(*exec.ExitError); ok { - glog.Warningf("%s returned with exit code %s", rr.Command(), ex.ExitCode()) + glog.Warningf("%s returned with exit code %d", rr.Command(), ex.ExitCode()) rr.ExitCode = ex.ExitCode() }