luxolus
/
open-consul
2
0
Fork 0
Code Issues 1 Pull Requests Packages Releases Wiki Activity

testutil: NewLogBuffer - buffer logs until a test fails 

Replaces #7559

Running tests in parallel, with background goroutines, results in test output not being associated with the correct test. `go test` does not make any guarantees about output from goroutines being attributed to the correct test case.

Attaching log output from background goroutines also cause data races.  If the goroutine outlives the test, it will race with the test being marked done. Previously this was noticed as a panic when logging, but with the race detector enabled it is shown as a data race.

The previous solution did not address the problem of correct test attribution because test output could still be hidden when it was associated with a test that did not fail. You would have to look at all of the log output to find the relevant lines. It also made debugging test failures more difficult because each log line was very long.

This commit attempts a new approach. Instead of printing all the logs, only print when a test fails. This should work well when there are a small number of failures, but may not work well when there are many test failures at the same time. In those cases the failures are unlikely a result of a specific test, and the log output is likely less useful.

All of the logs are printed from the test goroutine, so they should be associated with the correct test.

Also removes some test helpers that were not used, or only had a single caller. Packages which expose many functions with similar names can be difficult to use correctly.

Related:
https://github.com/golang/go/issues/38458 (may be fixed in go1.15)
https://github.com/golang/go/issues/38382#issuecomment-612940030
This commit is contained in:
Daniel Nephin 2020-05-06 16:40:16 -04:00
parent 308815b6bd
commit 80ff174880
12 changed files with 57 additions and 116 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
agent/acl_test.go
View File

@ -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,

2
agent/ae/ae_test.go
View File

@ -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)

4
agent/checks/check.go
View File

@ -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"
@ -613,7 +613,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 == "" {

2
agent/consul/acl_test.go
View File

@ -697,7 +697,7 @@ func newTestACLResolver(t *testing.T, delegate *ACLResolverTestDelegate, cb func
config.ACLsEnabled = delegate.enabled
rconf := &ACLResolverConfig{
Config: config,
Logger: testutil.LoggerWithName(t, t.Name()),
Logger: testutil.Logger(t),
CacheConfig: &structs.ACLCachesConfig{
Identities: 4,
Policies: 4,

2
agent/consul/client_test.go
View File

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

2
agent/consul/leader_test.go
View File

@ -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{

2
agent/consul/server_test.go
View File

@ -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.

3
agent/testagent.go
View File

@ -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{

2
api/api_test.go
View File

@ -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 {

2
sdk/testutil/README.md
View File

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

59
sdk/testutil/server.go
View File

@ -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,10 +249,7 @@ 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()
@ -283,21 +257,12 @@ func newTestServerConfigT(t testing.TB, cb ServerConfigCallback) (*TestServer, e
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
}

91
sdk/testutil/testlog.go
View File

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