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

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

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,
+	)
+}

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...)
+}

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,
+	)
+}

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
 }