pkg/lineprinter: Add a wrapper for Write -> Print

06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#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 06c5fd3, 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.

[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

pkg/lineprinter/lineprinter.go

@@ -0,0 +1,73 @@
+// 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
+type LinePrinter struct {
+	buf   bytes.Buffer
+	lock  sync.Mutex
+	Print Print
+}
+
+// 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.Lock()
+	defer lp.lock.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.Lock()
+	defer lp.lock.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/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
 }