From 51efba2c7d5e9378324cc48d5f95048ecc43a428 Mon Sep 17 00:00:00 2001 From: Daniel Nephin Date: Wed, 6 May 2020 16:40:16 -0400 Subject: [PATCH] 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 --- agent/acl_test.go | 2 +- agent/ae/ae_test.go | 2 +- agent/checks/check.go | 4 +- agent/consul/acl_test.go | 2 +- agent/consul/client_test.go | 2 +- agent/consul/leader_test.go | 2 +- agent/consul/server_test.go | 2 +- agent/testagent.go | 3 +- api/api_test.go | 2 +- sdk/testutil/README.md | 2 +- sdk/testutil/server.go | 59 ++++++------------------ sdk/testutil/testlog.go | 91 +++++++++++++------------------------ 12 files changed, 57 insertions(+), 116 deletions(-) diff --git a/agent/acl_test.go b/agent/acl_test.go index 9ae579600a..f8bfdb3d17 100644 --- a/agent/acl_test.go +++ b/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, diff --git a/agent/ae/ae_test.go b/agent/ae/ae_test.go index 55d983e752..e26f50b1c1 100644 --- a/agent/ae/ae_test.go +++ b/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) diff --git a/agent/checks/check.go b/agent/checks/check.go index a75ee912d6..c1d3bd280b 100644 --- a/agent/checks/check.go +++ b/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" @@ -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 == "" { diff --git a/agent/consul/acl_test.go b/agent/consul/acl_test.go index c99694cd9a..8e47e0032e 100644 --- a/agent/consul/acl_test.go +++ b/agent/consul/acl_test.go @@ -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, diff --git a/agent/consul/client_test.go b/agent/consul/client_test.go index 62c8264922..9adbb17fa4 100644 --- a/agent/consul/client_test.go +++ b/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 } diff --git a/agent/consul/leader_test.go b/agent/consul/leader_test.go index 508509868d..365e50ec25 100644 --- a/agent/consul/leader_test.go +++ b/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{ diff --git a/agent/consul/server_test.go b/agent/consul/server_test.go index 9033a0bf39..99632a499c 100644 --- a/agent/consul/server_test.go +++ b/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. diff --git a/agent/testagent.go b/agent/testagent.go index 3ddcc2de6f..1704e3a075 100644 --- a/agent/testagent.go +++ b/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{ diff --git a/api/api_test.go b/api/api_test.go index f9bf4915fc..39ae0e4c2c 100644 --- a/api/api_test.go +++ b/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 { diff --git a/sdk/testutil/README.md b/sdk/testutil/README.md index 641e7f44ad..dfd57ceb8b 100644 --- a/sdk/testutil/README.md +++ b/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) } diff --git a/sdk/testutil/server.go b/sdk/testutil/server.go index c3dc9e9f55..bf990795e9 100644 --- a/sdk/testutil/server.go +++ b/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,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 } diff --git a/sdk/testutil/testlog.go b/sdk/testutil/testlog.go index 154c1fc56e..a16396cb81 100644 --- a/sdk/testutil/testlog.go +++ b/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) }