testing: Improve logging from TestAgent

agent/agent.go

@@ -166,7 +166,13 @@ type Agent struct {
 	// Used for writing our logs
 	logger hclog.InterceptLogger
 
-	// Output sink for logs
+	// LogOutput is a Writer which is used when creating dependencies that
+	// require logging. Note that this LogOutput is not used by the agent logger,
+	// so setting this field does not result in the agent logs being written to
+	// LogOutput.
+	// FIXME: refactor so that: dependencies accept an hclog.Logger,
+	// or LogOutput is part of RuntimeConfig, or change Agent.logger to be
+	// a new type with an Out() io.Writer method which returns this value.
 	LogOutput io.Writer
 
 	// In-memory sink used for collecting metrics

agent/agent_test.go

@@ -138,12 +138,8 @@ func TestAgent_ConnectClusterIDConfig(t *testing.T) {
 
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			// This is a rare case where using a constructor for TestAgent
-			// (NewTestAgent and the likes) won't work, since we expect an error
-			// in one test case, and the constructors have built-in retry logic
-			// that runs automatically upon error.
-			a := &TestAgent{Name: tt.name, HCL: tt.hcl, LogOutput: testutil.TestWriter(t)}
-			err := a.Start()
+			a := NewTestAgentWithFields(t, false, TestAgent{HCL: tt.hcl})
+			err := a.Start(t)
 			if tt.wantErr {
 				if err == nil {
 					t.Fatal("expected error, got nil")
@@ -1777,7 +1773,6 @@ func TestAgent_HTTPCheck_EnableAgentTLSForChecks(t *testing.T) {
 
 	run := func(t *testing.T, ca string) {
 		a := NewTestAgentWithFields(t, true, TestAgent{
-			Name:   t.Name(),
 			UseTLS: true,
 			HCL: `
 				enable_agent_tls_for_checks = true
@@ -2134,7 +2129,7 @@ func testAgent_PurgeServiceOnDuplicate(t *testing.T, extraHCL string) {
 
 	// Try bringing the agent back up with the service already
 	// existing in the config
-	a2 := NewTestAgentWithFields(t, true, TestAgent{Name: t.Name() + "-a2", HCL: cfg + `
+	a2 := NewTestAgentWithFields(t, true, TestAgent{Name: "Agent2", HCL: cfg + `
 		service = {
 			id = "redis"
 			name = "redis"
@@ -2219,7 +2214,7 @@ func TestAgent_PersistCheck(t *testing.T) {
 	a.Shutdown()
 
 	// Should load it back during later start
-	a2 := NewTestAgentWithFields(t, true, TestAgent{Name: t.Name() + "-a2", HCL: cfg, DataDir: dataDir})
+	a2 := NewTestAgentWithFields(t, true, TestAgent{Name: "Agent2", HCL: cfg, DataDir: dataDir})
 	defer a2.Shutdown()
 
 	result := requireCheckExists(t, a2, check.CheckID)
@@ -2272,7 +2267,6 @@ func TestAgent_PurgeCheckOnDuplicate(t *testing.T) {
 	nodeID := NodeID()
 	dataDir := testutil.TempDir(t, "agent")
 	a := NewTestAgentWithFields(t, true, TestAgent{
-		Name:    t.Name(),
 		DataDir: dataDir,
 		HCL: `
 	    node_id = "` + nodeID + `"
@@ -2301,7 +2295,7 @@ func TestAgent_PurgeCheckOnDuplicate(t *testing.T) {
 
 	// Start again with the check registered in config
 	a2 := NewTestAgentWithFields(t, true, TestAgent{
-		Name:    t.Name() + "-a2",
+		Name:    "Agent2",
 		DataDir: dataDir,
 		HCL: `
 	    node_id = "` + nodeID + `"
@@ -3227,8 +3221,8 @@ func TestAgent_reloadWatches(t *testing.T) {
 
 func TestAgent_reloadWatchesHTTPS(t *testing.T) {
 	t.Parallel()
-	a := TestAgent{Name: t.Name(), UseTLS: true}
-	if err := a.Start(); err != nil {
+	a := TestAgent{UseTLS: true}
+	if err := a.Start(t); err != nil {
 		t.Fatal(err)
 	}
 	defer a.Shutdown()

agent/local/state_test.go

@@ -1159,12 +1159,12 @@ func TestAgentAntiEntropy_RemovingServiceAndCheck(t *testing.T) {
 func TestAgentAntiEntropy_Checks_ACLDeny(t *testing.T) {
 	t.Parallel()
 	dc := "dc1"
-	a := &agent.TestAgent{Name: t.Name(), HCL: `
+	a := &agent.TestAgent{HCL: `
 		acl_datacenter = "` + dc + `"
 		acl_master_token = "root"
 		acl_default_policy = "deny"
 		acl_enforce_version_8 = true`}
-	if err := a.Start(); err != nil {
+	if err := a.Start(t); err != nil {
 		t.Fatal(err)
 	}
 	defer a.Shutdown()
@@ -1429,10 +1429,10 @@ func TestAgent_UpdateCheck_DiscardOutput(t *testing.T) {
 
 func TestAgentAntiEntropy_Check_DeferSync(t *testing.T) {
 	t.Parallel()
-	a := &agent.TestAgent{Name: t.Name(), HCL: `
+	a := &agent.TestAgent{HCL: `
 		check_update_interval = "500ms"
 	`}
-	if err := a.Start(); err != nil {
+	if err := a.Start(t); err != nil {
 		t.Fatal(err)
 	}
 	defer a.Shutdown()
@@ -1637,12 +1637,12 @@ func TestAgentAntiEntropy_NodeInfo(t *testing.T) {
 	nodeMeta := map[string]string{
 		"somekey": "somevalue",
 	}
-	a := &agent.TestAgent{Name: t.Name(), HCL: `
+	a := &agent.TestAgent{HCL: `
 		node_id = "40e4a748-2192-161a-0510-9bf59fe950b5"
 		node_meta {
 			somekey = "somevalue"
 		}`}
-	if err := a.Start(); err != nil {
+	if err := a.Start(t); err != nil {
 		t.Fatal(err)
 	}
 	defer a.Shutdown()

agent/testagent.go

@@ -16,6 +16,7 @@ import (
 	"time"
 
 	metrics "github.com/armon/go-metrics"
+	"github.com/hashicorp/errwrap"
 	"github.com/hashicorp/go-hclog"
 	uuid "github.com/hashicorp/go-uuid"
 
@@ -25,7 +26,6 @@ import (
 	"github.com/hashicorp/consul/agent/structs"
 	"github.com/hashicorp/consul/api"
 	"github.com/hashicorp/consul/sdk/freeport"
-	"github.com/hashicorp/consul/sdk/testutil"
 	"github.com/hashicorp/consul/sdk/testutil/retry"
 )
 
@@ -101,18 +101,12 @@ func NewTestAgent(t *testing.T, name string, hcl string) *TestAgent {
 func NewTestAgentWithFields(t *testing.T, start bool, ta TestAgent) *TestAgent {
 	// copy values
 	a := ta
-	if a.Name == "" {
-		a.Name = t.Name()
-	}
-	if a.LogOutput == nil {
-		a.LogOutput = testutil.TestWriter(t)
-	}
 	if !start {
-		return nil
+		return &a
 	}
 
 	retry.RunWith(retry.ThreeTimes(), t, func(r *retry.R) {
-		if err := a.Start(); err != nil {
+		if err := a.Start(t); err != nil {
 			r.Fatal(err)
 		}
 	})
@@ -122,32 +116,45 @@ func NewTestAgentWithFields(t *testing.T, start bool, ta TestAgent) *TestAgent {
 
 // Start starts a test agent. It returns an error if the agent could not be started.
 // If no error is returned, the caller must call Shutdown() when finished.
-func (a *TestAgent) Start() (err error) {
+func (a *TestAgent) Start(t *testing.T) (err error) {
 	if a.Agent != nil {
 		return fmt.Errorf("TestAgent already started")
 	}
 
+	name := a.Name
+	// Many tests set Name to t.Name(), which takes up a lot of space at the
+	// start of the log messages. The only time we need to care about a name is
+	// when a test using multiple TestAgents.
+	// As a temporary workaround we ignore the default name and use a shorter
+	// default value. Tests which set a custom name for multiple agents will
+	// use the provided name.
+	// TODO: remove TestAgent.Name and accept a name arg on Start, to remove
+	// this workaround.
+	if name == "" || name == t.Name() {
+		name = "TestAgent"
+	}
+
 	var cleanupTmpDir = func() {
 		// Clean out the data dir if we are responsible for it before we
 		// try again, since the old ports may have gotten written to
 		// the data dir, such as in the Raft configuration.
 		if a.DataDir != "" {
 			if err := os.RemoveAll(a.DataDir); err != nil {
-				fmt.Printf("%s Error resetting data dir: %s", a.Name, err)
+				fmt.Printf("%s Error resetting data dir: %s", name, err)
 			}
 		}
 	}
 
 	var hclDataDir string
 	if a.DataDir == "" {
-		name := "agent"
-		if a.Name != "" {
-			name = a.Name + "-agent"
+		dirname := "agent"
+		if name != "" {
+			dirname = name + "-agent"
 		}
-		name = strings.Replace(name, "/", "_", -1)
-		d, err := ioutil.TempDir(TempDir, name)
+		dirname = strings.Replace(dirname, "/", "_", -1)
+		d, err := ioutil.TempDir(TempDir, dirname)
 		if err != nil {
-			return fmt.Errorf("Error creating data dir %s: %s", filepath.Join(TempDir, name), err)
+			return fmt.Errorf("Error creating data dir %s: %s", filepath.Join(TempDir, dirname), err)
 		}
 		// Convert windows style path to posix style path
 		// to avoid illegal char escape error when hcl
@@ -162,17 +169,18 @@ func (a *TestAgent) Start() (err error) {
 	}
 
 	logger := hclog.NewInterceptLogger(&hclog.LoggerOptions{
-		Name:   a.Name,
-		Level:  hclog.Debug,
-		Output: logOutput,
+		Level:      hclog.Debug,
+		Output:     logOutput,
+		TimeFormat: "04:05.000",
+		Name:       name,
 	})
 
 	portsConfig, returnPortsFn := randomPortsSource(a.UseTLS)
 	a.returnPortsFn = returnPortsFn
 	a.Config = TestConfig(logger,
 		portsConfig,
-		config.Source{Name: a.Name, Format: "hcl", Data: a.HCL},
-		config.Source{Name: a.Name + ".data_dir", Format: "hcl", Data: hclDataDir},
+		config.Source{Name: name, Format: "hcl", Data: a.HCL},
+		config.Source{Name: name + ".data_dir", Format: "hcl", Data: hclDataDir},
 	)
 
 	defer func() {
@@ -218,7 +226,7 @@ func (a *TestAgent) Start() (err error) {
 		agent.ShutdownAgent()
 		agent.ShutdownEndpoints()
 
-		return fmt.Errorf("%s %s Error starting agent: %s", id, a.Name, err)
+		return fmt.Errorf("%s %s Error starting agent: %s", id, name, err)
 	}
 
 	a.Agent = agent
@@ -229,7 +237,7 @@ func (a *TestAgent) Start() (err error) {
 	if err := a.waitForUp(); err != nil {
 		cleanupTmpDir()
 		a.Shutdown()
-		return err
+		return errwrap.Wrapf(name+": {{err}}", err)
 	}
 
 	a.dns = a.dnsServers[0]
@@ -247,7 +255,7 @@ func (a *TestAgent) waitForUp() error {
 	var out structs.IndexedNodes
 	for ; !time.Now().After(deadline); time.Sleep(timer.Wait) {
 		if len(a.httpServers) == 0 {
-			retErr = fmt.Errorf("%s: waiting for server", a.Name)
+			retErr = fmt.Errorf("waiting for server")
 			continue // fail, try again
 		}
 		if a.Config.Bootstrap && a.Config.ServerMode {
@@ -264,11 +272,11 @@ func (a *TestAgent) waitForUp() error {
 				continue // fail, try again
 			}
 			if !out.QueryMeta.KnownLeader {
-				retErr = fmt.Errorf("%s: No leader", a.Name)
+				retErr = fmt.Errorf("No leader")
 				continue // fail, try again
 			}
 			if out.Index == 0 {
-				retErr = fmt.Errorf("%s: Consul index is 0", a.Name)
+				retErr = fmt.Errorf("Consul index is 0")
 				continue // fail, try again
 			}
 			return nil // success
@@ -277,7 +285,7 @@ func (a *TestAgent) waitForUp() error {
 			resp := httptest.NewRecorder()
 			_, err := a.httpServers[0].AgentSelf(resp, req)
 			if err != nil || resp.Code != 200 {
-				retErr = fmt.Errorf("%s: failed OK response: %v", a.Name, err)
+				retErr = fmt.Errorf("failed OK response: %v", err)
 				continue
 			}
 			return nil // success

command/agent/agent.go

@@ -3,7 +3,6 @@ package agent
 import (
 	"flag"
 	"fmt"
-	"io"
 	"os"
 	"os/signal"
 	"path/filepath"
@@ -59,7 +58,6 @@ type cmd struct {
 	versionHuman      string
 	shutdownCh        <-chan struct{}
 	flagArgs          config.Flags
-	logOutput         io.Writer
 	logger            hclog.InterceptLogger
 }
 
@@ -205,7 +203,6 @@ func (c *cmd) run(args []string) int {
 	if !ok {
 		return 1
 	}
-	c.logOutput = logOutput
 
 	c.logger = logger
 

command/connect/proxy/proxy.go

@@ -3,7 +3,6 @@ package proxy
 import (
 	"flag"
 	"fmt"
-	"io"
 	"log"
 	"net"
 	"net/http"
@@ -43,8 +42,7 @@ type cmd struct {
 
 	shutdownCh <-chan struct{}
 
-	logOutput io.Writer
-	logger    hclog.Logger
+	logger hclog.Logger
 
 	// flags
 	logLevel    string
@@ -138,12 +136,10 @@ func (c *cmd) Run(args []string) int {
 		Name:     logging.Proxy,
 		LogJSON:  c.logJSON,
 	}
-	logger, logGate, logOutput, ok := logging.Setup(logConfig, c.UI)
+	logger, logGate, _, ok := logging.Setup(logConfig, c.UI)
 	if !ok {
 		return 1
 	}
-	c.logOutput = logOutput
-
 	c.logger = logger
 
 	// Enable Pprof if needed

go.mod

@@ -30,6 +30,7 @@ require (
 	github.com/google/tcpproxy v0.0.0-20180808230851-dfa16c61dad2
 	github.com/hashicorp/consul/api v1.4.0
 	github.com/hashicorp/consul/sdk v0.4.0
+	github.com/hashicorp/errwrap v1.0.0
 	github.com/hashicorp/go-bexpr v0.1.2
 	github.com/hashicorp/go-checkpoint v0.0.0-20171009173528-1545e56e46de
 	github.com/hashicorp/go-cleanhttp v0.5.1