Leveled log (hashicorp#321)

Add leveled logging

api.go

@@ -4,12 +4,13 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
 	"os"
 	"strconv"
 	"sync"
 	"time"
 
+	"github.com/hashicorp/go-hclog"
+
 	"github.com/armon/go-metrics"
 )
 
@@ -103,7 +104,7 @@ type Raft struct {
 	localAddr ServerAddress
 
 	// Used for our logging
-	logger *log.Logger
+	logger hclog.Logger
 
 	// LogStore provides durable storage for logs
 	logs LogStore
@@ -394,14 +395,19 @@ func NewRaft(conf *Config, fsm FSM, logs LogStore, stable StableStore, snaps Sna
 	}
 
 	// Ensure we have a LogOutput.
-	var logger *log.Logger
+	var logger hclog.Logger
 	if conf.Logger != nil {
 		logger = conf.Logger
 	} else {
 		if conf.LogOutput == nil {
 			conf.LogOutput = os.Stderr
 		}
-		logger = log.New(conf.LogOutput, "", log.LstdFlags)
+
+		logger = hclog.New(&hclog.LoggerOptions{
+			Name:   "raft",
+			Level:  hclog.LevelFromString(conf.LogLevel),
+			Output: conf.LogOutput,
+		})
 	}
 
 	// Try to restore the current term.
@@ -487,14 +493,13 @@ func NewRaft(conf *Config, fsm FSM, logs LogStore, stable StableStore, snaps Sna
 	for index := snapshotIndex + 1; index <= lastLog.Index; index++ {
 		var entry Log
 		if err := r.logs.GetLog(index, &entry); err != nil {
-			r.logger.Printf("[ERR] raft: Failed to get log at %d: %v", index, err)
+			r.logger.Error(fmt.Sprintf("Failed to get log at %d: %v", index, err))
 			panic(err)
 		}
 		r.processConfigurationLogEntry(&entry)
 	}
-
-	r.logger.Printf("[INFO] raft: Initial configuration (index=%d): %+v",
-		r.configurations.latestIndex, r.configurations.latest.Servers)
+	r.logger.Info(fmt.Sprintf("Initial configuration (index=%d): %+v",
+		r.configurations.latestIndex, r.configurations.latest.Servers))
 
 	// Setup a heartbeat fast-path to avoid head-of-line
 	// blocking where possible. It MUST be safe for this
@@ -514,26 +519,26 @@ func NewRaft(conf *Config, fsm FSM, logs LogStore, stable StableStore, snaps Sna
 func (r *Raft) restoreSnapshot() error {
 	snapshots, err := r.snapshots.List()
 	if err != nil {
-		r.logger.Printf("[ERR] raft: Failed to list snapshots: %v", err)
+		r.logger.Error(fmt.Sprintf("Failed to list snapshots: %v", err))
 		return err
 	}
 
 	// Try to load in order of newest to oldest
 	for _, snapshot := range snapshots {
 		_, source, err := r.snapshots.Open(snapshot.ID)
 		if err != nil {
-			r.logger.Printf("[ERR] raft: Failed to open snapshot %v: %v", snapshot.ID, err)
+			r.logger.Error(fmt.Sprintf("Failed to open snapshot %v: %v", snapshot.ID, err))
 			continue
 		}
 		defer source.Close()
 
 		if err := r.fsm.Restore(source); err != nil {
-			r.logger.Printf("[ERR] raft: Failed to restore snapshot %v: %v", snapshot.ID, err)
+			r.logger.Error(fmt.Sprintf("Failed to restore snapshot %v: %v", snapshot.ID, err))
 			continue
 		}
 
 		// Log success
-		r.logger.Printf("[INFO] raft: Restored from snapshot %v", snapshot.ID)
+		r.logger.Info(fmt.Sprintf("Restored from snapshot %v", snapshot.ID))
 
 		// Update the lastApplied so we don't replay old logs
 		r.setLastApplied(snapshot.Index)
@@ -955,7 +960,7 @@ func (r *Raft) Stats() map[string]string {
 
 	future := r.GetConfiguration()
 	if err := future.Error(); err != nil {
-		r.logger.Printf("[WARN] raft: could not get configuration for Stats: %v", err)
+		r.logger.Warn(fmt.Sprintf("could not get configuration for Stats: %v", err))
 	} else {
 		configuration := future.Configuration()
 		s["latest_configuration_index"] = toString(future.Index())

config.go

@@ -3,8 +3,9 @@ package raft
 import (
 	"fmt"
 	"io"
-	"log"
 	"time"
+
+	"github.com/hashicorp/go-hclog"
 )
 
 // These are the versions of the protocol (which includes RPC messages as
@@ -190,9 +191,13 @@ type Config struct {
 	// Defaults to os.Stderr.
 	LogOutput io.Writer
 
-	// Logger is a user-provided logger. If nil, a logger writing to LogOutput
-	// is used.
-	Logger *log.Logger
+	// LogLevel represents a log level. If a no matching string is specified,
+	// hclog.NoLevel is assumed.
+	LogLevel string
+
+	// Logger is a user-provided hc-log logger. If nil, a logger writing to
+	// LogOutput with LogLevel is used.
+	Logger hclog.Logger
 }
 
 // DefaultConfig returns a Config with usable defaults.
@@ -208,6 +213,7 @@ func DefaultConfig() *Config {
 		SnapshotInterval:   120 * time.Second,
 		SnapshotThreshold:  8192,
 		LeaderLeaseTimeout: 500 * time.Millisecond,
+		LogLevel:           "DEBUG",
 	}
 }
 

integ_test.go

@@ -4,10 +4,11 @@ import (
 	"bytes"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"os"
 	"testing"
 	"time"
+
+	"github.com/hashicorp/go-hclog"
 )
 
 // CheckInteg will skip a test if integration testing is not enabled.
@@ -30,7 +31,7 @@ type RaftEnv struct {
 	snapshot *FileSnapshotStore
 	trans    *NetworkTransport
 	raft     *Raft
-	logger   *log.Logger
+	logger   hclog.Logger
 }
 
 // Release shuts down and cleans up any stored data, its not restartable after this
@@ -42,7 +43,7 @@ func (r *RaftEnv) Release() {
 // Shutdown shuts down raft & transport, but keeps track of its data, its restartable
 // after a Shutdown() by calling Start()
 func (r *RaftEnv) Shutdown() {
-	r.logger.Printf("[WARN] Shutdown node at %v", r.raft.localAddr)
+	r.logger.Warn(fmt.Sprintf("Shutdown node at %v", r.raft.localAddr))
 	f := r.raft.Shutdown()
 	if err := f.Error(); err != nil {
 		panic(err)
@@ -57,7 +58,7 @@ func (r *RaftEnv) Restart(t *testing.T) {
 		t.Fatalf("err: %v", err)
 	}
 	r.trans = trans
-	r.logger.Printf("[INFO] Starting node at %v", trans.LocalAddr())
+	r.logger.Info(fmt.Sprintf("Starting node at %v", trans.LocalAddr()))
 	raft, err := NewRaft(r.conf, r.fsm, r.store, r.store, r.snapshot, r.trans)
 	if err != nil {
 		t.Fatalf("err: %v", err)
@@ -89,13 +90,15 @@ func MakeRaft(t *testing.T, conf *Config, bootstrap bool) *RaftEnv {
 		store:    stable,
 		snapshot: snap,
 		fsm:      &MockFSM{},
-		logger:   log.New(&testLoggerAdapter{t: t}, "", log.Lmicroseconds),
 	}
 	trans, err := NewTCPTransport("127.0.0.1:0", nil, 2, time.Second, nil)
 	if err != nil {
 		t.Fatalf("err: %v", err)
 	}
-	env.logger = log.New(os.Stdout, string(trans.LocalAddr())+" :", log.Lmicroseconds)
+
+	env.logger = hclog.New(&hclog.LoggerOptions{
+		Name: string(trans.LocalAddr()) + " :",
+	})
 	env.trans = trans
 
 	if bootstrap {
@@ -110,7 +113,7 @@ func MakeRaft(t *testing.T, conf *Config, bootstrap bool) *RaftEnv {
 			t.Fatalf("err: %v", err)
 		}
 	}
-	log.Printf("[INFO] Starting node at %v", trans.LocalAddr())
+	env.logger.Info(fmt.Sprintf("Starting node at %v", trans.LocalAddr()))
 	conf.Logger = env.logger
 	raft, err := NewRaft(conf, env.fsm, stable, stable, snap, trans)
 	if err != nil {
@@ -237,7 +240,7 @@ func TestRaft_Integ(t *testing.T) {
 		}
 		for _, f := range futures {
 			NoErr(WaitFuture(f, t), t)
-			leader.logger.Printf("[DEBUG] Applied at %d, size %d", f.Index(), sz)
+			leader.logger.Debug(fmt.Sprintf("Applied at %d, size %d", f.Index(), sz))
 		}
 		totalApplied += n
 	}