Added logging tests and better windows support

cmd/cmd.go

@@ -155,9 +155,18 @@ var (
 	SCMCommit = ""
 	// SCMRepository is the source repository. It is injected at compile time.
 	SCMRepository = ""
-	Logger        = internallog.NewLogWithWriters()
+
+	Logger = newLogger()
 )
 
+func newLogger() logging.Logger {
+	stdout := internallog.New(os.Stdout)
+	defer stdout.Close()
+	stderr := internallog.New(os.Stderr)
+	defer stderr.Close()
+	return internallog.NewLogWithWriters(stdout, stderr)
+}
+
 // buildVersion is a display format of the version and build metadata in compliance with semver.
 func buildVersion() string {
 	// noinspection GoBoolExpressions

internal/logging/logging.go

@@ -2,6 +2,7 @@
 package logging
 
 import (
+	"bytes"
 	"fmt"
 	"io"
 	"io/ioutil"
@@ -18,6 +19,7 @@ import (
 const (
 	errorLevelText = "ERROR: "
 	warnLevelText  = "Warning: "
+	lineFeed       = '\n'
 
 	// time format the out logging uses
 	timeFmt = "2006/01/02 15:04:05.000000"
@@ -117,7 +119,7 @@ func (lw *logWithWriters) WantLevel(level string) {
 }
 
 // NewLogWithWriters creates a logger to be used with pack CLI.
-func NewLogWithWriters() *logWithWriters {
+func NewLogWithWriters(stdout, stderr io.Writer) *logWithWriters {
 	hnd := &handler{
 		writer: os.Stdout,
 		timer: func() time.Time {
@@ -132,3 +134,59 @@ func NewLogWithWriters() *logWithWriters {
 	lw.Logger.Level = log.DebugLevel
 	return &lw
 }
+
+// Writer wraps console output file descriptors and will optionally strip ANSI color codes from output.  The reason
+// this is needed is because build pack scripts are generally bash shell scripts and are executed on a docker container.
+// The output from these scripts often contain color codes and the docker api returns this raw console output to
+// pack code.  If pack is running on Windows, the output containing the color codes looks like crap.
+type Writer struct {
+	sync.Mutex
+	buffer bytes.Buffer
+	out    io.Writer
+}
+
+// New creates writer taking something that implements io.Writer as an argument.
+func New(w io.Writer) *Writer {
+	return &Writer{
+		out: w,
+	}
+}
+
+func write(w *Writer, b []byte) {
+	if len(b) == 0 {
+		return
+	}
+	i := bytes.IndexByte(b, lineFeed)
+	if i == -1 {
+		w.buffer.Write(b)
+		return
+	}
+	w.buffer.Write(b[:i+1])
+	_, _ = fmt.Fprint(w.out, maybeStripColor(w.buffer.Bytes()))
+	w.buffer.Reset()
+	write(w, b[i+1:])
+}
+
+// Write buffered input is written to the underlying io.Writer when a line feed occurs.
+func (w *Writer) Write(b []byte) (n int, err error) {
+	w.Lock()
+	defer w.Unlock()
+	n = len(b)
+	write(w, b)
+	return n, err
+}
+
+// Close writes any remaining buffer contents to underlying io.Writer
+func (w *Writer) Close() error {
+	w.Lock()
+	defer w.Unlock()
+	if w.buffer.Len() == 0 {
+		return nil
+	}
+	contents := maybeStripColor(w.buffer.Bytes())
+	if len(contents) > 0 {
+		_, err := fmt.Fprintln(w.out, contents)
+		return err
+	}
+	return nil
+}

internal/logging/logging_test.go

@@ -0,0 +1,287 @@
+package logging
+
+import (
+	"bytes"
+	"io"
+	"io/ioutil"
+	"runtime"
+	"testing"
+	"time"
+
+	"github.com/apex/log"
+	"github.com/fatih/color"
+	"github.com/sclevine/spec"
+
+	h "github.com/buildpack/lifecycle/testhelpers"
+)
+
+const testTime = "2019/05/15 01:01:01.000000"
+
+func newTestLogger(stdout, stderr io.Writer) *logWithWriters {
+	hnd := &handler{
+		writer: stdout,
+		timer: func() time.Time {
+			tm, _ := time.Parse(timeFmt, testTime)
+			return tm
+		},
+	}
+	var lw logWithWriters
+	lw.handler = hnd
+	lw.out = hnd.writer
+	lw.errOut = stderr
+	lw.Logger.Handler = hnd
+	lw.Logger.Level = log.DebugLevel
+	return &lw
+}
+
+func TestPackCLILogger(t *testing.T) {
+	spec.Run(t, "PackCLILogger", func(t *testing.T, when spec.G, it spec.S) {
+		var log, errLog bytes.Buffer
+		var logger *logWithWriters
+
+		it.Before(func() {
+			color.NoColor = false
+			logger = newTestLogger(&log, &errLog)
+		})
+
+		it.After(func() {
+			log.Reset()
+			errLog.Reset()
+		})
+
+		it("can enable time in logs", func() {
+			logger.WantTime(true)
+			logger.Error("test")
+			expected := "2019/05/15 01:01:01.000000 \x1b[31;1mERROR: \x1b[0mtest\n"
+			h.AssertEq(t, log.String(), expected)
+		})
+
+		it("it has no time and color by default", func() {
+			logger.Error("test")
+			expected := "\x1b[31;1mERROR: \x1b[0mtest\n"
+			h.AssertEq(t, log.String(), expected)
+		})
+
+		it("can disable color logs", func() {
+			color.NoColor = true
+			logger.Error("test")
+			expected := "ERROR: test\n"
+			h.AssertEq(t, log.String(), expected)
+		})
+
+		it("non-error levels not shown", func() {
+			logger.Info("test")
+			expected := "test\n"
+			h.AssertEq(t, log.String(), expected)
+		})
+
+		it("will not show verbose messages if quiet", func() {
+			logger.WantLevel("info")
+			logger.Debug("hello")
+			logger.Debugf("there")
+			h.AssertEq(t, log.String(), "")
+			logger.Info("test")
+			expected := "test\n"
+			h.AssertEq(t, log.String(), expected)
+
+			testOut := logger.Writer()
+			h.AssertSameInstance(t, testOut, &log)
+
+			testOut = logger.DebugErrorWriter()
+			h.AssertSameInstance(t, testOut, ioutil.Discard)
+		})
+
+		it("will return correct writers", func() {
+			testOut := logger.Writer()
+			h.AssertSameInstance(t, testOut, &log)
+
+			testOut = logger.DebugErrorWriter()
+			h.AssertSameInstance(t, testOut, &errLog)
+		})
+
+		it("will convert an empty string to a line feed", func() {
+			logger.Info("")
+			expected := "\n"
+			h.AssertEq(t, log.String(), expected)
+		})
+	})
+}
+
+func TestColor(t *testing.T) {
+	spec.Run(t, "writer", func(t *testing.T, when spec.G, it spec.S) {
+		var previousColorSetting bool
+		var wtr *Writer
+		var out bytes.Buffer
+
+		it.Before(func() {
+			previousColorSetting = color.NoColor
+			wtr = New(&out)
+		})
+
+		it.After(func() {
+			color.NoColor = previousColorSetting
+			out.Reset()
+		})
+
+		when("color enabled", func() {
+			it.Before(func() {
+				if runtime.GOOS == "windows" {
+					t.Skip("with color tests disabled on windows")
+				}
+				color.NoColor = false
+			})
+
+			it("should add color", func() {
+				writeLines(wtr,
+					color.RedString("line one "),
+					color.YellowString("line two\n"),
+				)
+				want := "\x1b[31mline one \x1b[0m\x1b[33mline two\n\x1b[0m\n"
+				got := out.String()
+				h.AssertEq(t, got, want)
+			})
+
+			it("should handle split lines", func() {
+				writeLines(wtr,
+					color.RedString("one\ntwo"),
+					"\nthree",
+				)
+				want := "\x1b[31mone\ntwo\x1b[0m\nthree\n"
+				got := out.String()
+				h.AssertEq(t, got, want)
+			})
+
+			it("should handle empty input", func() {
+				writeLines(wtr, "")
+				want := ""
+				got := out.String()
+				h.AssertEq(t, got, want)
+			})
+
+			it("should handle single line", func() {
+				writeLines(wtr, "a line\n")
+				want := "a line\n"
+				got := out.String()
+				h.AssertEq(t, got, want)
+			})
+
+		})
+
+		when("color disabled", func() {
+			it.Before(func() {
+				color.NoColor = true
+			})
+
+			it("should strip color", func() {
+				writeLines(wtr, color.RedString("line one "), color.YellowString("line two\n"))
+				want := "line one line two\n"
+				got := out.String()
+				h.AssertEq(t, got, want)
+			})
+
+			it("handles split lines", func() {
+				writeLines(wtr, color.RedString("one\ntwo"), "\nthree")
+				want := "one\ntwo\nthree\n"
+				got := out.String()
+				h.AssertEq(t, got, want)
+			})
+		})
+	})
+}
+
+func writeLines(w io.WriteCloser, lines ...string) {
+	for _, line := range lines {
+		_, _ = w.Write([]byte(line))
+	}
+	_ = w.Close()
+}
+
+func TestMaybeStripColors(t *testing.T) {
+	spec.Run(t, "combinations", func(t *testing.T, when spec.G, it spec.S) {
+		var originalColorSetting bool
+		it.Before(func() {
+			originalColorSetting = color.NoColor
+			color.NoColor = true
+		})
+		it.After(func() {
+			color.NoColor = originalColorSetting
+		})
+		it("should strip color", func() {
+			baseAttrs := []color.Attribute{
+				color.Reset,
+				color.Bold,
+				color.Faint,
+				color.Italic,
+				color.Underline,
+				color.BlinkSlow,
+				color.BlinkRapid,
+				color.ReverseVideo,
+				color.Concealed,
+				color.CrossedOut,
+			}
+			foregroundAttrs := []color.Attribute{
+				color.FgBlack,
+				color.FgRed,
+				color.FgGreen,
+				color.FgYellow,
+				color.FgBlue,
+				color.FgMagenta,
+				color.FgCyan,
+				color.FgWhite,
+				color.FgHiBlack,
+				color.FgHiRed,
+				color.FgHiGreen,
+				color.FgHiYellow,
+				color.FgHiBlue,
+				color.FgHiMagenta,
+				color.FgHiCyan,
+				color.FgHiWhite,
+			}
+			backgroundAttrs := []color.Attribute{
+				color.BgBlack,
+				color.BgRed,
+				color.BgGreen,
+				color.BgYellow,
+				color.BgBlue,
+				color.BgMagenta,
+				color.BgCyan,
+				color.BgWhite,
+				color.BgHiBlack,
+				color.BgHiRed,
+				color.BgHiGreen,
+				color.BgHiYellow,
+				color.BgHiBlue,
+				color.BgHiMagenta,
+				color.BgHiCyan,
+				color.BgHiWhite,
+			}
+			want := "Hello, 786 colorful\n[ ]; world."
+			testCombo := func(c *color.Color) {
+				var out bytes.Buffer
+				_, _ = c.Fprint(&out, want)
+				got := maybeStripColor(out.Bytes())
+				if got != want {
+					t.Logf("color %+v", *c)
+					t.Fatalf("got %q want %q", got, want)
+				}
+			}
+
+			for i := 0; i < len(baseAttrs); i++ {
+				testCombo(color.New(baseAttrs[i]))
+
+				for j := 0; j < len(foregroundAttrs); j++ {
+					testCombo(color.New(foregroundAttrs[j]))
+					testCombo(color.New(baseAttrs[i], foregroundAttrs[j]))
+
+					for k := 0; k < len(backgroundAttrs); k++ {
+						testCombo(color.New(backgroundAttrs[k]))
+						testCombo(color.New(backgroundAttrs[k], foregroundAttrs[j]))
+						testCombo(color.New(backgroundAttrs[k], baseAttrs[i]))
+						testCombo(color.New(baseAttrs[i], foregroundAttrs[j], backgroundAttrs[k]))
+					}
+				}
+			}
+		})
+
+	})
+}