From 2dd9230e2455df1d8cb6be4dbac67d7932169052 Mon Sep 17 00:00:00 2001 From: "W. Trevor King" Date: Mon, 26 Nov 2018 11:30:33 -0800 Subject: [PATCH] pkg/lineprinter: Add a wrapper for Write -> Print 06c5fd36 (openshift-install: log debug output to file, 2018-11-15, #689), the global logrus level has been TraceLevel. Decisions about logging to a particular target are now made when adding the hook for that target. This broke our Terraform debug approach, which had been based on the level for the global logger. Since 06c5fd36, logrus.GetLevel() == logrus.DebugLevel will never be true. With this commit, I've replaced that switch and now just push all Terraform stdout into the default logger at the debug level. A new LinePrinter provides a shim between Terraform's stdout stream and the line-based log calls. I've added a local buffer for stderr, because Run [1] doesn't collect it automatically like Output does [2]. LinePrinter.Lock protects us from parallel writes, because [3]: The slice is valid for use only until the next buffer modification (that is, only until the next call to a method like Read, Write, Reset, or Truncate). The docs aren't clear about whether that limitation applies to ReadString or not [4], but the backing implementation has no internal lock to protect from changes made before the internal reference is copied into a new slice [5]. We're unlikely to actually have parallel writes for our Terraform use-case, but I'd rather be conservative now and not have to track down a race if someone decides to use LinePrinter for something concurrent later. The mutex is embedded at Alex's recommendation [6]. [1]: https://golang.org/pkg/os/exec/#Cmd.Run [2]: https://golang.org/pkg/os/exec/#Cmd.Output [3]: https://golang.org/pkg/bytes/#Buffer.Bytes [4]: https://golang.org/pkg/bytes/#Buffer.ReadString [5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439 [6]: https://github.com/openshift/installer/pull/730#discussion_r237304411 --- pkg/lineprinter/lineprinter.go | 83 +++++++++++++++++++++++++++++ pkg/lineprinter/lineprinter_test.go | 49 +++++++++++++++++ pkg/lineprinter/trimmer.go | 27 ++++++++++ pkg/lineprinter/trimmer_test.go | 22 ++++++++ pkg/terraform/executor.go | 24 ++++----- 5 files changed, 193 insertions(+), 12 deletions(-) create mode 100644 pkg/lineprinter/lineprinter.go create mode 100644 pkg/lineprinter/lineprinter_test.go create mode 100644 pkg/lineprinter/trimmer.go create mode 100644 pkg/lineprinter/trimmer_test.go diff --git a/pkg/lineprinter/lineprinter.go b/pkg/lineprinter/lineprinter.go new file mode 100644 index 00000000000..359a164c3cf --- /dev/null +++ b/pkg/lineprinter/lineprinter.go @@ -0,0 +1,83 @@ +// Package lineprinter wraps a Print implementation to provide an io.WriteCloser. +package lineprinter + +import ( + "bytes" + "io" + "sync" +) + +// Print is a type that can hold fmt.Print and other implementations +// which match that signature. For example, you can use: +// +// trimmer := &lineprinter.Trimmer{WrappedPrint: logrus.StandardLogger().Debug} +// linePrinter := &linePrinter{Print: trimmer.Print} +// +// to connect the line printer to logrus at the debug level. +type Print func(args ...interface{}) + +// LinePrinter is an io.WriteCloser that buffers written bytes. +// During each Write, newline-terminated lines are removed from the +// buffer and passed to Print. On Close, any content remaining in the +// buffer is also passed to Print. +// +// One use-case is connecting a subprocess's standard streams to a +// logger: +// +// linePrinter := &linePrinter{ +// Print: &Trimmer{WrappedPrint: logrus.StandardLogger().Debug}.Print, +// } +// defer linePrinter.Close() +// cmd := exec.Command(...) +// cmd.Stdout = linePrinter +// +// LinePrinter buffers the subcommand's byte stream and splits it into +// lines for the logger. Sometimes we might have a partial line +// written to the buffer. We don't want to push that partial line into +// the logs if the next read attempt will pull in the remainder of the +// line. But we do want to push that partial line into the logs if there +// will never be a next read. So LinePrinter.Write pushes any +// complete lines to the wrapped printer, and LinePrinter.Close pushes +// any remaining partial line. +type LinePrinter struct { + buf bytes.Buffer + Print Print + + sync.Mutex +} + +// Write writes len(p) bytes from p to an internal buffer. Then it +// retrieves any newline-terminated lines from the internal buffer and +// prints them with lp.Print. Partial lines are left in the internal +// buffer. +func (lp *LinePrinter) Write(p []byte) (int, error) { + lp.Lock() + defer lp.Unlock() + n, err := lp.buf.Write(p) + if err != nil { + return n, err + } + + for { + line, err := lp.buf.ReadString(byte('\n')) + if err == io.EOF { + _, err = lp.buf.Write([]byte(line)) + return n, err + } else if err != nil { + return n, err + } + + lp.Print(line) + } +} + +// Close prints anything that remains in the buffer. +func (lp *LinePrinter) Close() error { + lp.Lock() + defer lp.Unlock() + line := lp.buf.String() + if len(line) > 0 { + lp.Print(line) + } + return nil +} diff --git a/pkg/lineprinter/lineprinter_test.go b/pkg/lineprinter/lineprinter_test.go new file mode 100644 index 00000000000..470b8e17f2d --- /dev/null +++ b/pkg/lineprinter/lineprinter_test.go @@ -0,0 +1,49 @@ +package lineprinter + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +type printer struct { + data [][]interface{} +} + +func (p *printer) print(args ...interface{}) { + p.data = append(p.data, args) +} + +func TestLinePrinter(t *testing.T) { + print := &printer{} + lp := &LinePrinter{Print: print.print} + data := []byte("Hello\nWorld\nAnd more") + n, err := lp.Write(data) + if err != nil { + t.Fatal(err) + } + + assert.Equal(t, len(data), n) + assert.Equal( + t, + [][]interface{}{ + {"Hello\n"}, + {"World\n"}, + }, + print.data, + ) + print.data = [][]interface{}{} + + err = lp.Close() + if err != nil { + t.Fatal(err) + } + + assert.Equal( + t, + [][]interface{}{ + {"And more"}, + }, + print.data, + ) +} diff --git a/pkg/lineprinter/trimmer.go b/pkg/lineprinter/trimmer.go new file mode 100644 index 00000000000..d2b7c77521c --- /dev/null +++ b/pkg/lineprinter/trimmer.go @@ -0,0 +1,27 @@ +package lineprinter + +import ( + "strings" +) + +// Trimmer is a Print wrapper that removes trailing newlines from the +// final argument (if it is a string argument). This is useful for +// connecting a LinePrinter to a logger whose Print-analog does not +// expect trailing newlines. +type Trimmer struct { + WrappedPrint Print +} + +// Print removes trailing newlines from the final argument (if it is a +// string argument) and then passes the arguments through to +// WrappedPrint. +func (t *Trimmer) Print(args ...interface{}) { + if len(args) > 0 { + i := len(args) - 1 + arg, ok := args[i].(string) + if ok { + args[i] = strings.TrimRight(arg, "\n") + } + } + t.WrappedPrint(args...) +} diff --git a/pkg/lineprinter/trimmer_test.go b/pkg/lineprinter/trimmer_test.go new file mode 100644 index 00000000000..1a883f96085 --- /dev/null +++ b/pkg/lineprinter/trimmer_test.go @@ -0,0 +1,22 @@ +package lineprinter + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestTrimmer(t *testing.T) { + print := &printer{} + trimmer := &Trimmer{WrappedPrint: print.print} + trimmer.Print("Hello\n", "World\n") + trimmer.Print(123) + assert.Equal( + t, + [][]interface{}{ + {"Hello\n", "World"}, + {123}, + }, + print.data, + ) +} diff --git a/pkg/terraform/executor.go b/pkg/terraform/executor.go index 0d8779e4c6f..abd46ab1643 100644 --- a/pkg/terraform/executor.go +++ b/pkg/terraform/executor.go @@ -1,12 +1,14 @@ package terraform import ( + "bytes" "os" "os/exec" "path/filepath" "runtime" "strings" + "github.com/openshift/installer/pkg/lineprinter" "github.com/pkg/errors" "github.com/sirupsen/logrus" ) @@ -59,24 +61,22 @@ func (ex *executor) execute(clusterDir string, args ...string) error { return errors.Errorf("clusterDir is unset. Quitting") } + trimmer := &lineprinter.Trimmer{WrappedPrint: logrus.StandardLogger().Debug} + linePrinter := &lineprinter.LinePrinter{Print: trimmer.Print} + defer linePrinter.Close() + + stderr := &bytes.Buffer{} + cmd := exec.Command(ex.binaryPath, args...) cmd.Dir = clusterDir + cmd.Stdout = linePrinter + cmd.Stderr = stderr logrus.Debugf("Running %#v...", cmd) - - if logrus.GetLevel() == logrus.DebugLevel { - cmd.Stdin = os.Stdin - cmd.Stdout = os.Stdout - cmd.Stderr = os.Stderr - return cmd.Run() - } - - output, err := cmd.Output() + err := cmd.Run() if err != nil { exitError := err.(*exec.ExitError) - if len(exitError.Stderr) == 0 { - exitError.Stderr = output - } + exitError.Stderr = stderr.Bytes() } return err }