Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Replaced logging with hclog throughout raft. #360

Merged
merged 3 commits into from
Aug 9, 2019
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 9 additions & 8 deletions api.go
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
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
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