Merge pull request #7948 from hashicorp/dnephin/buffer-test-logs

testutil: NewLogBuffer - buffer logs until a test fails

agent/acl_test.go

@@ -59,7 +59,7 @@ func NewTestACLAgent(t *testing.T, name string, hcl string, resolveAuthz authzRe
 	a := &TestACLAgent{Name: name, HCL: hcl, resolveAuthzFn: resolveAuthz, resolveIdentFn: resolveIdent}
 	dataDir := `data_dir = "acl-agent"`
 
-	logOutput := testutil.TestWriter(t)
+	logOutput := testutil.NewLogBuffer(t)
 	logger := hclog.NewInterceptLogger(&hclog.LoggerOptions{
 		Name:   a.Name,
 		Level:  hclog.Debug,

agent/ae/ae_test.go

@@ -394,7 +394,7 @@ func (m *mock) SyncChanges() error {
 func testSyncer(t *testing.T) *StateSyncer {
 	logger := hclog.New(&hclog.LoggerOptions{
 		Level:  0,
-		Output: testutil.TestWriter(t),
+		Output: testutil.NewLogBuffer(t),
 	})
 
 	l := NewStateSyncer(nil, time.Second, nil, logger)

agent/checks/check.go

@@ -4,6 +4,7 @@ import (
 	"crypto/tls"
 	"fmt"
 	"io"
+	"io/ioutil"
 	"net"
 	"net/http"
 	"os"
@@ -14,7 +15,6 @@ import (
 	"time"
 
 	"github.com/hashicorp/consul/agent/structs"
-	"github.com/hashicorp/consul/sdk/testutil"
 	"github.com/hashicorp/go-hclog"
 
 	"github.com/armon/circbuf"
@@ -607,7 +607,7 @@ func (c *CheckDocker) Start() {
 	}
 
 	if c.Logger == nil {
-		c.Logger = testutil.NewDiscardLogger()
+		c.Logger = hclog.New(&hclog.LoggerOptions{Output: ioutil.Discard})
 	}
 
 	if c.Shell == "" {

agent/consul/acl_test.go

@@ -697,7 +697,7 @@ func newTestACLResolver(t *testing.T, delegate ACLResolverDelegate, cb func(*ACL
 	config.ACLDownPolicy = "extend-cache"
 	rconf := &ACLResolverConfig{
 		Config: config,
-		Logger: testutil.LoggerWithName(t, t.Name()),
+		Logger: testutil.Logger(t),
 		CacheConfig: &structs.ACLCachesConfig{
 			Identities:     4,
 			Policies:       4,

agent/consul/client_test.go

@@ -48,7 +48,7 @@ func testClientConfig(t *testing.T) (string, *Config) {
 	config.SerfLANConfig.MemberlistConfig.ProbeTimeout = 200 * time.Millisecond
 	config.SerfLANConfig.MemberlistConfig.ProbeInterval = time.Second
 	config.SerfLANConfig.MemberlistConfig.GossipInterval = 100 * time.Millisecond
-	config.LogOutput = testutil.TestWriter(t)
+	config.LogOutput = testutil.NewLogBuffer(t)
 
 	return dir, config
 }

agent/consul/leader_test.go

@@ -1284,7 +1284,7 @@ func TestLeader_ConfigEntryBootstrap_Fail(t *testing.T) {
 	}()
 
 	dir1, s1 := testServerWithConfig(t, func(c *Config) {
-		c.LogOutput = io.MultiWriter(pw, testutil.TestWriter(t))
+		c.LogOutput = io.MultiWriter(pw, testutil.NewLogBuffer(t))
 		c.Build = "1.6.0"
 		c.ConfigEntryBootstrap = []structs.ConfigEntry{
 			&structs.ServiceSplitterConfigEntry{

agent/consul/server_test.go

@@ -146,7 +146,7 @@ func testServerConfig(t *testing.T) (string, *Config) {
 	config.Bootstrap = true
 	config.Datacenter = "dc1"
 	config.DataDir = dir
-	config.LogOutput = testutil.TestWriter(t)
+	config.LogOutput = testutil.NewLogBuffer(t)
 
 	// bind the rpc server to a random port. config.RPCAdvertise will be
 	// set to the listen address unless it was set in the configuration.

agent/testagent.go

@@ -20,6 +20,7 @@ import (
 	"time"
 
 	metrics "github.com/armon/go-metrics"
+	"github.com/hashicorp/consul/sdk/testutil"
 	"github.com/hashicorp/errwrap"
 	"github.com/hashicorp/go-hclog"
 	uuid "github.com/hashicorp/go-uuid"
@@ -186,7 +187,7 @@ func (a *TestAgent) Start(t *testing.T) (err error) {
 
 	logOutput := a.LogOutput
 	if logOutput == nil {
-		logOutput = os.Stderr
+		logOutput = testutil.NewLogBuffer(t)
 	}
 
 	logger := hclog.NewInterceptLogger(&hclog.LoggerOptions{

api/api_test.go

@@ -62,7 +62,7 @@ func makeClientWithConfig(
 	retry.RunWith(retry.ThreeTimes(), t, func(r *retry.R) {
 		server, err = testutil.NewTestServerConfigT(t, cb2)
 		if err != nil {
-			r.Fatal(err)
+			r.Fatalf("Failed to start server: %v", err.Error())
 		}
 	})
 	if server.Config.Bootstrap {

sdk/testutil/README.md

@@ -27,7 +27,7 @@ import (
 
 func TestFoo_bar(t *testing.T) {
 	// Create a test Consul server
-	srv1, err := testutil.NewTestServerT(t)
+	srv1, err := testutil.NewTestServerConfigT(t, nil)
 	if err != nil {
 		t.Fatal(err)
 	}

sdk/testutil/server.go

@@ -101,7 +101,8 @@ type TestServerConfig struct {
 	Connect             map[string]interface{} `json:"connect,omitempty"`
 	EnableDebug         bool                   `json:"enable_debug,omitempty"`
 	ReadyTimeout        time.Duration          `json:"-"`
-	Stdout, Stderr      io.Writer              `json:"-"`
+	Stdout              io.Writer              `json:"-"`
+	Stderr              io.Writer              `json:"-"`
 	Args                []string               `json:"-"`
 	ReturnPorts         func()                 `json:"-"`
 }
@@ -132,13 +133,14 @@ type ServerConfigCallback func(c *TestServerConfig)
 
 // defaultServerConfig returns a new TestServerConfig struct
 // with all of the listen ports incremented by one.
-func defaultServerConfig() *TestServerConfig {
+func defaultServerConfig(t CleanupT) *TestServerConfig {
 	nodeID, err := uuid.GenerateUUID()
 	if err != nil {
 		panic(err)
 	}
 
 	ports := freeport.MustTake(6)
+	logBuffer := NewLogBuffer(t)
 
 	return &TestServerConfig{
 		NodeName:          "node-" + nodeID,
@@ -171,6 +173,8 @@ func defaultServerConfig() *TestServerConfig {
 		ReturnPorts: func() {
 			freeport.Return(ports)
 		},
+		Stdout: logBuffer,
+		Stderr: logBuffer,
 	}
 }
 
@@ -211,34 +215,11 @@ type TestServer struct {
 	tmpdir string
 }
 
-// Deprecated: Use NewTestServerT instead.
-func NewTestServer() (*TestServer, error) {
-	return NewTestServerConfigT(nil, nil)
-}
-
-// NewTestServerT is an easy helper method to create a new Consul
-// test server with the most basic configuration.
-func NewTestServerT(t *testing.T) (*TestServer, error) {
-	if t == nil {
-		return nil, errors.New("testutil: a non-nil *testing.T is required")
-	}
-	return NewTestServerConfigT(t, nil)
-}
-
-func NewTestServerConfig(cb ServerConfigCallback) (*TestServer, error) {
-	return NewTestServerConfigT(nil, cb)
-}
-
 // NewTestServerConfig creates a new TestServer, and makes a call to an optional
 // callback function to modify the configuration. If there is an error
 // configuring or starting the server, the server will NOT be running when the
 // function returns (thus you do not need to stop it).
 func NewTestServerConfigT(t testing.TB, cb ServerConfigCallback) (*TestServer, error) {
-	return newTestServerConfigT(t, cb)
-}
-
-// newTestServerConfigT is the internal helper for NewTestServerConfigT.
-func newTestServerConfigT(t testing.TB, cb ServerConfigCallback) (*TestServer, error) {
 	path, err := exec.LookPath("consul")
 	if err != nil || path == "" {
 		return nil, fmt.Errorf("consul not found on $PATH - download and install " +
@@ -255,11 +236,7 @@ func newTestServerConfigT(t testing.TB, cb ServerConfigCallback) (*TestServer, e
 		return nil, errors.Wrap(err, "failed to create tempdir")
 	}
 
-	cfg := defaultServerConfig()
-	testWriter := TestWriter(t)
-	cfg.Stdout = testWriter
-	cfg.Stderr = testWriter
-
+	cfg := defaultServerConfig(t)
 	cfg.DataDir = filepath.Join(tmpdir, "data")
 	if cb != nil {
 		cb(cfg)
@@ -272,32 +249,20 @@ func newTestServerConfigT(t testing.TB, cb ServerConfigCallback) (*TestServer, e
 		return nil, errors.Wrap(err, "failed marshaling json")
 	}
 
-	if t != nil {
-		// if you really want this output ensure to pass a valid t
-		t.Logf("CONFIG JSON: %s", string(b))
-	}
+	t.Logf("CONFIG JSON: %s", string(b))
 	configFile := filepath.Join(tmpdir, "config.json")
 	if err := ioutil.WriteFile(configFile, b, 0644); err != nil {
 		cfg.ReturnPorts()
 		os.RemoveAll(tmpdir)
 		return nil, errors.Wrap(err, "failed writing config content")
 	}
 
-	stdout := testWriter
-	if cfg.Stdout != nil {
-		stdout = cfg.Stdout
-	}
-	stderr := testWriter
-	if cfg.Stderr != nil {
-		stderr = cfg.Stderr
-	}
-
 	// Start the server
 	args := []string{"agent", "-config-file", configFile}
 	args = append(args, cfg.Args...)
 	cmd := exec.Command("consul", args...)
-	cmd.Stdout = stdout
-	cmd.Stderr = stderr
+	cmd.Stdout = cfg.Stdout
+	cmd.Stderr = cfg.Stderr
 	if err := cmd.Start(); err != nil {
 		cfg.ReturnPorts()
 		os.RemoveAll(tmpdir)
@@ -331,7 +296,9 @@ func newTestServerConfigT(t testing.TB, cb ServerConfigCallback) (*TestServer, e
 
 	// Wait for the server to be ready
 	if err := server.waitForAPI(); err != nil {
-		server.Stop()
+		if err := server.Stop(); err != nil {
+			t.Logf("server stop failed with: %v", err)
+		}
 		return nil, err
 	}
 

sdk/testutil/testlog.go

@@ -1,37 +1,17 @@
 package testutil
 
 import (
-	"fmt"
+	"bytes"
 	"io"
-	"io/ioutil"
-	"log"
 	"os"
-	"strings"
+	"sync"
 	"testing"
 
 	"github.com/hashicorp/go-hclog"
 )
 
-var sendTestLogsToStdout bool
-
-func init() {
-	sendTestLogsToStdout = os.Getenv("NOLOGBUFFER") == "1"
-}
-
-// Deprecated: use Logger(t)
-func TestLogger(t testing.TB) *log.Logger {
-	return log.New(&testWriter{t}, t.Name()+": ", log.LstdFlags)
-}
-
-func NewDiscardLogger() hclog.Logger {
-	return hclog.New(&hclog.LoggerOptions{
-		Level:  0,
-		Output: ioutil.Discard,
-	})
-}
-
 func Logger(t testing.TB) hclog.InterceptLogger {
-	return LoggerWithOutput(t, &testWriter{t})
+	return LoggerWithOutput(t, NewLogBuffer(t))
 }
 
 func LoggerWithOutput(t testing.TB, output io.Writer) hclog.InterceptLogger {
@@ -42,48 +22,41 @@ func LoggerWithOutput(t testing.TB, output io.Writer) hclog.InterceptLogger {
 	})
 }
 
-// Deprecated: use LoggerWithName(t)
-func TestLoggerWithName(t testing.TB, name string) *log.Logger {
-	return log.New(&testWriter{t}, "test["+name+"]: ", log.LstdFlags)
-}
+var sendTestLogsToStdout = os.Getenv("NOLOGBUFFER") == "1"
 
-func LoggerWithName(t testing.TB, name string) hclog.InterceptLogger {
-	return hclog.NewInterceptLogger(&hclog.LoggerOptions{
-		Name:   "test[" + name + "]",
-		Level:  hclog.Debug,
-		Output: &testWriter{t},
+// NewLogBuffer returns an io.Writer which buffers all writes. When the test
+// ends, t.Failed is checked. If the test has failed all log output is printed
+// to stdout.
+//
+// Set the env var NOLOGBUFFER=1 to disable buffering, resulting in all log
+// output being written immediately to stdout.
+func NewLogBuffer(t CleanupT) io.Writer {
+	if sendTestLogsToStdout {
+		return os.Stdout
+	}
+	buf := &logBuffer{buf: new(bytes.Buffer)}
+	t.Cleanup(func() {
+		if t.Failed() {
+			buf.Lock()
+			defer buf.Unlock()
+			buf.buf.WriteTo(os.Stdout)
+		}
 	})
+	return buf
 }
 
-func TestWriter(t testing.TB) io.Writer {
-	return &testWriter{t}
+type CleanupT interface {
+	Cleanup(f func())
+	Failed() bool
 }
 
-type testWriter struct {
-	t testing.TB
+type logBuffer struct {
+	buf *bytes.Buffer
+	sync.Mutex
 }
 
-func (tw *testWriter) Write(p []byte) (n int, err error) {
-	if tw.t != nil {
-		tw.t.Helper()
-	}
-	if sendTestLogsToStdout || tw.t == nil {
-		fmt.Fprint(os.Stdout, strings.TrimSpace(string(p))+"\n")
-	} else {
-		defer func() {
-			if r := recover(); r != nil {
-				if sr, ok := r.(string); ok {
-					if strings.HasPrefix(sr, "Log in goroutine after ") {
-						// These sorts of panics are undesirable, but requires
-						// total control over goroutine lifetimes to correct.
-						fmt.Fprint(os.Stdout, "SUPPRESSED PANIC: "+sr+"\n")
-						return
-					}
-				}
-				panic(r)
-			}
-		}()
-		tw.t.Log(strings.TrimSpace(string(p)))
-	}
-	return len(p), nil
+func (lb *logBuffer) Write(p []byte) (n int, err error) {
+	lb.Lock()
+	defer lb.Unlock()
+	return lb.buf.Write(p)
 }