From bc5eb2a1f712452d4a131fe725239d9117059bda Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Wed, 19 Dec 2018 10:42:19 -0800 Subject: [PATCH 1/6] Stream command output from integration tests --- test/integration/util/util.go | 68 ++++++++++++++++++++++++++++++----- 1 file changed, 60 insertions(+), 8 deletions(-) diff --git a/test/integration/util/util.go b/test/integration/util/util.go index a4b4a8d5b19b..adefc220dc09 100644 --- a/test/integration/util/util.go +++ b/test/integration/util/util.go @@ -22,6 +22,7 @@ import ( "context" "encoding/json" "fmt" + "io" "math/rand" "os/exec" "path/filepath" @@ -38,6 +39,8 @@ import ( ) const kubectlBinary = "kubectl" +const errPrefix = " !" +const outPrefix = " >" type MinikubeRunner struct { T *testing.T @@ -47,6 +50,14 @@ type MinikubeRunner struct { Runtime string } +func Logf(str string, args ...interface{}) { + if !testing.Verbose() { + return + } + fmt.Printf("%s: ", time.Now().Format(time.Stamp)) + fmt.Println(fmt.Sprintf(str, args...)) +} + func (m *MinikubeRunner) Run(cmd string) error { _, err := m.SSH(cmd) return err @@ -55,6 +66,7 @@ func (m *MinikubeRunner) Run(cmd string) error { func (m *MinikubeRunner) Copy(f assets.CopyableFile) error { path, _ := filepath.Abs(m.BinaryPath) cmd := exec.Command("/bin/bash", "-c", path, "ssh", "--", fmt.Sprintf("cat >> %s", filepath.Join(f.GetTargetDir(), f.GetTargetName()))) + Logf("Running: %s", cmd) return cmd.Run() } @@ -67,20 +79,58 @@ func (m *MinikubeRunner) Remove(f assets.CopyableFile) error { return err } +// tee logs streams command output to console and returns it +func tee(prefix string, f io.Reader, b strings.Builder) { + start := time.Now() + scanner := bufio.NewScanner(f) + for scanner.Scan() { + t := scanner.Text() + b.WriteString(t + "\n") + if !testing.Verbose() { + continue + } + offset := "" + seconds := time.Since(start).Seconds() + if seconds > 1 { + offset = fmt.Sprintf("+%.fs", seconds) + } + fmt.Printf("%s%6s %s\n", prefix, offset, t) + } + Logf("%s tee done: %d bytes", prefix, b.Len()) +} + func (m *MinikubeRunner) RunCommand(command string, checkError bool) string { commandArr := strings.Split(command, " ") path, _ := filepath.Abs(m.BinaryPath) cmd := exec.Command(path, commandArr...) - stdout, err := cmd.Output() + Logf("Run: %s", cmd.Args) + stderr, err := cmd.StderrPipe() + if err != nil { + m.T.Fatalf("stderr pipe: %v", err) + } + stdout, err := cmd.StdoutPipe() + if err != nil { + m.T.Fatalf("stderr pipe: %v", err) + } + + start := time.Now() + cmd.Start() + var bOut strings.Builder + var bErr strings.Builder + go tee(errPrefix, stderr, bErr) + go tee(outPrefix, stdout, bOut) + + err = cmd.Wait() + Logf("Completed in %s, err=%v, out=%q", time.Since(start), err, bOut.String()) if checkError && err != nil { if exitError, ok := err.(*exec.ExitError); ok { - m.T.Fatalf("Error running command: %s %s. Output: %s", command, exitError.Stderr, stdout) + m.T.Fatalf("Error running command: %s %s. Output: %s", command, exitError.Stderr, bOut.String()) } else { - m.T.Fatalf("Error running command: %s %v. Output: %s", command, err, stdout) + m.T.Fatalf("Error running command: %s %v. Output: %s", command, err, bOut.String()) } } - return string(stdout) + return bOut.String() } // RunWithContext calls the minikube command with a context, useful for timeouts. @@ -115,11 +165,13 @@ func (m *MinikubeRunner) SetRuntime(runtime string) { func (m *MinikubeRunner) SSH(command string) (string, error) { path, _ := filepath.Abs(m.BinaryPath) cmd := exec.Command(path, "ssh", command) + Logf("SSH: %s", command) + stdout, err := cmd.CombinedOutput() + Logf("Output: %s", stdout) if err, ok := err.(*exec.ExitError); ok { return string(stdout), err } - return string(stdout), nil } @@ -127,9 +179,9 @@ func (m *MinikubeRunner) Start() { switch r := m.Runtime; r { case constants.ContainerdRuntime: containerdFlags := "--container-runtime=containerd --network-plugin=cni --docker-opt containerd=/var/run/containerd/containerd.sock" - m.RunCommand(fmt.Sprintf("start %s %s %s", m.StartArgs, m.Args, containerdFlags), true) + m.RunCommand(fmt.Sprintf("start %s %s %s --alsologtostderr --v=6", m.StartArgs, m.Args, containerdFlags), true) default: - m.RunCommand(fmt.Sprintf("start %s %s", m.StartArgs, m.Args), true) + m.RunCommand(fmt.Sprintf("start %s %s --alsologtostderr --v=6", m.StartArgs, m.Args), true) } } @@ -167,7 +219,7 @@ func (m *MinikubeRunner) CheckStatus(desired string) { func (m *MinikubeRunner) CheckStatusNoFail(desired string) error { s := m.GetStatus() if s != desired { - return fmt.Errorf("Machine is in the wrong state: %s, expected %s", s, desired) + return fmt.Errorf("got state: %q, expected %q", s, desired) } return nil } From ab5d433448d4e9ae4bb11bd9ac92c183a1893b74 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Wed, 19 Dec 2018 11:16:08 -0800 Subject: [PATCH 2/6] Make tee work with RunWithContext also --- test/integration/docker_test.go | 20 +++++++-------- test/integration/util/util.go | 43 +++++++++++++++++++++------------ 2 files changed, 38 insertions(+), 25 deletions(-) diff --git a/test/integration/docker_test.go b/test/integration/docker_test.go index 68428fe7d6c5..609af4458d6f 100644 --- a/test/integration/docker_test.go +++ b/test/integration/docker_test.go @@ -41,31 +41,31 @@ func TestDocker(t *testing.T) { startCmd := fmt.Sprintf("start %s %s %s", mk.StartArgs, mk.Args, "--docker-env=FOO=BAR --docker-env=BAZ=BAT --docker-opt=debug --docker-opt=icc=true") - out, err := mk.RunWithContext(ctx, startCmd) + stdout, stderr, err := mk.RunWithContext(ctx, startCmd) if err != nil { - t.Fatalf("start: %v\nstart out: %s", err, out) + t.Fatalf("start: %v\nstdout: %s\nstderr: %s", err, stdout, stderr) } mk.EnsureRunning() - out, err = mk.RunWithContext(ctx, "ssh -- systemctl show docker --property=Environment --no-pager") + stdout, stderr, err = mk.RunWithContext(ctx, "ssh -- systemctl show docker --property=Environment --no-pager") if err != nil { - t.Errorf("docker env: %v\ndocker env out: %s", err, out) + t.Errorf("docker env: %v\nstderr: %s", err, stderr) } for _, envVar := range []string{"FOO=BAR", "BAZ=BAT"} { - if !strings.Contains(string(out), envVar) { - t.Errorf("Env var %s missing: %s.", envVar, out) + if !strings.Contains(stdout, envVar) { + t.Errorf("Env var %s missing: %s.", envVar, stdout) } } - out, err = mk.RunWithContext(ctx, "ssh -- systemctl show docker --property=ExecStart --no-pager") + stdout, stderr, err = mk.RunWithContext(ctx, "ssh -- systemctl show docker --property=ExecStart --no-pager") if err != nil { - t.Errorf("ssh show docker: %v\nshow docker out: %s", err, out) + t.Errorf("ssh show docker: %v\nstderr: %s", err, stderr) } for _, opt := range []string{"--debug", "--icc=true"} { - if !strings.Contains(string(out), opt) { - t.Fatalf("Option %s missing from ExecStart: %s.", opt, out) + if !strings.Contains(stdout, opt) { + t.Fatalf("Option %s missing from ExecStart: %s.", opt, stdout) } } } diff --git a/test/integration/util/util.go b/test/integration/util/util.go index adefc220dc09..18114dc880ef 100644 --- a/test/integration/util/util.go +++ b/test/integration/util/util.go @@ -79,7 +79,7 @@ func (m *MinikubeRunner) Remove(f assets.CopyableFile) error { return err } -// tee logs streams command output to console and returns it +// tee logs new lines from a reader to stdout. Designed to be callable in the background. func tee(prefix string, f io.Reader, b strings.Builder) { start := time.Now() scanner := bufio.NewScanner(f) @@ -96,15 +96,10 @@ func tee(prefix string, f io.Reader, b strings.Builder) { } fmt.Printf("%s%6s %s\n", prefix, offset, t) } - Logf("%s tee done: %d bytes", prefix, b.Len()) } -func (m *MinikubeRunner) RunCommand(command string, checkError bool) string { - commandArr := strings.Split(command, " ") - path, _ := filepath.Abs(m.BinaryPath) - cmd := exec.Command(path, commandArr...) - Logf("Run: %s", cmd.Args) - +// teeRun runs a command, streaming stdout, stderr to console +func teeRun(cmd exec.Cmd) (string, string, error) { stderr, err := cmd.StderrPipe() if err != nil { m.T.Fatalf("stderr pipe: %v", err) @@ -118,26 +113,44 @@ func (m *MinikubeRunner) RunCommand(command string, checkError bool) string { cmd.Start() var bOut strings.Builder var bErr strings.Builder - go tee(errPrefix, stderr, bErr) - go tee(outPrefix, stdout, bOut) + var wg sync.WaitGroup + wg.Add(2) + go func() { + tee(errPrefix, stderr, bErr) + wg.Done() + } + go func() { + tee(outPrefix, stdout, bOut) + wg.Done() + } + err := cmd.Wait() + wg.Wait() + return bOut.String(), bErr.String(), err +} - err = cmd.Wait() +func (m *MinikubeRunner) RunCommand(command string, checkError bool) string { + commandArr := strings.Split(command, " ") + path, _ := filepath.Abs(m.BinaryPath) + cmd := exec.Command(path, commandArr...) + Logf("Run: %s", cmd.Args) + stdout, stderr, err := teeRun(cmd) Logf("Completed in %s, err=%v, out=%q", time.Since(start), err, bOut.String()) if checkError && err != nil { if exitError, ok := err.(*exec.ExitError); ok { - m.T.Fatalf("Error running command: %s %s. Output: %s", command, exitError.Stderr, bOut.String()) + m.T.Fatalf("Error running command: %s %s. Output: %s", command, exitError.Stderr, stdout) } else { - m.T.Fatalf("Error running command: %s %v. Output: %s", command, err, bOut.String()) + m.T.Fatalf("Error running command: %s %v. Output: %s", command, err, stderr) } } return bOut.String() } // RunWithContext calls the minikube command with a context, useful for timeouts. -func (m *MinikubeRunner) RunWithContext(ctx context.Context, command string) ([]byte, error) { +func (m *MinikubeRunner) RunWithContext(ctx context.Context, command string) (stdout, stderr, error) { commandArr := strings.Split(command, " ") path, _ := filepath.Abs(m.BinaryPath) - return exec.CommandContext(ctx, path, commandArr...).CombinedOutput() + cmd := exec.CommandContext(ctx, path, commandArr...) + stdout, stderr, err := teeRun(cmd) } func (m *MinikubeRunner) RunDaemon(command string) (*exec.Cmd, *bufio.Reader) { From 9b707fe23491a2339135e9ff207ef11d412f2cf5 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Wed, 19 Dec 2018 17:03:55 -0800 Subject: [PATCH 3/6] Add TeeWithPrefix to ssh_runner as well --- pkg/minikube/bootstrapper/ssh_runner.go | 70 ++++++++++++++++++++++--- pkg/util/utils.go | 34 ++++++++++++ pkg/util/utils_test.go | 41 +++++++++++++++ test/integration/util/util.go | 67 +++++++++-------------- 4 files changed, 162 insertions(+), 50 deletions(-) diff --git a/pkg/minikube/bootstrapper/ssh_runner.go b/pkg/minikube/bootstrapper/ssh_runner.go index 95bf59b91ec1..eb5417e1fd7b 100644 --- a/pkg/minikube/bootstrapper/ssh_runner.go +++ b/pkg/minikube/bootstrapper/ssh_runner.go @@ -17,6 +17,7 @@ limitations under the License. package bootstrapper import ( + "bytes" "fmt" "io" "path" @@ -26,6 +27,7 @@ import ( "github.com/pkg/errors" "golang.org/x/crypto/ssh" "k8s.io/minikube/pkg/minikube/assets" + "k8s.io/minikube/pkg/util" ) // SSHRunner runs commands through SSH. @@ -52,25 +54,75 @@ func (s *SSHRunner) Remove(f assets.CopyableFile) error { return sess.Run(cmd) } +type singleWriter struct { + b bytes.Buffer + mu sync.Mutex +} + +func (w *singleWriter) Write(p []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + return w.b.Write(p) +} + +// teeSSH runs an SSH command, streaming stdout, stderr to logs +func teeSSH(s *ssh.Session, cmd string, outB io.Writer, errB io.Writer) error { + outPipe, err := s.StdoutPipe() + if err != nil { + return errors.Wrap(err, "stdout") + } + + errPipe, err := s.StderrPipe() + if err != nil { + return errors.Wrap(err, "stderr") + } + var wg sync.WaitGroup + wg.Add(2) + + go func() { + if err := util.TeeWithPrefix(util.ErrPrefix, errPipe, errB, glog.Infof); err != nil { + glog.Errorf("tee stderr: %v", err) + } + wg.Done() + }() + go func() { + if err := util.TeeWithPrefix(util.OutPrefix, outPipe, outB, glog.Infof); err != nil { + glog.Errorf("tee stdout: %v", err) + } + wg.Done() + }() + err = s.Run(cmd) + wg.Wait() + return err +} + // Run starts a command on the remote and waits for it to return. func (s *SSHRunner) Run(cmd string) error { - glog.Infoln("Run:", cmd) + glog.Infof("SSH: %s", cmd) sess, err := s.c.NewSession() + defer func() { + if err := sess.Close(); err != nil { + if err != io.EOF { + glog.Errorf("close: %v", err) + } + } + }() if err != nil { return errors.Wrap(err, "getting ssh session") } - defer sess.Close() - return sess.Run(cmd) + var outB bytes.Buffer + var errB bytes.Buffer + return teeSSH(sess, cmd, &outB, &errB) } // CombinedOutputTo runs the command and stores both command // output and error to out. -func (s *SSHRunner) CombinedOutputTo(cmd string, out io.Writer) error { - b, err := s.CombinedOutput(cmd) +func (s *SSHRunner) CombinedOutputTo(cmd string, w io.Writer) error { + out, err := s.CombinedOutput(cmd) if err != nil { return errors.Wrapf(err, "running command: %s\n.", cmd) } - _, err = out.Write([]byte(b)) + _, err = w.Write([]byte(out)) return err } @@ -84,9 +136,11 @@ func (s *SSHRunner) CombinedOutput(cmd string) (string, error) { } defer sess.Close() - b, err := sess.CombinedOutput(cmd) + var combined singleWriter + err = teeSSH(sess, cmd, &combined, &combined) + b := combined.b.Bytes() if err != nil { - return "", errors.Wrapf(err, "running command: %s\n, output: %s", cmd, string(b)) + return "", errors.Wrapf(err, "running command: %s\n, output: %s", cmd, b) } return string(b), nil } diff --git a/pkg/util/utils.go b/pkg/util/utils.go index 88b86368d101..4ac7ac13a72c 100644 --- a/pkg/util/utils.go +++ b/pkg/util/utils.go @@ -17,6 +17,8 @@ limitations under the License. package util import ( + "bufio" + "bytes" "fmt" "io" "io/ioutil" @@ -33,6 +35,9 @@ import ( "github.com/pkg/errors" ) +const ErrPrefix = "! " +const OutPrefix = "> " + const ( downloadURL = "https://storage.googleapis.com/minikube/releases/%s/minikube-%s-amd64%s" ) @@ -199,3 +204,32 @@ func MaybeChownDirRecursiveToMinikubeUser(dir string) error { } return nil } + +// TeeWithPrefix logs new lines from a reader. Designed to be run in the background. +func TeeWithPrefix(prefix string, r io.Reader, w io.Writer, logger func(format string, args ...interface{})) error { + scanner := bufio.NewScanner(r) + // Collect individual bytes so that we don't accidentally strip newlines required by callers. + scanner.Split(bufio.ScanBytes) + var line bytes.Buffer + + for scanner.Scan() { + b := scanner.Bytes() + if _, err := w.Write(b); err != nil { + return err + } + + if bytes.IndexAny(b, "\r\n") == 0 { + if line.Len() > 0 { + logger("%s%s", prefix, line.String()) + line.Reset() + } + continue + } + line.Write(b) + } + // Catch trailing output in case stream does not end with a newline + if line.Len() > 0 { + logger("%s%s", prefix, line.String()) + } + return nil +} diff --git a/pkg/util/utils_test.go b/pkg/util/utils_test.go index eeea378564d6..2975e3edde6a 100644 --- a/pkg/util/utils_test.go +++ b/pkg/util/utils_test.go @@ -17,9 +17,13 @@ limitations under the License. package util import ( + "bytes" + "fmt" "io" "net/http" "net/http/httptest" + "strings" + "sync" "testing" "github.com/pkg/errors" @@ -158,3 +162,40 @@ func TestGetBinaryDownloadURL(t *testing.T) { } } + +func TestTeeWithPrefix(t *testing.T) { + var in bytes.Buffer + var out bytes.Buffer + var logged strings.Builder + + logSink := func(format string, args ...interface{}) { + logged.WriteString("(") + logged.WriteString(fmt.Sprintf(format, args...)) + logged.WriteString(")") + } + + // Simulate the primary use case: tee in the background. This also helps avoid I/O races. + var wg sync.WaitGroup + wg.Add(1) + go func() { + TeeWithPrefix(": ", &in, &out, logSink) + wg.Done() + }() + + in.Write([]byte("goo")) + in.Write([]byte("\n")) + in.Write([]byte("gle")) + wg.Wait() + + gotBytes := out.Bytes() + wantBytes := []byte("goo\ngle") + if !bytes.Equal(gotBytes, wantBytes) { + t.Errorf("got bytes: %v, want: %v", gotBytes, wantBytes) + } + + gotLog := logged.String() + wantLog := "(: goo)(: gle)" + if gotLog != wantLog { + t.Errorf("got log %q, want log %q", gotLog, wantLog) + } +} diff --git a/test/integration/util/util.go b/test/integration/util/util.go index 18114dc880ef..03c80562f499 100644 --- a/test/integration/util/util.go +++ b/test/integration/util/util.go @@ -22,12 +22,12 @@ import ( "context" "encoding/json" "fmt" - "io" "math/rand" "os/exec" "path/filepath" "regexp" "strings" + "sync" "testing" "time" @@ -39,8 +39,6 @@ import ( ) const kubectlBinary = "kubectl" -const errPrefix = " !" -const outPrefix = " >" type MinikubeRunner struct { T *testing.T @@ -50,11 +48,12 @@ type MinikubeRunner struct { Runtime string } +// Logf writes logs to stdout if -v is set. func Logf(str string, args ...interface{}) { if !testing.Verbose() { return } - fmt.Printf("%s: ", time.Now().Format(time.Stamp)) + fmt.Printf(" %s | ", time.Now().Format("15:04:05")) fmt.Println(fmt.Sprintf(str, args...)) } @@ -79,53 +78,37 @@ func (m *MinikubeRunner) Remove(f assets.CopyableFile) error { return err } -// tee logs new lines from a reader to stdout. Designed to be callable in the background. -func tee(prefix string, f io.Reader, b strings.Builder) { - start := time.Now() - scanner := bufio.NewScanner(f) - for scanner.Scan() { - t := scanner.Text() - b.WriteString(t + "\n") - if !testing.Verbose() { - continue - } - offset := "" - seconds := time.Since(start).Seconds() - if seconds > 1 { - offset = fmt.Sprintf("+%.fs", seconds) - } - fmt.Printf("%s%6s %s\n", prefix, offset, t) - } -} - // teeRun runs a command, streaming stdout, stderr to console -func teeRun(cmd exec.Cmd) (string, string, error) { - stderr, err := cmd.StderrPipe() +func (m *MinikubeRunner) teeRun(cmd *exec.Cmd) (string, string, error) { + errPipe, err := cmd.StderrPipe() if err != nil { - m.T.Fatalf("stderr pipe: %v", err) + return "", "", err } - stdout, err := cmd.StdoutPipe() + outPipe, err := cmd.StdoutPipe() if err != nil { - m.T.Fatalf("stderr pipe: %v", err) + return "", "", err } - start := time.Now() cmd.Start() - var bOut strings.Builder - var bErr strings.Builder + var outB bytes.Buffer + var errB bytes.Buffer var wg sync.WaitGroup wg.Add(2) go func() { - tee(errPrefix, stderr, bErr) + if err := commonutil.TeeWithPrefix(commonutil.ErrPrefix, errPipe, &errB, Logf); err != nil { + m.T.Logf("tee: %v", err) + } wg.Done() - } + }() go func() { - tee(outPrefix, stdout, bOut) + if err := commonutil.TeeWithPrefix(commonutil.OutPrefix, outPipe, &outB, Logf); err != nil { + m.T.Logf("tee: %v", err) + } wg.Done() - } - err := cmd.Wait() + }() + err = cmd.Wait() wg.Wait() - return bOut.String(), bErr.String(), err + return outB.String(), errB.String(), err } func (m *MinikubeRunner) RunCommand(command string, checkError bool) string { @@ -133,8 +116,7 @@ func (m *MinikubeRunner) RunCommand(command string, checkError bool) string { path, _ := filepath.Abs(m.BinaryPath) cmd := exec.Command(path, commandArr...) Logf("Run: %s", cmd.Args) - stdout, stderr, err := teeRun(cmd) - Logf("Completed in %s, err=%v, out=%q", time.Since(start), err, bOut.String()) + stdout, stderr, err := m.teeRun(cmd) if checkError && err != nil { if exitError, ok := err.(*exec.ExitError); ok { m.T.Fatalf("Error running command: %s %s. Output: %s", command, exitError.Stderr, stdout) @@ -142,15 +124,16 @@ func (m *MinikubeRunner) RunCommand(command string, checkError bool) string { m.T.Fatalf("Error running command: %s %v. Output: %s", command, err, stderr) } } - return bOut.String() + return stdout } // RunWithContext calls the minikube command with a context, useful for timeouts. -func (m *MinikubeRunner) RunWithContext(ctx context.Context, command string) (stdout, stderr, error) { +func (m *MinikubeRunner) RunWithContext(ctx context.Context, command string) (string, string, error) { commandArr := strings.Split(command, " ") path, _ := filepath.Abs(m.BinaryPath) cmd := exec.CommandContext(ctx, path, commandArr...) - stdout, stderr, err := teeRun(cmd) + Logf("Run: %s", cmd.Args) + return m.teeRun(cmd) } func (m *MinikubeRunner) RunDaemon(command string) (*exec.Cmd, *bufio.Reader) { From 7f7587d96cf685bc88953daddf5c1a3063897958 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Thu, 20 Dec 2018 09:54:09 -0800 Subject: [PATCH 4/6] Rename TeeWithPrefix to TeePrefix to match Go idioms --- pkg/minikube/bootstrapper/ssh_runner.go | 4 ++-- pkg/util/utils.go | 5 ++--- pkg/util/utils_test.go | 19 +++++++++---------- test/integration/util/util.go | 4 ++-- 4 files changed, 15 insertions(+), 17 deletions(-) diff --git a/pkg/minikube/bootstrapper/ssh_runner.go b/pkg/minikube/bootstrapper/ssh_runner.go index eb5417e1fd7b..696bd47e267d 100644 --- a/pkg/minikube/bootstrapper/ssh_runner.go +++ b/pkg/minikube/bootstrapper/ssh_runner.go @@ -80,13 +80,13 @@ func teeSSH(s *ssh.Session, cmd string, outB io.Writer, errB io.Writer) error { wg.Add(2) go func() { - if err := util.TeeWithPrefix(util.ErrPrefix, errPipe, errB, glog.Infof); err != nil { + if err := util.TeePrefix(util.ErrPrefix, errPipe, errB, glog.Infof); err != nil { glog.Errorf("tee stderr: %v", err) } wg.Done() }() go func() { - if err := util.TeeWithPrefix(util.OutPrefix, outPipe, outB, glog.Infof); err != nil { + if err := util.TeePrefix(util.OutPrefix, outPipe, outB, glog.Infof); err != nil { glog.Errorf("tee stdout: %v", err) } wg.Done() diff --git a/pkg/util/utils.go b/pkg/util/utils.go index 4ac7ac13a72c..5ebe4cd2a49c 100644 --- a/pkg/util/utils.go +++ b/pkg/util/utils.go @@ -205,10 +205,9 @@ func MaybeChownDirRecursiveToMinikubeUser(dir string) error { return nil } -// TeeWithPrefix logs new lines from a reader. Designed to be run in the background. -func TeeWithPrefix(prefix string, r io.Reader, w io.Writer, logger func(format string, args ...interface{})) error { +// TeePrefix copies bytes from a reader to writer, logging each new line. +func TeePrefix(prefix string, r io.Reader, w io.Writer, logger func(format string, args ...interface{})) error { scanner := bufio.NewScanner(r) - // Collect individual bytes so that we don't accidentally strip newlines required by callers. scanner.Split(bufio.ScanBytes) var line bytes.Buffer diff --git a/pkg/util/utils_test.go b/pkg/util/utils_test.go index 2975e3edde6a..f1027a7e4c96 100644 --- a/pkg/util/utils_test.go +++ b/pkg/util/utils_test.go @@ -163,39 +163,38 @@ func TestGetBinaryDownloadURL(t *testing.T) { } -func TestTeeWithPrefix(t *testing.T) { +func TestTeePrefix(t *testing.T) { var in bytes.Buffer var out bytes.Buffer var logged strings.Builder logSink := func(format string, args ...interface{}) { - logged.WriteString("(") - logged.WriteString(fmt.Sprintf(format, args...)) - logged.WriteString(")") + logged.WriteString("(" + fmt.Sprintf(format, args...) + ")") } // Simulate the primary use case: tee in the background. This also helps avoid I/O races. var wg sync.WaitGroup wg.Add(1) go func() { - TeeWithPrefix(": ", &in, &out, logSink) + TeePrefix(":", &in, &out, logSink) wg.Done() }() in.Write([]byte("goo")) in.Write([]byte("\n")) - in.Write([]byte("gle")) + in.Write([]byte("g\r\n\r\n")) + in.Write([]byte("le")) wg.Wait() gotBytes := out.Bytes() - wantBytes := []byte("goo\ngle") + wantBytes := []byte("goo\ng\r\n\r\nle") if !bytes.Equal(gotBytes, wantBytes) { - t.Errorf("got bytes: %v, want: %v", gotBytes, wantBytes) + t.Errorf("output=%q, want: %q", gotBytes, wantBytes) } gotLog := logged.String() - wantLog := "(: goo)(: gle)" + wantLog := "(:goo)(:g)(:le)" if gotLog != wantLog { - t.Errorf("got log %q, want log %q", gotLog, wantLog) + t.Errorf("log=%q, want: %q", gotLog, wantLog) } } diff --git a/test/integration/util/util.go b/test/integration/util/util.go index 03c80562f499..1e9ec8c7ca3b 100644 --- a/test/integration/util/util.go +++ b/test/integration/util/util.go @@ -95,13 +95,13 @@ func (m *MinikubeRunner) teeRun(cmd *exec.Cmd) (string, string, error) { var wg sync.WaitGroup wg.Add(2) go func() { - if err := commonutil.TeeWithPrefix(commonutil.ErrPrefix, errPipe, &errB, Logf); err != nil { + if err := commonutil.TeePrefix(commonutil.ErrPrefix, errPipe, &errB, Logf); err != nil { m.T.Logf("tee: %v", err) } wg.Done() }() go func() { - if err := commonutil.TeeWithPrefix(commonutil.OutPrefix, outPipe, &outB, Logf); err != nil { + if err := commonutil.TeePrefix(commonutil.OutPrefix, outPipe, &outB, Logf); err != nil { m.T.Logf("tee: %v", err) } wg.Done() From 8aae0f72f810bfca8953572e2fa9546adb672d4c Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Thu, 20 Dec 2018 10:16:47 -0800 Subject: [PATCH 5/6] Set --v=5, which seems to be the initial right level for testing --- test/integration/docker_test.go | 2 +- test/integration/util/util.go | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/test/integration/docker_test.go b/test/integration/docker_test.go index 609af4458d6f..ede3f15ae220 100644 --- a/test/integration/docker_test.go +++ b/test/integration/docker_test.go @@ -40,7 +40,7 @@ func TestDocker(t *testing.T) { mk.RunWithContext(ctx, "delete") startCmd := fmt.Sprintf("start %s %s %s", mk.StartArgs, mk.Args, - "--docker-env=FOO=BAR --docker-env=BAZ=BAT --docker-opt=debug --docker-opt=icc=true") + "--docker-env=FOO=BAR --docker-env=BAZ=BAT --docker-opt=debug --docker-opt=icc=true --alsologtostderr --v=5") stdout, stderr, err := mk.RunWithContext(ctx, startCmd) if err != nil { t.Fatalf("start: %v\nstdout: %s\nstderr: %s", err, stdout, stderr) diff --git a/test/integration/util/util.go b/test/integration/util/util.go index 1e9ec8c7ca3b..7a4c11d77072 100644 --- a/test/integration/util/util.go +++ b/test/integration/util/util.go @@ -175,9 +175,9 @@ func (m *MinikubeRunner) Start() { switch r := m.Runtime; r { case constants.ContainerdRuntime: containerdFlags := "--container-runtime=containerd --network-plugin=cni --docker-opt containerd=/var/run/containerd/containerd.sock" - m.RunCommand(fmt.Sprintf("start %s %s %s --alsologtostderr --v=6", m.StartArgs, m.Args, containerdFlags), true) + m.RunCommand(fmt.Sprintf("start %s %s %s --alsologtostderr --v=5", m.StartArgs, m.Args, containerdFlags), true) default: - m.RunCommand(fmt.Sprintf("start %s %s --alsologtostderr --v=6", m.StartArgs, m.Args), true) + m.RunCommand(fmt.Sprintf("start %s %s --alsologtostderr --v=5", m.StartArgs, m.Args), true) } } From b5185c6b3fd284dc77ff71ae2553fe5008448b09 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Thu, 20 Dec 2018 10:17:41 -0800 Subject: [PATCH 6/6] err cleanup: include cmd/out/err, but keep messages small and deduped --- pkg/minikube/bootstrapper/ssh_runner.go | 37 +++++++++++++------------ 1 file changed, 20 insertions(+), 17 deletions(-) diff --git a/pkg/minikube/bootstrapper/ssh_runner.go b/pkg/minikube/bootstrapper/ssh_runner.go index 696bd47e267d..f10cb4dab5c0 100644 --- a/pkg/minikube/bootstrapper/ssh_runner.go +++ b/pkg/minikube/bootstrapper/ssh_runner.go @@ -100,19 +100,24 @@ func teeSSH(s *ssh.Session, cmd string, outB io.Writer, errB io.Writer) error { func (s *SSHRunner) Run(cmd string) error { glog.Infof("SSH: %s", cmd) sess, err := s.c.NewSession() + if err != nil { + return errors.Wrap(err, "NewSession") + } + defer func() { if err := sess.Close(); err != nil { if err != io.EOF { - glog.Errorf("close: %v", err) + glog.Errorf("session close: %v", err) } } }() - if err != nil { - return errors.Wrap(err, "getting ssh session") - } var outB bytes.Buffer var errB bytes.Buffer - return teeSSH(sess, cmd, &outB, &errB) + err = teeSSH(sess, cmd, &outB, &errB) + if err != nil { + return errors.Wrapf(err, "command failed: %s\nstdout: %s\nstderr: %s", cmd, outB.String(), errB.String()) + } + return nil } // CombinedOutputTo runs the command and stores both command @@ -120,7 +125,7 @@ func (s *SSHRunner) Run(cmd string) error { func (s *SSHRunner) CombinedOutputTo(cmd string, w io.Writer) error { out, err := s.CombinedOutput(cmd) if err != nil { - return errors.Wrapf(err, "running command: %s\n.", cmd) + return err } _, err = w.Write([]byte(out)) return err @@ -132,17 +137,17 @@ func (s *SSHRunner) CombinedOutput(cmd string) (string, error) { glog.Infoln("Run with output:", cmd) sess, err := s.c.NewSession() if err != nil { - return "", errors.Wrap(err, "getting ssh session") + return "", errors.Wrap(err, "NewSession") } defer sess.Close() var combined singleWriter err = teeSSH(sess, cmd, &combined, &combined) - b := combined.b.Bytes() + out := combined.b.String() if err != nil { - return "", errors.Wrapf(err, "running command: %s\n, output: %s", cmd, b) + return "", err } - return string(b), nil + return out, nil } // Copy copies a file to the remote over SSH. @@ -151,18 +156,18 @@ func (s *SSHRunner) Copy(f assets.CopyableFile) error { mkdirCmd := fmt.Sprintf("sudo mkdir -p %s", f.GetTargetDir()) for _, cmd := range []string{deleteCmd, mkdirCmd} { if err := s.Run(cmd); err != nil { - return errors.Wrapf(err, "Error running command: %s", cmd) + return errors.Wrapf(err, "pre-copy") } } sess, err := s.c.NewSession() if err != nil { - return errors.Wrap(err, "Error creating new session via ssh client") + return errors.Wrap(err, "NewSession") } w, err := sess.StdinPipe() if err != nil { - return errors.Wrap(err, "Error accessing StdinPipe via ssh session") + return errors.Wrap(err, "StdinPipe") } // The scpcmd below *should not* return until all data is copied and the // StdinPipe is closed. But let's use a WaitGroup to make it expicit. @@ -177,12 +182,10 @@ func (s *SSHRunner) Copy(f assets.CopyableFile) error { fmt.Fprint(w, "\x00") }() - scpcmd := fmt.Sprintf("sudo scp -t %s", f.GetTargetDir()) - out, err := sess.CombinedOutput(scpcmd) + _, err = sess.CombinedOutput(fmt.Sprintf("sudo scp -t %s", f.GetTargetDir())) if err != nil { - return errors.Wrapf(err, "Error running scp command: %s output: %s", scpcmd, out) + return err } wg.Wait() - return nil }