Allow users to configure either unstructured or JSON logging (hashicorp#7130)

* hclog Allow users to choose between unstructured and JSON logging

Author: crhino

agent/acl.go

@@ -62,7 +62,7 @@ func (a *Agent) resolveIdentityFromToken(secretID string) (bool, structs.ACLIden
 func (a *Agent) aclAccessorID(secretID string) string {
 	_, ident, err := a.resolveIdentityFromToken(secretID)
 	if err != nil {
-		a.logger.Printf("[DEBUG] agent.acl: %v", err)
+		a.logger.Debug("error", err)
 		return ""
 	}
 	if ident == nil {
@@ -281,7 +281,7 @@ func (a *Agent) filterMembers(token string, members *[]serf.Member) error {
 			continue
 		}
 		accessorID := a.aclAccessorID(token)
-		a.logger.Printf("[DEBUG] agent: dropping node from result due to ACLs, node=%q accessorID=%q", node, accessorID)
+		a.logger.Debug("dropping node from result due to ACLs", "node", node, "accessorID", accessorID)
 		m = append(m[:i], m[i+1:]...)
 		i--
 	}
@@ -311,7 +311,7 @@ func (a *Agent) filterServicesWithAuthorizer(authz acl.Authorizer, services *map
 		if authz.ServiceRead(service.Service, &authzContext) == acl.Allow {
 			continue
 		}
-		a.logger.Printf("[DEBUG] agent: dropping service from result due to ACLs, service=%q", id.String())
+		a.logger.Debug("dropping service from result due to ACLs", "service", id.String())
 		delete(*services, id)
 	}
 	return nil
@@ -347,7 +347,7 @@ func (a *Agent) filterChecksWithAuthorizer(authz acl.Authorizer, checks *map[str
 				continue
 			}
 		}
-		a.logger.Printf("[DEBUG] agent: dropping check from result due to ACLs, check=%q", id.String())
+		a.logger.Debug("dropping check from result due to ACLs", "check", id.String())
 		delete(*checks, id)
 	}
 	return nil

agent/acl_test.go

@@ -3,7 +3,6 @@ package agent
 import (
 	"fmt"
 	"io"
-	"log"
 	"testing"
 	"time"
 
@@ -14,9 +13,9 @@ import (
 	"github.com/hashicorp/consul/agent/local"
 	"github.com/hashicorp/consul/agent/structs"
 	"github.com/hashicorp/consul/lib"
-	"github.com/hashicorp/consul/logger"
 	"github.com/hashicorp/consul/sdk/testutil"
 	"github.com/hashicorp/consul/types"
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/serf/serf"
 
 	"github.com/stretchr/testify/require"
@@ -39,9 +38,6 @@ type TestACLAgent struct {
 	// to os.Stderr.
 	LogOutput io.Writer
 
-	// LogWriter is used for streaming logs.
-	LogWriter *logger.LogWriter
-
 	// DataDir is the data directory which is used when Config.DataDir
 	// is not set. It is created automatically and removed when
 	// Shutdown() is called.
@@ -60,7 +56,11 @@ func NewTestACLAgent(t *testing.T, name string, hcl string, resolveFn func(strin
 	hclDataDir := `data_dir = "acl-agent"`
 
 	logOutput := testutil.TestWriter(t)
-	logger := log.New(logOutput, a.Name+" - ", log.LstdFlags|log.Lmicroseconds)
+	logger := hclog.NewInterceptLogger(&hclog.LoggerOptions{
+		Name:   a.Name,
+		Level:  hclog.Debug,
+		Output: logOutput,
+	})
 
 	a.Config = TestConfig(logger,
 		config.Source{Name: a.Name, Format: "hcl", Data: a.HCL},
@@ -74,7 +74,6 @@ func NewTestACLAgent(t *testing.T, name string, hcl string, resolveFn func(strin
 	a.Agent = agent
 
 	agent.LogOutput = logOutput
-	agent.LogWriter = a.LogWriter
 	agent.logger = logger
 	agent.MemSink = metrics.NewInmemSink(1*time.Second, time.Minute)
 

agent/ae/ae.go

@@ -3,12 +3,12 @@ package ae
 
 import (
 	"fmt"
-	"log"
+	"github.com/hashicorp/consul/lib"
+	"github.com/hashicorp/consul/logging"
+	"github.com/hashicorp/go-hclog"
 	"math"
 	"sync"
 	"time"
-
-	"github.com/hashicorp/consul/lib"
 )
 
 // scaleThreshold is the number of nodes after which regular sync runs are
@@ -60,7 +60,7 @@ type StateSyncer struct {
 	ShutdownCh chan struct{}
 
 	// Logger is the logger.
-	Logger *log.Logger
+	Logger hclog.Logger
 
 	// ClusterSize returns the number of members in the cluster to
 	// allow staggering the sync runs based on cluster size.
@@ -107,12 +107,16 @@ const (
 	retryFailIntv = 15 * time.Second
 )
 
-func NewStateSyncer(state SyncState, intv time.Duration, shutdownCh chan struct{}, logger *log.Logger) *StateSyncer {
+func NewStateSyncer(state SyncState, intv time.Duration, shutdownCh chan struct{}, logger hclog.Logger) *StateSyncer {
+	if logger == nil {
+		logger = hclog.New(&hclog.LoggerOptions{})
+	}
+
 	s := &StateSyncer{
 		State:             state,
 		Interval:          intv,
 		ShutdownCh:        shutdownCh,
-		Logger:            logger,
+		Logger:            logger.Named(logging.AntiEntropy),
 		SyncFull:          NewTrigger(),
 		SyncChanges:       NewTrigger(),
 		serverUpInterval:  serverUpIntv,
@@ -166,7 +170,7 @@ func (s *StateSyncer) nextFSMState(fs fsmState) fsmState {
 
 		err := s.State.SyncFull()
 		if err != nil {
-			s.Logger.Printf("[ERR] agent: failed to sync remote state: %v", err)
+			s.Logger.Error("failed to sync remote state", "error", err)
 			return retryFullSyncState
 		}
 
@@ -196,7 +200,7 @@ func (s *StateSyncer) nextFSMState(fs fsmState) fsmState {
 
 			err := s.State.SyncChanges()
 			if err != nil {
-				s.Logger.Printf("[ERR] agent: failed to sync changes: %v", err)
+				s.Logger.Error("failed to sync changes", "error", err)
 			}
 			return partialSyncState
 

agent/ae/ae_test.go

@@ -3,14 +3,14 @@ package ae
 import (
 	"errors"
 	"fmt"
-	"log"
-	"os"
 	"reflect"
 	"sync"
 	"testing"
 	"time"
 
 	"github.com/hashicorp/consul/lib"
+	"github.com/hashicorp/consul/sdk/testutil"
+	"github.com/hashicorp/go-hclog"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -86,7 +86,7 @@ func TestAE_staggerDependsOnClusterSize(t *testing.T) {
 	libRandomStagger = func(d time.Duration) time.Duration { return d }
 	defer func() { libRandomStagger = lib.RandomStagger }()
 
-	l := testSyncer()
+	l := testSyncer(t)
 	if got, want := l.staggerFn(10*time.Millisecond), 10*time.Millisecond; got != want {
 		t.Fatalf("got %v want %v", got, want)
 	}
@@ -106,7 +106,7 @@ func TestAE_Run_SyncFullBeforeChanges(t *testing.T) {
 	}
 
 	// indicate that we have partial changes before starting Run
-	l := testSyncer()
+	l := testSyncer(t)
 	l.State = state
 	l.ShutdownCh = shutdownCh
 	l.SyncChanges.Trigger()
@@ -132,15 +132,15 @@ func TestAE_Run_Quit(t *testing.T) {
 				t.Fatal("Run should panic")
 			}
 		}()
-		l := testSyncer()
+		l := testSyncer(t)
 		l.ClusterSize = nil
 		l.Run()
 	})
 	t.Run("runFSM quits", func(t *testing.T) {
 		// start timer which explodes if runFSM does not quit
 		tm := time.AfterFunc(time.Second, func() { panic("timeout") })
 
-		l := testSyncer()
+		l := testSyncer(t)
 		l.runFSM(fullSyncState, func(fsmState) fsmState { return doneState })
 		// should just quit
 		tm.Stop()
@@ -150,23 +150,23 @@ func TestAE_Run_Quit(t *testing.T) {
 func TestAE_FSM(t *testing.T) {
 	t.Run("fullSyncState", func(t *testing.T) {
 		t.Run("Paused -> retryFullSyncState", func(t *testing.T) {
-			l := testSyncer()
+			l := testSyncer(t)
 			l.Pause()
 			fs := l.nextFSMState(fullSyncState)
 			if got, want := fs, retryFullSyncState; got != want {
 				t.Fatalf("got state %v want %v", got, want)
 			}
 		})
 		t.Run("SyncFull() error -> retryFullSyncState", func(t *testing.T) {
-			l := testSyncer()
+			l := testSyncer(t)
 			l.State = &mock{syncFull: func() error { return errors.New("boom") }}
 			fs := l.nextFSMState(fullSyncState)
 			if got, want := fs, retryFullSyncState; got != want {
 				t.Fatalf("got state %v want %v", got, want)
 			}
 		})
 		t.Run("SyncFull() OK -> partialSyncState", func(t *testing.T) {
-			l := testSyncer()
+			l := testSyncer(t)
 			l.State = &mock{}
 			fs := l.nextFSMState(fullSyncState)
 			if got, want := fs, partialSyncState; got != want {
@@ -178,7 +178,7 @@ func TestAE_FSM(t *testing.T) {
 	t.Run("retryFullSyncState", func(t *testing.T) {
 		// helper for testing state transitions from retrySyncFullState
 		test := func(ev event, to fsmState) {
-			l := testSyncer()
+			l := testSyncer(t)
 			l.retrySyncFullEvent = func() event { return ev }
 			fs := l.nextFSMState(retryFullSyncState)
 			if got, want := fs, to; got != want {
@@ -208,7 +208,7 @@ func TestAE_FSM(t *testing.T) {
 	t.Run("partialSyncState", func(t *testing.T) {
 		// helper for testing state transitions from partialSyncState
 		test := func(ev event, to fsmState) {
-			l := testSyncer()
+			l := testSyncer(t)
 			l.syncChangesEvent = func() event { return ev }
 			fs := l.nextFSMState(partialSyncState)
 			if got, want := fs, to; got != want {
@@ -225,7 +225,7 @@ func TestAE_FSM(t *testing.T) {
 			test(syncFullTimerEvent, fullSyncState)
 		})
 		t.Run("syncChangesEvent+Paused -> partialSyncState", func(t *testing.T) {
-			l := testSyncer()
+			l := testSyncer(t)
 			l.Pause()
 			l.syncChangesEvent = func() event { return syncChangesNotifEvent }
 			fs := l.nextFSMState(partialSyncState)
@@ -234,7 +234,7 @@ func TestAE_FSM(t *testing.T) {
 			}
 		})
 		t.Run("syncChangesEvent+SyncChanges() error -> partialSyncState", func(t *testing.T) {
-			l := testSyncer()
+			l := testSyncer(t)
 			l.State = &mock{syncChanges: func() error { return errors.New("boom") }}
 			l.syncChangesEvent = func() event { return syncChangesNotifEvent }
 			fs := l.nextFSMState(partialSyncState)
@@ -243,7 +243,7 @@ func TestAE_FSM(t *testing.T) {
 			}
 		})
 		t.Run("syncChangesEvent+SyncChanges() OK -> partialSyncState", func(t *testing.T) {
-			l := testSyncer()
+			l := testSyncer(t)
 			l.State = &mock{}
 			l.syncChangesEvent = func() event { return syncChangesNotifEvent }
 			fs := l.nextFSMState(partialSyncState)
@@ -268,14 +268,14 @@ func TestAE_FSM(t *testing.T) {
 				t.Fatal("invalid state should panic")
 			}
 		}()
-		l := testSyncer()
+		l := testSyncer(t)
 		l.nextFSMState(fsmState("invalid"))
 	})
 }
 
 func TestAE_RetrySyncFullEvent(t *testing.T) {
 	t.Run("trigger shutdownEvent", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		l.ShutdownCh = make(chan struct{})
 		evch := make(chan event)
 		go func() { evch <- l.retrySyncFullEvent() }()
@@ -285,7 +285,7 @@ func TestAE_RetrySyncFullEvent(t *testing.T) {
 		}
 	})
 	t.Run("trigger shutdownEvent during FullNotif", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		l.ShutdownCh = make(chan struct{})
 		evch := make(chan event)
 		go func() { evch <- l.retrySyncFullEvent() }()
@@ -297,7 +297,7 @@ func TestAE_RetrySyncFullEvent(t *testing.T) {
 		}
 	})
 	t.Run("trigger syncFullNotifEvent", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		l.serverUpInterval = 10 * time.Millisecond
 		evch := make(chan event)
 		go func() { evch <- l.retrySyncFullEvent() }()
@@ -307,7 +307,7 @@ func TestAE_RetrySyncFullEvent(t *testing.T) {
 		}
 	})
 	t.Run("trigger syncFullTimerEvent", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		l.retryFailInterval = 10 * time.Millisecond
 		evch := make(chan event)
 		go func() { evch <- l.retrySyncFullEvent() }()
@@ -319,7 +319,7 @@ func TestAE_RetrySyncFullEvent(t *testing.T) {
 
 func TestAE_SyncChangesEvent(t *testing.T) {
 	t.Run("trigger shutdownEvent", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		l.ShutdownCh = make(chan struct{})
 		evch := make(chan event)
 		go func() { evch <- l.syncChangesEvent() }()
@@ -329,7 +329,7 @@ func TestAE_SyncChangesEvent(t *testing.T) {
 		}
 	})
 	t.Run("trigger shutdownEvent during FullNotif", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		l.ShutdownCh = make(chan struct{})
 		evch := make(chan event)
 		go func() { evch <- l.syncChangesEvent() }()
@@ -341,7 +341,7 @@ func TestAE_SyncChangesEvent(t *testing.T) {
 		}
 	})
 	t.Run("trigger syncFullNotifEvent", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		l.serverUpInterval = 10 * time.Millisecond
 		evch := make(chan event)
 		go func() { evch <- l.syncChangesEvent() }()
@@ -351,7 +351,7 @@ func TestAE_SyncChangesEvent(t *testing.T) {
 		}
 	})
 	t.Run("trigger syncFullTimerEvent", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		l.Interval = 10 * time.Millisecond
 		evch := make(chan event)
 		go func() { evch <- l.syncChangesEvent() }()
@@ -360,7 +360,7 @@ func TestAE_SyncChangesEvent(t *testing.T) {
 		}
 	})
 	t.Run("trigger syncChangesNotifEvent", func(t *testing.T) {
-		l := testSyncer()
+		l := testSyncer(t)
 		evch := make(chan event)
 		go func() { evch <- l.syncChangesEvent() }()
 		l.SyncChanges.Trigger()
@@ -391,8 +391,12 @@ func (m *mock) SyncChanges() error {
 	return nil
 }
 
-func testSyncer() *StateSyncer {
-	logger := log.New(os.Stderr, "", 0)
+func testSyncer(t *testing.T) *StateSyncer {
+	logger := hclog.New(&hclog.LoggerOptions{
+		Level:  0,
+		Output: testutil.TestWriter(t),
+	})
+
 	l := NewStateSyncer(nil, time.Second, nil, logger)
 	l.stagger = func(d time.Duration) time.Duration { return d }
 	l.ClusterSize = func() int { return 1 }