Skip to content

Commit

Permalink
Replaced logging with hclog throughout raft. (#360)
Browse files Browse the repository at this point in the history 
* Replaced logging with hclog throughout raft.

This simply replaces the existing logging implementation with hclog to
make everything consistent throughout the library.

* Removed fmt.Sprintf and made all logging consistent.

* Cleaned up the last few Sprintfs that I missed.
  • Loading branch information
@elliotcourant @schristoff
elliotcourant authored and schristoff committed Aug 9, 2019
1 parent ff523e1 commit 635796e
Show file tree
Hide file tree
Showing 14 changed files with 423 additions and 369 deletions.
17 changes: 9 additions & 8 deletions api.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -528,13 +528,14 @@ 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.Error(fmt.Sprintf("Failed to get log at %d: %v", index, err))
r.logger.Error("failed to get log", "index", index, "error", err)
panic(err)
}
r.processConfigurationLogEntry(&entry)
}
r.logger.Info(fmt.Sprintf("Initial configuration (index=%d): %+v",
r.configurations.latestIndex, r.configurations.latest.Servers))
r.logger.Info("initial configuration",
"index", r.configurations.latestIndex,
"servers", hclog.Fmt("%+v", r.configurations.latest.Servers))

// Setup a heartbeat fast-path to avoid head-of-line
// blocking where possible. It MUST be safe for this
Expand All @@ -554,7 +555,7 @@ 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.Error(fmt.Sprintf("Failed to list snapshots: %v", err))
r.logger.Error("failed to list snapshots", "error", err)
return err
}

Expand All @@ -563,19 +564,19 @@ func (r *Raft) restoreSnapshot() error {
if !r.conf.NoSnapshotRestoreOnStart {
_, source, err := r.snapshots.Open(snapshot.ID)
if err != nil {
r.logger.Error(fmt.Sprintf("Failed to open snapshot %v: %v", snapshot.ID, err))
r.logger.Error("failed to open snapshot", "id", snapshot.ID, "error", err)
continue
}

err = r.fsm.Restore(source)
// Close the source after the restore has completed
source.Close()
if err != nil {
r.logger.Error(fmt.Sprintf("Failed to restore snapshot %v: %v", snapshot.ID, err))
r.logger.Error("failed to restore snapshot", "id", snapshot.ID, "error", err)
continue
}

r.logger.Info(fmt.Sprintf("Restored from snapshot %v", snapshot.ID))
r.logger.Info("restored from snapshot", "id", snapshot.ID)
}
// Update the lastApplied so we don't replay old logs
r.setLastApplied(snapshot.Index)
Expand Down Expand Up @@ -1013,7 +1014,7 @@ func (r *Raft) Stats() map[string]string {

future := r.GetConfiguration()
if err := future.Error(); err != nil {
r.logger.Warn(fmt.Sprintf("could not get configuration for Stats: %v", err))
r.logger.Warn("could not get configuration for stats", "error", err)
} else {
configuration := future.Configuration()
s["latest_configuration_index"] = toString(future.Index())
Expand Down
71 changes: 39 additions & 32 deletions file_snapshot.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,11 +5,11 @@ import (
"bytes"
"encoding/json"
"fmt"
"github.com/hashicorp/go-hclog"
"hash"
"hash/crc64"
"io"
"io/ioutil"
"log"
"os"
"path/filepath"
"runtime"
Expand All @@ -31,15 +31,15 @@ const (
type FileSnapshotStore struct {
path string
retain int
logger *log.Logger
logger hclog.Logger
}

type snapMetaSlice []*fileSnapshotMeta

// FileSnapshotSink implements SnapshotSink with a file.
type FileSnapshotSink struct {
store *FileSnapshotStore
logger *log.Logger
logger hclog.Logger
dir string
parentDir string
meta fileSnapshotMeta
Expand Down Expand Up @@ -76,12 +76,16 @@ func (b *bufferedFile) Close() error {
// NewFileSnapshotStoreWithLogger creates a new FileSnapshotStore based
// on a base directory. The `retain` parameter controls how many
// snapshots are retained. Must be at least 1.
func NewFileSnapshotStoreWithLogger(base string, retain int, logger *log.Logger) (*FileSnapshotStore, error) {
func NewFileSnapshotStoreWithLogger(base string, retain int, logger hclog.Logger) (*FileSnapshotStore, error) {
if retain < 1 {
return nil, fmt.Errorf("must retain at least one snapshot")
}
if logger == nil {
logger = log.New(os.Stderr, "", log.LstdFlags)
logger = hclog.New(&hclog.LoggerOptions{
Name: "snapshot",
Output: hclog.DefaultOutput,
Level: hclog.DefaultLevel,
})
}

// Ensure our path exists
Expand Down Expand Up @@ -111,7 +115,11 @@ func NewFileSnapshotStore(base string, retain int, logOutput io.Writer) (*FileSn
if logOutput == nil {
logOutput = os.Stderr
}
return NewFileSnapshotStoreWithLogger(base, retain, log.New(logOutput, "", log.LstdFlags))
return NewFileSnapshotStoreWithLogger(base, retain, hclog.New(&hclog.LoggerOptions{
Name: "snapshot",
Output: logOutput,
Level: hclog.DefaultLevel,
}))
}

// testPermissions tries to touch a file in our path to see if it works.
Expand Down Expand Up @@ -150,11 +158,11 @@ func (f *FileSnapshotStore) Create(version SnapshotVersion, index, term uint64,
// Create a new path
name := snapshotName(term, index)
path := filepath.Join(f.path, name+tmpSuffix)
f.logger.Printf("[INFO] snapshot: Creating new snapshot at %s", path)
f.logger.Info("creating new snapshot", "path", path)

// Make the directory
if err := os.MkdirAll(path, 0755); err != nil {
f.logger.Printf("[ERR] snapshot: Failed to make snapshot directory: %v", err)
f.logger.Error("failed to make snapshot directly", "error", err)
return nil, err
}

Expand All @@ -180,15 +188,15 @@ func (f *FileSnapshotStore) Create(version SnapshotVersion, index, term uint64,

// Write out the meta data
if err := sink.writeMeta(); err != nil {
f.logger.Printf("[ERR] snapshot: Failed to write metadata: %v", err)
f.logger.Error("failed to write metadata", "error", err)
return nil, err
}

// Open the state file
statePath := filepath.Join(path, stateFilePath)
fh, err := os.Create(statePath)
if err != nil {
f.logger.Printf("[ERR] snapshot: Failed to create state file: %v", err)
f.logger.Error("failed to create state file", "error", err)
return nil, err
}
sink.stateFile = fh
Expand All @@ -209,7 +217,7 @@ func (f *FileSnapshotStore) List() ([]*SnapshotMeta, error) {
// Get the eligible snapshots
snapshots, err := f.getSnapshots()
if err != nil {
f.logger.Printf("[ERR] snapshot: Failed to get snapshots: %v", err)
f.logger.Error("failed to get snapshots", "error", err)
return nil, err
}

Expand All @@ -228,7 +236,7 @@ func (f *FileSnapshotStore) getSnapshots() ([]*fileSnapshotMeta, error) {
// Get the eligible snapshots
snapshots, err := ioutil.ReadDir(f.path)
if err != nil {
f.logger.Printf("[ERR] snapshot: Failed to scan snapshot dir: %v", err)
f.logger.Error("failed to scan snapshot directory", "error", err)
return nil, err
}

Expand All @@ -243,20 +251,20 @@ func (f *FileSnapshotStore) getSnapshots() ([]*fileSnapshotMeta, error) {
// Ignore any temporary snapshots
dirName := snap.Name()
if strings.HasSuffix(dirName, tmpSuffix) {
f.logger.Printf("[WARN] snapshot: Found temporary snapshot: %v", dirName)
f.logger.Warn("found temporary snapshot", "name", dirName)
continue
}

// Try to read the meta data
meta, err := f.readMeta(dirName)
if err != nil {
f.logger.Printf("[WARN] snapshot: Failed to read metadata for %v: %v", dirName, err)
f.logger.Warn("failed to read metadata", "name", dirName, "error", err)
continue
}

// Make sure we can understand this version.
if meta.Version < SnapshotVersionMin || meta.Version > SnapshotVersionMax {
f.logger.Printf("[WARN] snapshot: Snapshot version for %v not supported: %d", dirName, meta.Version)
f.logger.Warn("snapshot version not supported", "name", dirName, "version", meta.Version)
continue
}

Expand Down Expand Up @@ -297,15 +305,15 @@ func (f *FileSnapshotStore) Open(id string) (*SnapshotMeta, io.ReadCloser, error
// Get the metadata
meta, err := f.readMeta(id)
if err != nil {
f.logger.Printf("[ERR] snapshot: Failed to get meta data to open snapshot: %v", err)
f.logger.Error("failed to get meta data to open snapshot", "error", err)
return nil, nil, err
}

// Open the state file
statePath := filepath.Join(f.path, id, stateFilePath)
fh, err := os.Open(statePath)
if err != nil {
f.logger.Printf("[ERR] snapshot: Failed to open state file: %v", err)
f.logger.Error("failed to open state file", "error", err)
return nil, nil, err
}

Expand All @@ -315,23 +323,22 @@ func (f *FileSnapshotStore) Open(id string) (*SnapshotMeta, io.ReadCloser, error
// Compute the hash
_, err = io.Copy(stateHash, fh)
if err != nil {
f.logger.Printf("[ERR] snapshot: Failed to read state file: %v", err)
f.logger.Error("failed to read state file", "error", err)
fh.Close()
return nil, nil, err
}

// Verify the hash
computed := stateHash.Sum(nil)
if bytes.Compare(meta.CRC, computed) != 0 {
f.logger.Printf("[ERR] snapshot: CRC checksum failed (stored: %v computed: %v)",
meta.CRC, computed)
f.logger.Error("CRC checksum failed", "stored", meta.CRC, "computed", computed)
fh.Close()
return nil, nil, fmt.Errorf("CRC mismatch")
}

// Seek to the start
if _, err := fh.Seek(0, 0); err != nil {
f.logger.Printf("[ERR] snapshot: State file seek failed: %v", err)
f.logger.Error("state file seek failed", "error", err)
fh.Close()
return nil, nil, err
}
Expand All @@ -349,15 +356,15 @@ func (f *FileSnapshotStore) Open(id string) (*SnapshotMeta, io.ReadCloser, error
func (f *FileSnapshotStore) ReapSnapshots() error {
snapshots, err := f.getSnapshots()
if err != nil {
f.logger.Printf("[ERR] snapshot: Failed to get snapshots: %v", err)
f.logger.Error("failed to get snapshots", "error", err)
return err
}

for i := f.retain; i < len(snapshots); i++ {
path := filepath.Join(f.path, snapshots[i].ID)
f.logger.Printf("[INFO] snapshot: reaping snapshot %v", path)
f.logger.Info("reaping snapshot", "path", path)
if err := os.RemoveAll(path); err != nil {
f.logger.Printf("[ERR] snapshot: Failed to reap snapshot %v: %v", path, err)
f.logger.Error("failed to reap snapshot", "path", path, "error", err)
return err
}
}
Expand Down Expand Up @@ -386,37 +393,37 @@ func (s *FileSnapshotSink) Close() error {

// Close the open handles
if err := s.finalize(); err != nil {
s.logger.Printf("[ERR] snapshot: Failed to finalize snapshot: %v", err)
s.logger.Error("failed to finalize snapshot", "error", err)
if delErr := os.RemoveAll(s.dir); delErr != nil {
s.logger.Printf("[ERR] snapshot: Failed to delete temporary snapshot directory at path %v: %v", s.dir, delErr)
s.logger.Error("failed to delete temporary snapshot directory", "path", s.dir, "error", delErr)
return delErr
}
return err
}

// Write out the meta data
if err := s.writeMeta(); err != nil {
s.logger.Printf("[ERR] snapshot: Failed to write metadata: %v", err)
s.logger.Error("failed to write metadata", "error", err)
return err
}

// Move the directory into place
newPath := strings.TrimSuffix(s.dir, tmpSuffix)
if err := os.Rename(s.dir, newPath); err != nil {
s.logger.Printf("[ERR] snapshot: Failed to move snapshot into place: %v", err)
s.logger.Error("failed to move snapshot into place", "error", err)
return err
}

if runtime.GOOS != "windows" { //skipping fsync for directory entry edits on Windows, only needed for *nix style file systems
if runtime.GOOS != "windows" { // skipping fsync for directory entry edits on Windows, only needed for *nix style file systems
parentFH, err := os.Open(s.parentDir)
defer parentFH.Close()
if err != nil {
s.logger.Printf("[ERR] snapshot: Failed to open snapshot parent directory %v, error: %v", s.parentDir, err)
s.logger.Error("failed to open snapshot parent directory", "path", s.parentDir, "error", err)
return err
}

if err = parentFH.Sync(); err != nil {
s.logger.Printf("[ERR] snapshot: Failed syncing parent directory %v, error: %v", s.parentDir, err)
s.logger.Error("failed syncing parent directory", "path", s.parentDir, "error", err)
return err
}
}
Expand All @@ -439,7 +446,7 @@ func (s *FileSnapshotSink) Cancel() error {

// Close the open handles
if err := s.finalize(); err != nil {
s.logger.Printf("[ERR] snapshot: Failed to finalize snapshot: %v", err)
s.logger.Error("failed to finalize snapshot", "error", err)
return err
}

Expand Down
26 changes: 19 additions & 7 deletions fuzzy/cluster.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,9 +3,9 @@ package fuzzy
import (
"bytes"
"fmt"
"github.com/hashicorp/go-hclog"
"io"
"io/ioutil"
"log"
"os"
"path/filepath"
"testing"
Expand Down Expand Up @@ -38,17 +38,17 @@ type Logger interface {

// LoggerAdapter allows a log.Logger to be used with the local Logger interface
type LoggerAdapter struct {
log *log.Logger
log hclog.Logger
}

// Log a message to the contained debug log
func (a *LoggerAdapter) Log(v ...interface{}) {
a.log.Print(v...)
a.log.Info(fmt.Sprint(v...))
}

// Logf will record a formatted message to the contained debug log
func (a *LoggerAdapter) Logf(s string, v ...interface{}) {
a.log.Printf(s, v...)
a.log.Info(fmt.Sprintf(s, v...))
}

func newRaftCluster(t *testing.T, logWriter io.Writer, namePrefix string, n uint, transportHooks TransportHooks) *cluster {
Expand All @@ -57,10 +57,18 @@ func newRaftCluster(t *testing.T, logWriter io.Writer, namePrefix string, n uint
for i := uint(0); i < n; i++ {
names = append(names, nodeName(namePrefix, i))
}
l := log.New(logWriter, "", log.Lmicroseconds)
l := hclog.New(&hclog.LoggerOptions{
Output: logWriter,
Level: hclog.DefaultLevel,
})
transports := newTransports(l)
for _, i := range names {
r, err := newRaftNode(log.New(logWriter, i+":", log.Lmicroseconds), transports, transportHooks, names, i)

r, err := newRaftNode(hclog.New(&hclog.LoggerOptions{
Name: i + ":",
Output: logWriter,
Level: hclog.DefaultLevel,
}), transports, transportHooks, names, i)
if err != nil {
t.Fatalf("Unable to create raftNode:%v : %v", i, err)
}
Expand All @@ -78,7 +86,11 @@ func newRaftCluster(t *testing.T, logWriter io.Writer, namePrefix string, n uint

func (c *cluster) CreateAndAddNode(t *testing.T, logWriter io.Writer, namePrefix string, nodeNum uint) error {
name := nodeName(namePrefix, nodeNum)
rn, err := newRaftNode(log.New(logWriter, name+":", log.Lmicroseconds), c.transports, c.hooks, nil, name)
rn, err := newRaftNode(hclog.New(&hclog.LoggerOptions{
Name: name + ":",
Output: logWriter,
Level: hclog.DefaultLevel,
}), c.transports, c.hooks, nil, name)
if err != nil {
t.Fatalf("Unable to create raftNode:%v : %v", name, err)
}
Expand Down
Loading

0 comments on commit 635796e

Please sign in to comment.