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

Merge pull request #7546 from hashicorp/dnephin/logging-in-tests 

testing: Improve logging from TestAgent
This commit is contained in:
Daniel Nephin 2020-03-31 11:08:39 -04:00 committed by GitHub
parent e4a00b39bf 96c4a35de7
commit 35e716cfc2
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
7 changed files with 59 additions and 57 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
agent/agent.go
View File

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

20
agent/agent_test.go
View File

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

12
agent/local/state_test.go
View File

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

64
agent/testagent.go
View File

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

3
command/agent/agent.go
View File

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

8
command/connect/proxy/proxy.go
View File

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

1
go.mod
View File

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