Merge pull request #510 from tommyknows/logging

Logging

modules/docker/build.go

@@ -19,6 +19,9 @@ type BuildOptions struct {
 	// Terratest to not have to support every single command-line option offered by the 'docker build' command, and
 	// solely focus on the most important ones.
 	OtherOptions []string
+
+	// Set a logger that should be used. See the logger package for more info.
+	Logger *logger.Logger
 }
 
 // Build runs the 'docker build' command at the given path with the given options and fails the test if there are any
@@ -29,7 +32,7 @@ func Build(t testing.TestingT, path string, options *BuildOptions) {
 
 // BuildE runs the 'docker build' command at the given path with the given options and returns any errors.
 func BuildE(t testing.TestingT, path string, options *BuildOptions) error {
-	logger.Logf(t, "Running 'docker build' in %s", path)
+	options.Logger.Logf(t, "Running 'docker build' in %s", path)
 
 	args, err := formatDockerBuildArgs(path, options)
 	if err != nil {
@@ -39,6 +42,7 @@ func BuildE(t testing.TestingT, path string, options *BuildOptions) error {
 	cmd := shell.Command{
 		Command: "docker",
 		Args:    args,
+		Logger:  options.Logger,
 	}
 
 	_, buildErr := shell.RunCommandAndGetOutputE(t, cmd)
@@ -57,9 +61,7 @@ func formatDockerBuildArgs(path string, options *BuildOptions) ([]string, error)
 		args = append(args, "--build-arg", arg)
 	}
 
-	for _, opt := range options.OtherOptions {
-		args = append(args, opt)
-	}
+	args = append(args, options.OtherOptions...)
 
 	args = append(args, path)
 

modules/docker/docker_compose.go

@@ -1,6 +1,7 @@
 package docker
 
 import (
+	"github.com/gruntwork-io/terratest/modules/logger"
 	"github.com/gruntwork-io/terratest/modules/shell"
 	"github.com/gruntwork-io/terratest/modules/testing"
 )
@@ -9,6 +10,8 @@ import (
 type Options struct {
 	WorkingDir string
 	EnvVars    map[string]string
+	// Set a logger that should be used. See the logger package for more info.
+	Logger *logger.Logger
 }
 
 // RunDockerCompose runs docker-compose with the given arguments and options and return stdout/stderr.
@@ -29,6 +32,7 @@ func RunDockerComposeE(t testing.TestingT, options *Options, args ...string) (st
 		Args:       append([]string{"--project-name", t.Name()}, args...),
 		WorkingDir: options.WorkingDir,
 		Env:        options.EnvVars,
+		Logger:     options.Logger,
 	}
 
 	return shell.RunCommandAndGetOutputE(t, cmd)

modules/docker/inspect.go

@@ -8,6 +8,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/gruntwork-io/terratest/modules/logger"
 	"github.com/gruntwork-io/terratest/modules/shell"
 	"github.com/stretchr/testify/require"
 )
@@ -125,6 +126,8 @@ func InspectE(t *testing.T, id string) (*ContainerInspect, error) {
 	cmd := shell.Command{
 		Command: "docker",
 		Args:    []string{"container", "inspect", id},
+		// inspect is a short-running command, don't print the output.
+		Logger: logger.Discard,
 	}
 
 	out, err := shell.RunCommandAndGetStdOutE(t, cmd)

modules/docker/run.go

@@ -47,6 +47,9 @@ type RunOptions struct {
 	// Terratest to not have to support every single command-line option offered by the 'docker run' command, and
 	// solely focus on the most important ones.
 	OtherOptions []string
+
+	// Set a logger that should be used. See the logger package for more info.
+	Logger *logger.Logger
 }
 
 // Run runs the 'docker run' command on the given image with the given options and return stdout/stderr. This method
@@ -59,7 +62,7 @@ func Run(t testing.TestingT, image string, options *RunOptions) string {
 
 // RunE runs the 'docker run' command on the given image with the given options and return stdout/stderr, or any error.
 func RunE(t testing.TestingT, image string, options *RunOptions) (string, error) {
-	logger.Logf(t, "Running 'docker run' on image '%s'", image)
+	options.Logger.Logf(t, "Running 'docker run' on image '%s'", image)
 
 	args, err := formatDockerRunArgs(image, options)
 	if err != nil {
@@ -69,6 +72,7 @@ func RunE(t testing.TestingT, image string, options *RunOptions) (string, error)
 	cmd := shell.Command{
 		Command: "docker",
 		Args:    args,
+		Logger:  options.Logger,
 	}
 
 	return shell.RunCommandAndGetOutputE(t, cmd)
@@ -85,7 +89,7 @@ func RunAndGetID(t testing.TestingT, image string, options *RunOptions) string {
 // RunAndGetIDE runs the 'docker run' command on the given image with the given options and returns the container ID
 // that is returned in stdout, or any error.
 func RunAndGetIDE(t testing.TestingT, image string, options *RunOptions) (string, error) {
-	logger.Logf(t, "Running 'docker run' on image '%s', returning stdout", image)
+	options.Logger.Logf(t, "Running 'docker run' on image '%s', returning stdout", image)
 
 	args, err := formatDockerRunArgs(image, options)
 	if err != nil {
@@ -95,6 +99,7 @@ func RunAndGetIDE(t testing.TestingT, image string, options *RunOptions) (string
 	cmd := shell.Command{
 		Command: "docker",
 		Args:    args,
+		Logger:  options.Logger,
 	}
 
 	return shell.RunCommandAndGetStdOutE(t, cmd)
@@ -144,15 +149,11 @@ func formatDockerRunArgs(image string, options *RunOptions) ([]string, error) {
 		args = append(args, "--volume", volume)
 	}
 
-	for _, opt := range options.OtherOptions {
-		args = append(args, opt)
-	}
+	args = append(args, options.OtherOptions...)
 
 	args = append(args, image)
 
-	for _, arg := range options.Command {
-		args = append(args, arg)
-	}
+	args = append(args, options.Command...)
 
 	return args, nil
 }

modules/docker/stop.go

@@ -13,6 +13,9 @@ import (
 type StopOptions struct {
 	// Seconds to wait for stop before killing the container (default 10)
 	Time int
+
+	// Set a logger that should be used. See the logger package for more info.
+	Logger *logger.Logger
 }
 
 // Stop runs the 'docker stop' command for the given containers and return the stdout/stderr. This method fails
@@ -25,7 +28,7 @@ func Stop(t testing.TestingT, containers []string, options *StopOptions) string
 
 // StopE runs the 'docker stop' command for the given containers and returns any errors.
 func StopE(t testing.TestingT, containers []string, options *StopOptions) (string, error) {
-	logger.Logf(t, "Running 'docker stop' on containers '%s'", containers)
+	options.Logger.Logf(t, "Running 'docker stop' on containers '%s'", containers)
 
 	args, err := formatDockerStopArgs(containers, options)
 	if err != nil {
@@ -35,6 +38,7 @@ func StopE(t testing.TestingT, containers []string, options *StopOptions) (strin
 	cmd := shell.Command{
 		Command: "docker",
 		Args:    args,
+		Logger:  options.Logger,
 	}
 
 	return shell.RunCommandAndGetOutputE(t, cmd)

modules/helm/cmd.go

@@ -61,6 +61,7 @@ func RunHelmCommandAndGetOutputE(t testing.TestingT, options *Options, cmd strin
 		Args:       args,
 		WorkingDir: ".",
 		Env:        options.EnvVars,
+		Logger:     options.Logger,
 	}
 	return shell.RunCommandAndGetOutputE(t, helmCmd)
 }

modules/helm/options.go

@@ -2,6 +2,7 @@ package helm
 
 import (
 	"github.com/gruntwork-io/terratest/modules/k8s"
+	"github.com/gruntwork-io/terratest/modules/logger"
 )
 
 type Options struct {
@@ -13,4 +14,5 @@ type Options struct {
 	HomePath       string              // The path to the helm home to use when calling out to helm. Empty string means use default ($HOME/.helm).
 	EnvVars        map[string]string   // Environment variables to set when running helm
 	Version        string              // Version of chart
+	Logger         *logger.Logger      // Set a non-default logger that should be used. See the logger package for more info.
 }

modules/logger/logger.go

@@ -7,36 +7,134 @@ import (
 	"os"
 	"runtime"
 	"strings"
+	gotesting "testing"
 	"time"
 
 	"github.com/gruntwork-io/terratest/modules/testing"
 )
 
+var (
+	// Default is the default logger that is used for the Logf function, if no one is provided. It uses the
+	// TerratestLogger to log messages. This can be overwritten to change the logging globally.
+	Default = New(terratestLogger{})
+	// Discard discards all logging.
+	Discard = New(discardLogger{})
+	// Terratest logs the given format and arguments, formatted using fmt.Sprintf, to stdout, along with a timestamp and
+	// information about what test and file is doing the logging. Before Go 1.14, this is an alternative to t.Logf as it
+	// logs to stdout immediately, rather than buffering all log output and only displaying it at the very end of the test.
+	// This is useful because:
+	//
+	// 1. It allows you to iterate faster locally, as you get feedback on whether your code changes are working as expected
+	//    right away, rather than at the very end of the test run.
+	//
+	// 2. If you have a bug in your code that causes a test to never complete or if the test code crashes, t.Logf would
+	//    show you no log output whatsoever, making debugging very hard, where as this method will show you all the log
+	//    output available.
+	//
+	// 3. If you have a test that takes a long time to complete, some CI systems will kill the test suite prematurely
+	//    because there is no log output with t.Logf (e.g., CircleCI kills tests after 10 minutes of no log output). With
+	//    this log method, you get log output continuously.
+	//
+	Terratest = New(terratestLogger{})
+	// TestingT can be used to use Go's testing.T to log. If this is used, but no testing.T is provided, it will fallback
+	// to Default.
+	TestingT = New(testingT{})
+)
+
+type TestLogger interface {
+	Logf(t testing.TestingT, format string, args ...interface{})
+}
+
+type Logger struct {
+	l TestLogger
+}
+
+func New(l TestLogger) *Logger {
+	return &Logger{
+		l,
+	}
+}
+
+func (l *Logger) Logf(t testing.TestingT, format string, args ...interface{}) {
+	if tt, ok := t.(helper); ok {
+		tt.Helper()
+	}
+
+	// methods can be called on (typed) nil pointers. In this case, use the Default function to log. This enables the
+	// caller to do `var l *Logger` and then use the logger already.
+	if l == nil || l.l == nil {
+		Default.Logf(t, format, args...)
+		return
+	}
+
+	l.l.Logf(t, format, args...)
+}
+
+// helper is used to mark this library as a "helper", and thus not appearing in the line numbers. testing.T implements
+// this interface, for example.
+type helper interface {
+	Helper()
+}
+
+type discardLogger struct{}
+
+func (_ discardLogger) Logf(_ testing.TestingT, format string, args ...interface{}) {}
+
+type testingT struct{}
+
+func (_ testingT) Logf(t testing.TestingT, format string, args ...interface{}) {
+	// this should never fail
+	tt, ok := t.(*gotesting.T)
+	if !ok {
+		// fallback
+		DoLog(t, 2, os.Stdout, fmt.Sprintf(format, args...))
+		return
+	}
+
+	tt.Helper()
+	tt.Logf(format, args...)
+	return
+}
+
+type terratestLogger struct{}
+
+func (_ terratestLogger) Logf(t testing.TestingT, format string, args ...interface{}) {
+	DoLog(t, 3, os.Stdout, fmt.Sprintf(format, args...))
+}
+
+// Deprecated: use Logger instead, as it provides more flexibility on logging.
 // Logf logs the given format and arguments, formatted using fmt.Sprintf, to stdout, along with a timestamp and information
-// about what test and file is doing the logging. This is an alternative to t.Logf that logs to stdout immediately,
-// rather than buffering all log output and only displaying it at the very end of the test. This is useful because:
+// about what test and file is doing the logging. Before Go 1.14, this is an alternative to t.Logf as it logs to stdout
+// immediately, rather than buffering all log output and only displaying it at the very end of the test. This is useful
+// because:
 //
 // 1. It allows you to iterate faster locally, as you get feedback on whether your code changes are working as expected
 //    right away, rather than at the very end of the test run.
 //
-// 2. If you have a bug in your code that causes a test to never complete or if the test code crashes,, t.Logf would
+// 2. If you have a bug in your code that causes a test to never complete or if the test code crashes, t.Logf would
 //    show you no log output whatsoever, making debugging very hard, where as this method will show you all the log
 //    output available.
 //
 // 3. If you have a test that takes a long time to complete, some CI systems will kill the test suite prematurely
 //    because there is no log output with t.Logf (e.g., CircleCI kills tests after 10 minutes of no log output). With
 //    this log method, you get log output continuously.
-//
-// Note that there is a proposal to improve t.Logf (https://github.com/golang/go/issues/24929), but until that's
-// implemented, this method is our best bet.
+// Although t.Logf now supports streaming output since Go 1.14, this is kept for compatibility purposes.
 func Logf(t testing.TestingT, format string, args ...interface{}) {
+	if tt, ok := t.(helper); ok {
+		tt.Helper()
+	}
+
 	DoLog(t, 2, os.Stdout, fmt.Sprintf(format, args...))
 }
 
 // Log logs the given arguments to stdout, along with a timestamp and information about what test and file is doing the
 // logging. This is an alternative to t.Logf that logs to stdout immediately, rather than buffering all log output and
 // only displaying it at the very end of the test. See the Logf method for more info.
 func Log(t testing.TestingT, args ...interface{}) {
+	if tt, ok := t.(helper); ok {
+		tt.Helper()
+	}
+
 	DoLog(t, 2, os.Stdout, args...)
 }
 

modules/logger/logger_test.go

@@ -6,6 +6,7 @@ import (
 	"strings"
 	"testing"
 
+	tftesting "github.com/gruntwork-io/terratest/modules/testing"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -19,3 +20,35 @@ func TestDoLog(t *testing.T) {
 
 	assert.Regexp(t, fmt.Sprintf("^%s .+? [[:word:]]+.go:[0-9]+: %s$", t.Name(), text), strings.TrimSpace(buffer.String()))
 }
+
+type customLogger struct {
+	logs []string
+}
+
+func (c *customLogger) Logf(t tftesting.TestingT, format string, args ...interface{}) {
+	c.logs = append(c.logs, fmt.Sprintf(format, args...))
+}
+
+func TestCustomLogger(t *testing.T) {
+	Logf(t, "this should be logged with the default logger")
+
+	var l *Logger
+	l.Logf(t, "this should be logged with the default logger too")
+
+	l = New(nil)
+	l.Logf(t, "this should be logged with the default logger too!")
+
+	c := &customLogger{}
+	l = New(c)
+	l.Logf(t, "log output 1")
+	l.Logf(t, "log output 2")
+
+	t.Run("logger-subtest", func(t *testing.T) {
+		l.Logf(t, "subtest log")
+	})
+
+	assert.Len(t, c.logs, 3)
+	assert.Equal(t, "log output 1", c.logs[0])
+	assert.Equal(t, "log output 2", c.logs[1])
+	assert.Equal(t, "subtest log", c.logs[2])
+}

modules/packer/packer.go

@@ -27,6 +27,7 @@ type Options struct {
 	MaxRetries         int               // Maximum number of times to retry errors matching RetryableErrors
 	TimeBetweenRetries time.Duration     // The amount of time to wait between retries
 	WorkingDir         string            // The directory to run packer in
+	Logger             *logger.Logger    // If set, use a non-default logger
 }
 
 // BuildArtifacts can take a map of identifierName <-> Options and then parallelize
@@ -88,7 +89,7 @@ func BuildArtifact(t testing.TestingT, options *Options) string {
 
 // BuildArtifactE builds the given Packer template and return the generated Artifact ID.
 func BuildArtifactE(t testing.TestingT, options *Options) (string, error) {
-	logger.Logf(t, "Running Packer to generate a custom artifact for template %s", options.Template)
+	options.Logger.Logf(t, "Running Packer to generate a custom artifact for template %s", options.Template)
 
 	cmd := shell.Command{
 		Command:    "packer",