diff --git a/pkg/minikube/bootstrapper/kubeadm/kubeadm.go b/pkg/minikube/bootstrapper/kubeadm/kubeadm.go index d138566c12..204d042626 100644 --- a/pkg/minikube/bootstrapper/kubeadm/kubeadm.go +++ b/pkg/minikube/bootstrapper/kubeadm/kubeadm.go @@ -404,7 +404,7 @@ func (k *Bootstrapper) RestartCluster(k8s config.KubernetesConfig) error { glog.Errorf("failed to create compat symlinks: %v", err) } - baseCmd := fmt.Sprintf("%s -v=1 %s", invokeKubeadm(k8s.KubernetesVersion), phase) + baseCmd := fmt.Sprintf("%s %s", invokeKubeadm(k8s.KubernetesVersion), phase) cmds := []string{ fmt.Sprintf("%s phase certs all --config %s", baseCmd, yamlConfigPath), fmt.Sprintf("%s phase kubeconfig all --config %s", baseCmd, yamlConfigPath), diff --git a/pkg/minikube/cluster/cluster.go b/pkg/minikube/cluster/cluster.go index b63b6b5896..ac71c66ace 100644 --- a/pkg/minikube/cluster/cluster.go +++ b/pkg/minikube/cluster/cluster.go @@ -152,7 +152,12 @@ func localDriver(name string) bool { // configureHost handles any post-powerup configuration required func configureHost(h *host.Host, e *engine.Options) error { - glog.Infof("configureHost: %T %+v", h, h) + start := time.Now() + glog.Infof("configureHost: %+v", h.Driver) + defer func() { + glog.Infof("configureHost completed within %s", time.Since(start)) + }() + if len(e.Env) > 0 { h.HostOptions.EngineOptions.Env = e.Env glog.Infof("Detecting provisioner ...") diff --git a/pkg/minikube/command/ssh_runner.go b/pkg/minikube/command/ssh_runner.go index 08d6370740..95f3cada48 100644 --- a/pkg/minikube/command/ssh_runner.go +++ b/pkg/minikube/command/ssh_runner.go @@ -81,13 +81,13 @@ func teeSSH(s *ssh.Session, cmd string, outB io.Writer, errB io.Writer) error { wg.Add(2) go func() { - if err := util.TeePrefix(util.ErrPrefix, errPipe, errB, glog.Infof); err != nil { + if err := util.TeePrefix(util.ErrPrefix, errPipe, errB, glog.V(2).Infof); err != nil { glog.Errorf("tee stderr: %v", err) } wg.Done() }() go func() { - if err := util.TeePrefix(util.OutPrefix, outPipe, outB, glog.Infof); err != nil { + if err := util.TeePrefix(util.OutPrefix, outPipe, outB, glog.V(2).Infof); err != nil { glog.Errorf("tee stdout: %v", err) } wg.Done() diff --git a/test/integration/docker_test.go b/test/integration/docker_test.go index f1083b590a..b8af04450e 100644 --- a/test/integration/docker_test.go +++ b/test/integration/docker_test.go @@ -36,6 +36,7 @@ func TestDockerFlags(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), 20*time.Minute) defer Cleanup(t, profile, cancel) + // Use the most verbose logging for the simplest test. If it fails, something is very wrong. args := append([]string{"start", "-p", profile, "--wait=false", "--docker-env=FOO=BAR", "--docker-env=BAZ=BAT", "--docker-opt=debug", "--docker-opt=icc=true", "--alsologtostderr", "-v=8"}, StartArgs()...) rr, err := Run(t, exec.CommandContext(ctx, Target(), args...)) if err != nil { diff --git a/test/integration/helpers.go b/test/integration/helpers.go index 8c1832e47c..30d82a4be7 100644 --- a/test/integration/helpers.go +++ b/test/integration/helpers.go @@ -62,14 +62,13 @@ func (rr RunResult) Command() string { return sb.String() } -func (rr RunResult) String() string { +func (rr RunResult) Output() string { var sb strings.Builder - sb.WriteString(fmt.Sprintf("Command: %v\n", rr.Command())) if rr.Stdout.Len() > 0 { - sb.WriteString(fmt.Sprintf("\n-- stdout -- \n%s\n", rr.Stdout.Bytes())) + sb.WriteString(fmt.Sprintf("-- stdout --\n%s\n-- /stdout --", rr.Stdout.Bytes())) } if rr.Stderr.Len() > 0 { - sb.WriteString(fmt.Sprintf("\n** stderr ** \n%s\n", rr.Stderr.Bytes())) + sb.WriteString(fmt.Sprintf("\n** stderr ** \n%s\n** /stderr **", rr.Stderr.Bytes())) } return sb.String() } @@ -95,8 +94,7 @@ func Run(t *testing.T, cmd *exec.Cmd) (*RunResult, error) { if exitError, ok := err.(*exec.ExitError); ok { rr.ExitCode = exitError.ExitCode() } - t.Logf("(dbg) Non-zero exit: %v: %v (%s)", rr.Command(), err, elapsed) - t.Logf("(dbg) %s", rr.String()) + t.Logf("(dbg) Non-zero exit: %v: %v (%s)\n%s", rr.Command(), err, elapsed, rr.Output()) } return rr, err } @@ -111,7 +109,7 @@ type StartSession struct { // Start starts a process in the background, streaming output func Start(t *testing.T, cmd *exec.Cmd) (*StartSession, error) { t.Helper() - t.Logf("Daemon: %v", cmd.Args) + t.Logf("(dbg) daemon: %v", cmd.Args) stdoutPipe, err := cmd.StdoutPipe() if err != nil { @@ -129,7 +127,7 @@ func Start(t *testing.T, cmd *exec.Cmd) (*StartSession, error) { // Stop stops the started process func (ss *StartSession) Stop(t *testing.T) { t.Helper() - t.Logf("Stopping %s ...", ss.cmd.Args) + t.Logf("(dbg) stopping %s ...", ss.cmd.Args) if ss.cmd.Process == nil { t.Logf("%s has a nil Process. Maybe it's dead? How weird!", ss.cmd.Args) return @@ -162,7 +160,7 @@ func Cleanup(t *testing.T, profile string, cancel context.CancelFunc) { t.Logf("failed cleanup: %v", err) } } else { - t.Logf("Skipping cleanup of %s (--cleanup=false)", profile) + t.Logf("skipping cleanup of %s (--cleanup=false)", profile) } cancel() } @@ -172,11 +170,11 @@ func CleanupWithLogs(t *testing.T, profile string, cancel context.CancelFunc) { t.Helper() if t.Failed() && *postMortemLogs { t.Logf("%s failed, collecting logs ...", t.Name()) - rr, err := Run(t, exec.Command(Target(), "-p", profile, "logs", "-n", "10")) + rr, err := Run(t, exec.Command(Target(), "-p", profile, "logs", "-n", "5")) if err != nil { t.Logf("failed logs error: %v", err) } - t.Logf("%s logs: %s\n", t.Name(), rr) + t.Logf("%s logs: %s", t.Name(), rr.Stdout) t.Logf("Sorry that %s failed :(", t.Name()) } Cleanup(t, profile, cancel) @@ -218,7 +216,7 @@ func PodWait(ctx context.Context, t *testing.T, profile string, ns string, selec lastMsg := "" start := time.Now() - t.Logf("Waiting for pods with labels %q in namespace %q ...", selector, ns) + t.Logf("(dbg) waiting for pods with labels %q in namespace %q ...", selector, ns) f := func() (bool, error) { pods, err := client.CoreV1().Pods(ns).List(listOpts) if err != nil { @@ -270,11 +268,11 @@ func PodWait(ctx context.Context, t *testing.T, profile string, ns string, selec } if err == nil { - t.Logf("pods %s up and healthy within %s", selector, time.Since(start)) + t.Logf("(dbg) pods %s up and healthy within %s", selector, time.Since(start)) return names, nil } - t.Logf("pods %q: %v", selector, err) + t.Logf("pod %q failed to start: %v", selector, err) showPodLogs(ctx, t, profile, ns, names) return names, fmt.Errorf("%s: %v", fmt.Sprintf("%s within %s", selector, timeout), err) } diff --git a/test/integration/main.go b/test/integration/main.go index 49490e5b21..02ce476cf9 100644 --- a/test/integration/main.go +++ b/test/integration/main.go @@ -18,9 +18,11 @@ package integration import ( "flag" + "fmt" "os" "strings" "testing" + "time" ) // General configuration: used to set the VM Driver @@ -38,7 +40,10 @@ var testdataDir = flag.String("testdata-dir", "testdata", "the directory relativ // TestMain is the test main func TestMain(m *testing.M) { flag.Parse() - os.Exit(m.Run()) + start := time.Now() + code := m.Run() + fmt.Printf("Tests completed in %s (result code %d)\n", time.Since(start), code) + os.Exit(code) } // StartArgs returns the arguments normally used for starting minikube diff --git a/test/integration/start_stop_delete_test.go b/test/integration/start_stop_delete_test.go index 3c64353a0f..66d505ea7f 100644 --- a/test/integration/start_stop_delete_test.go +++ b/test/integration/start_stop_delete_test.go @@ -84,8 +84,7 @@ func TestStartStop(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), 40*time.Minute) defer CleanupWithLogs(t, profile, cancel) - // Use copious amounts of debugging for this stress test: we will need it. - startArgs := append([]string{"start", "-p", profile, "--alsologtostderr", "-v=8"}, tc.args...) + startArgs := append([]string{"start", "-p", profile, "--alsologtostderr", "-v=1"}, tc.args...) startArgs = append(startArgs, StartArgs()...) rr, err := Run(t, exec.CommandContext(ctx, Target(), startArgs...)) if err != nil { diff --git a/test/integration/version_upgrade_test.go b/test/integration/version_upgrade_test.go index 442c249bfc..9296bdde94 100644 --- a/test/integration/version_upgrade_test.go +++ b/test/integration/version_upgrade_test.go @@ -89,7 +89,7 @@ func TestVersionUpgrade(t *testing.T) { t.Errorf("status = %q; want = %q", got, state.Stopped.String()) } - args = append([]string{"start", "-p", profile, fmt.Sprintf("--kubernetes-version=%s", constants.NewestKubernetesVersion), "--alsologtostderr", "-v=2"}, StartArgs()...) + args = append([]string{"start", "-p", profile, fmt.Sprintf("--kubernetes-version=%s", constants.NewestKubernetesVersion), "--alsologtostderr", "-v=1"}, StartArgs()...) rr, err = Run(t, exec.CommandContext(ctx, Target(), args...)) if err != nil { t.Errorf("%s failed: %v", rr.Args, err)