Minor tuning of test log verbosity

pull/5335/head
Thomas Stromberg 2019-09-13 07:42:30 -07:00
parent 046391db69
commit 625a4f8c05
8 changed files with 30 additions and 22 deletions

View File

@ -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),

View File

@ -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 ...")

View File

@ -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()

View File

@ -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 {

View File

@ -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)
}

View File

@ -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

View File

@ -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 {

View File

@ -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)