WIP2 logging done somewhat

This commit is contained in:
Christian Schwarz
2018-08-10 17:06:00 +02:00
parent 74445a0017
commit c1f3076eb3
14 changed files with 573 additions and 397 deletions
+4
View File
@@ -41,6 +41,10 @@ func FilesystemVersionFromZFS(fsv zfs.FilesystemVersion) *FilesystemVersion {
}
}
func (v *FilesystemVersion) CreationAsTime() (time.Time, error) {
return time.Parse(time.RFC3339, v.Creation)
}
func (v *FilesystemVersion) ZFSFilesystemVersion() *zfs.FilesystemVersion {
ct := time.Time{}
if v.Creation != "" {
+299 -179
View File
@@ -2,18 +2,20 @@ package replication
import (
"context"
"io"
"container/list"
"fmt"
"github.com/zrepl/zrepl/logger"
"io"
"net"
"sort"
"time"
)
type ReplicationEndpoint interface {
// Does not include placeholder filesystems
ListFilesystems(ctx context.Context) ([]*Filesystem, error)
ListFilesystemVersions(ctx context.Context, fs string) ([]*FilesystemVersion, error) // fix depS
Sender
Receiver
Send(ctx context.Context, r *SendReq) (*SendRes, io.ReadCloser, error)
Receive(ctx context.Context, r *ReceiveReq, sendStream io.ReadCloser) error
}
type FilteredError struct{ fs string }
@@ -73,62 +75,175 @@ func (p EndpointPair) Mode() ReplicationMode {
type contextKey int
const (
ContextKeyLog contextKey = iota
contextKeyLog contextKey = iota
)
type Logger interface{
Printf(fmt string, args ... interface{})
//type Logger interface {
// Infof(fmt string, args ...interface{})
// Errorf(fmt string, args ...interface{})
//}
//var _ Logger = nullLogger{}
//type nullLogger struct{}
//
//func (nullLogger) Infof(fmt string, args ...interface{}) {}
//func (nullLogger) Errorf(fmt string, args ...interface{}) {}
type Logger = logger.Logger
func ContextWithLogger(ctx context.Context, l Logger) context.Context {
return context.WithValue(ctx, contextKeyLog, l)
}
type replicationWork struct {
fs *Filesystem
}
type FilesystemReplicationResult struct {
Done bool
Retry bool
Unfixable bool
}
func handleGenericEndpointError(err error) FilesystemReplicationResult {
if _, ok := err.(net.Error); ok {
return FilesystemReplicationResult{Retry: true}
func getLogger(ctx context.Context) Logger {
l, ok := ctx.Value(contextKeyLog).(Logger)
if !ok {
l = logger.NewNullLogger()
}
return FilesystemReplicationResult{Unfixable: true}
return l
}
func driveFSReplication(ctx context.Context, ws *list.List, allTriedOnce chan struct{}, log Logger, f func(w *replicationWork) FilesystemReplicationResult) {
initialLen, fCalls := ws.Len(), 0
for ws.Len() > 0 {
type replicationStep struct {
from, to *FilesystemVersion
fswork *replicateFSWork
}
func (s *replicationStep) String() string {
if s.from == nil { // FIXME: ZFS semantics are that to is nil on non-incremental send
return fmt.Sprintf("%s%s (full)", s.fswork.fs.Path, s.to.RelName())
} else {
return fmt.Sprintf("%s(%s => %s)", s.fswork.fs.Path, s.from.RelName(), s.to.RelName())
}
}
func newReplicationStep(from, to *FilesystemVersion) *replicationStep {
return &replicationStep{from: from, to: to}
}
type replicateFSWork struct {
fs *Filesystem
steps []*replicationStep
currentStep int
errorCount int
}
func newReplicateFSWork(fs *Filesystem) *replicateFSWork {
if fs == nil {
panic("implementation error")
}
return &replicateFSWork{
fs: fs,
steps: make([]*replicationStep, 0),
}
}
func newReplicateFSWorkWithConflict(fs *Filesystem, conflict error) *replicateFSWork {
// FIXME ignore conflict for now, but will be useful later when we make the replicationPlan exportable
return &replicateFSWork{
fs: fs,
steps: make([]*replicationStep, 0),
}
}
func (r *replicateFSWork) AddStep(step *replicationStep) {
if step == nil {
panic("implementation error")
}
if step.fswork != nil {
panic("implementation error")
}
step.fswork = r
r.steps = append(r.steps, step)
}
func (w *replicateFSWork) CurrentStepDate() time.Time {
if len(w.steps) == 0 {
return time.Time{}
}
toTime, err := w.steps[w.currentStep].to.CreationAsTime()
if err != nil {
panic(err) // implementation inconsistent: should not admit invalid FilesystemVersion objects
}
return toTime
}
func (w *replicateFSWork) CurrentStep() *replicationStep {
if w.currentStep >= len(w.steps) {
return nil
}
return w.steps[w.currentStep]
}
func (w *replicateFSWork) CompleteStep() {
w.currentStep++
}
type replicationPlan struct {
fsws []*replicateFSWork
}
func newReplicationPlan() *replicationPlan {
return &replicationPlan{
fsws: make([]*replicateFSWork, 0),
}
}
func (p *replicationPlan) addWork(work *replicateFSWork) {
p.fsws = append(p.fsws, work)
}
func (p *replicationPlan) executeOldestFirst(ctx context.Context, doStep func(fs *Filesystem, from, to *FilesystemVersion) tryRes) {
log := getLogger(ctx)
for {
select {
case <-ctx.Done():
log.Printf("aborting replication due to context error: %s", ctx.Err())
log.WithError(ctx.Err()).Info("aborting replication due to context error")
return
default:
}
w := ws.Remove(ws.Front()).(*replicationWork)
res := f(w)
fCalls++
if fCalls == initialLen {
select {
case allTriedOnce <- struct{}{}:
default:
// FIXME poor man's nested priority queue
pending := make([]*replicateFSWork, 0, len(p.fsws))
for _, fsw := range p.fsws {
if fsw.CurrentStep() != nil {
pending = append(pending, fsw)
}
}
if res.Done {
log.Printf("finished replication of %s", w.fs.Path)
continue
sort.Slice(pending, func(i, j int) bool {
if pending[i].errorCount == pending[j].errorCount {
return pending[i].CurrentStepDate().Before(pending[j].CurrentStepDate())
}
return pending[i].errorCount < pending[j].errorCount
})
// pending is now sorted ascending by errorCount,CurrentStep().Creation
if len(pending) == 0 {
log.Info("replication complete")
return
}
if res.Unfixable {
log.Printf("aborting replication of %s after unfixable error", w.fs.Path)
continue
fsw := pending[0]
step := fsw.CurrentStep()
if step == nil {
panic("implementation error")
}
log.WithField("step", step).Info("begin replication step")
res := doStep(step.fswork.fs, step.from, step.to)
if res.done {
log.Info("replication step successful")
fsw.errorCount = 0
fsw.CompleteStep()
} else {
log.Error("replication step failed, queuing for retry result")
fsw.errorCount++
}
log.Printf("queuing replication of %s for retry", w.fs.Path)
ws.PushBack(w)
}
}
func resolveConflict(conflict error) (path []*FilesystemVersion, msg string) {
@@ -137,7 +252,7 @@ func resolveConflict(conflict error) (path []*FilesystemVersion, msg string) {
// FIXME hard-coded replication policy: most recent
// snapshot as source
var mostRecentSnap *FilesystemVersion
for n := len(noCommonAncestor.SortedSenderVersions) -1; n >= 0; n-- {
for n := len(noCommonAncestor.SortedSenderVersions) - 1; n >= 0; n-- {
if noCommonAncestor.SortedSenderVersions[n].Type == FilesystemVersion_Snapshot {
mostRecentSnap = noCommonAncestor.SortedSenderVersions[n]
break
@@ -146,7 +261,7 @@ func resolveConflict(conflict error) (path []*FilesystemVersion, msg string) {
if mostRecentSnap == nil {
return nil, "no snapshots available on sender side"
}
return []*FilesystemVersion{mostRecentSnap}, fmt.Sprintf("start replication at most recent snapshot %s", mostRecentSnap)
return []*FilesystemVersion{mostRecentSnap}, fmt.Sprintf("start replication at most recent snapshot %s", mostRecentSnap.RelName())
}
}
return nil, "no automated way to handle conflict type"
@@ -160,43 +275,144 @@ func resolveConflict(conflict error) (path []*FilesystemVersion, msg string) {
// If an error occurs when replicating a filesystem, that error is logged to the logger in ctx.
// Replicate continues with the replication of the remaining file systems.
// Depending on the type of error, failed replications are retried in an unspecified order (currently FIFO).
func Replicate(ctx context.Context, ep EndpointPair, ipr IncrementalPathReplicator, allTriedOnce chan struct{}) {
func Replicate(ctx context.Context, ep EndpointPair) {
log := ctx.Value(ContextKeyLog).(Logger)
log := getLogger(ctx)
retryPlanTicker := time.NewTicker(15 * time.Second) // FIXME make configurable
defer retryPlanTicker.Stop()
var (
plan *replicationPlan
res tryRes
)
for {
log.Info("build replication plan")
plan, res = tryBuildReplicationPlan(ctx, ep)
if plan != nil {
break
}
log.WithField("result", res).Error("building replication plan failed, wait for retry timer result")
select {
case <-ctx.Done():
log.WithError(ctx.Err()).Info("aborting replication because context is done")
return
case <-retryPlanTicker.C:
// TODO also accept an external channel that allows us to tick
}
}
retryPlanTicker.Stop()
mainlog := log
plan.executeOldestFirst(ctx, func(fs *Filesystem, from, to *FilesystemVersion) tryRes {
log := mainlog.WithField("filesystem", fs.Path)
// FIXME refresh fs resume token
fs.ResumeToken = ""
var sr *SendReq
if fs.ResumeToken != "" {
sr = &SendReq{
Filesystem: fs.Path,
ResumeToken: fs.ResumeToken,
}
} else if from == nil {
sr = &SendReq{
Filesystem: fs.Path,
From: to.RelName(), // FIXME fix protocol to use To, like zfs does internally
}
} else {
sr = &SendReq{
Filesystem: fs.Path,
From: from.RelName(),
To: to.RelName(),
}
}
log.WithField("request", sr).Debug("initiate send request")
sres, sstream, err := ep.Sender().Send(ctx, sr)
if err != nil {
log.WithError(err).Error("send request failed")
return tryResFromEndpointError(err)
}
if sstream == nil {
log.Error("send request did not return a stream, broken endpoint implementation")
return tryRes{unfixable: true}
}
rr := &ReceiveReq{
Filesystem: fs.Path,
ClearResumeToken: !sres.UsedResumeToken,
}
log.WithField("request", rr).Debug("initiate receive request")
err = ep.Receiver().Receive(ctx, rr, sstream)
if err != nil {
log.WithError(err).Error("receive request failed (might also be error on sender)")
sstream.Close()
// This failure could be due to
// - an unexpected exit of ZFS on the sending side
// - an unexpected exit of ZFS on the receiving side
// - a connectivity issue
return tryResFromEndpointError(err)
}
log.Info("receive finished")
return tryRes{done: true}
})
}
type tryRes struct {
done bool
retry bool
unfixable bool
}
func tryResFromEndpointError(err error) tryRes {
if _, ok := err.(net.Error); ok {
return tryRes{retry: true}
}
return tryRes{unfixable: true}
}
func tryBuildReplicationPlan(ctx context.Context, ep EndpointPair) (*replicationPlan, tryRes) {
log := getLogger(ctx)
early := func(err error) (*replicationPlan, tryRes) {
return nil, tryResFromEndpointError(err)
}
sfss, err := ep.Sender().ListFilesystems(ctx)
if err != nil {
log.Printf("error listing sender filesystems: %s", err)
return
log.WithError(err).Error("error listing sender filesystems")
return early(err)
}
rfss, err := ep.Receiver().ListFilesystems(ctx)
if err != nil {
log.Printf("error listing receiver filesystems: %s", err)
return
log.WithError(err).Error("error listing receiver filesystems")
return early(err)
}
wq := list.New()
plan := newReplicationPlan()
mainlog := log
for _, fs := range sfss {
wq.PushBack(&replicationWork{
fs: fs,
})
}
driveFSReplication(ctx, wq, allTriedOnce, log, func(w *replicationWork) FilesystemReplicationResult {
fs := w.fs
log := mainlog.WithField("filesystem", fs.Path)
log.Printf("replicating %s", fs.Path)
log.Info("assessing filesystem")
sfsvs, err := ep.Sender().ListFilesystemVersions(ctx, fs.Path)
if err != nil {
log.Printf("cannot get remote filesystem versions: %s", err)
return handleGenericEndpointError(err)
log.WithError(err).Error("cannot get remote filesystem versions")
return early(err)
}
if len(sfsvs) <= 1 {
log.Printf("sender does not have any versions")
return FilesystemReplicationResult{Unfixable: true}
log.Error("sender does not have any versions")
return nil, tryRes{unfixable: true}
}
receiverFSExists := false
@@ -211,11 +427,11 @@ func Replicate(ctx context.Context, ep EndpointPair, ipr IncrementalPathReplicat
rfsvs, err = ep.Receiver().ListFilesystemVersions(ctx, fs.Path)
if err != nil {
if _, ok := err.(FilteredError); ok {
log.Printf("receiver does not map %s", fs.Path)
return FilesystemReplicationResult{Done: true}
log.Info("receiver ignores filesystem")
continue
}
log.Printf("receiver error %s", err)
return handleGenericEndpointError(err)
log.WithError(err).Error("receiver error")
return early(err)
}
} else {
rfsvs = []*FilesystemVersion{}
@@ -223,130 +439,34 @@ func Replicate(ctx context.Context, ep EndpointPair, ipr IncrementalPathReplicat
path, conflict := IncrementalPath(rfsvs, sfsvs)
if conflict != nil {
log.Printf("conflict: %s", conflict)
var msg string
path, msg = resolveConflict(conflict)
path, msg = resolveConflict(conflict) // no shadowing allowed!
if path != nil {
log.Printf("conflict resolved: %s", msg)
log.WithField("conflict", conflict).Info("conflict")
log.WithField("resolution", msg).Info("automatically resolved")
} else {
log.Printf("%s", msg)
log.WithField("conflict", conflict).Error("conflict")
log.WithField("problem", msg).Error("cannot resolve conflict")
}
}
if path == nil {
return FilesystemReplicationResult{Unfixable: true}
plan.addWork(newReplicateFSWorkWithConflict(fs, conflict))
continue
}
return ipr.Replicate(ctx, ep.Sender(), ep.Receiver(), NewCopier(), fs, path)
w := newReplicateFSWork(fs)
if len(path) == 1 {
step := newReplicationStep(nil, path[0])
w.AddStep(step)
} else {
for i := 0; i < len(path)-1; i++ {
step := newReplicationStep(path[i], path[i+1])
w.AddStep(step)
}
}
plan.addWork(w)
})
}
type Sender interface {
Send(ctx context.Context, r *SendReq) (*SendRes, io.ReadCloser, error)
}
type Receiver interface {
Receive(ctx context.Context, r *ReceiveReq, sendStream io.ReadCloser) (error)
}
type Copier interface {
Copy(writer io.Writer, reader io.Reader) (int64, error)
}
type copier struct{}
func (copier) Copy(writer io.Writer, reader io.Reader) (int64, error) {
return io.Copy(writer, reader)
}
func NewCopier() Copier {
return copier{}
}
type IncrementalPathReplicator interface {
Replicate(ctx context.Context, sender Sender, receiver Receiver, copier Copier, fs *Filesystem, path []*FilesystemVersion) FilesystemReplicationResult
}
type incrementalPathReplicator struct{}
func NewIncrementalPathReplicator() IncrementalPathReplicator {
return incrementalPathReplicator{}
}
func (incrementalPathReplicator) Replicate(ctx context.Context, sender Sender, receiver Receiver, copier Copier, fs *Filesystem, path []*FilesystemVersion) FilesystemReplicationResult {
log := ctx.Value(ContextKeyLog).(Logger)
if len(path) == 0 {
log.Printf("nothing to do")
return FilesystemReplicationResult{Done: true}
}
if len(path) == 1 {
log.Printf("full send of version %s", path[0])
sr := &SendReq{
Filesystem: fs.Path,
From: path[0].RelName(),
ResumeToken: fs.ResumeToken,
}
sres, sstream, err := sender.Send(ctx, sr)
if err != nil {
log.Printf("send request failed: %s", err)
return handleGenericEndpointError(err)
}
rr := &ReceiveReq{
Filesystem: fs.Path,
ClearResumeToken: fs.ResumeToken != "" && !sres.UsedResumeToken,
}
err = receiver.Receive(ctx, rr, sstream)
if err != nil {
log.Printf("receive request failed (might also be error on sender): %s", err)
sstream.Close()
// This failure could be due to
// - an unexpected exit of ZFS on the sending side
// - an unexpected exit of ZFS on the receiving side
// - a connectivity issue
return handleGenericEndpointError(err)
}
return FilesystemReplicationResult{Done: true}
}
usedResumeToken := false
for j := 0; j < len(path)-1; j++ {
rt := ""
if !usedResumeToken { // only send resume token for first increment
rt = fs.ResumeToken
usedResumeToken = true
}
sr := &SendReq{
Filesystem: fs.Path,
From: path[j].RelName(),
To: path[j+1].RelName(),
ResumeToken: rt,
}
sres, sstream, err := sender.Send(ctx, sr)
if err != nil {
log.Printf("send request failed: %s", err)
return handleGenericEndpointError(err)
}
// try to consume stream
rr := &ReceiveReq{
Filesystem: fs.Path,
ClearResumeToken: rt != "" && !sres.UsedResumeToken,
}
err = receiver.Receive(ctx, rr, sstream)
if err != nil {
log.Printf("receive request failed: %s", err)
return handleGenericEndpointError(err) // FIXME resume state on receiver -> update ResumeToken
}
// FIXME handle properties from sres
}
return FilesystemReplicationResult{Done: true}
return plan, tryRes{done: true}
}
+119 -119
View File
@@ -51,131 +51,131 @@ func (m *MockIncrementalPathRecorder) Finished() bool {
return m.Pos == len(m.Sequence)
}
type DiscardCopier struct{}
func (DiscardCopier) Copy(writer io.Writer, reader io.Reader) (int64, error) {
return 0, nil
}
type IncrementalPathReplicatorTest struct {
Msg string
Filesystem *replication.Filesystem
Path []*replication.FilesystemVersion
Steps []IncrementalPathSequenceStep
}
func (test *IncrementalPathReplicatorTest) Test(t *testing.T) {
t.Log(test.Msg)
rec := &MockIncrementalPathRecorder{
T: t,
Sequence: test.Steps,
}
ctx := context.WithValue(context.Background(), replication.ContextKeyLog, testLog{t})
ipr := replication.NewIncrementalPathReplicator()
ipr.Replicate(
ctx,
rec,
rec,
DiscardCopier{},
test.Filesystem,
test.Path,
)
assert.True(t, rec.Finished())
}
//type IncrementalPathReplicatorTest struct {
// Msg string
// Filesystem *replication.Filesystem
// Path []*replication.FilesystemVersion
// Steps []IncrementalPathSequenceStep
//}
//
//func (test *IncrementalPathReplicatorTest) Test(t *testing.T) {
//
// t.Log(test.Msg)
//
// rec := &MockIncrementalPathRecorder{
// T: t,
// Sequence: test.Steps,
// }
//
// ctx := replication.ContextWithLogger(context.Background(), testLog{t})
//
// ipr := replication.NewIncrementalPathReplicator()
// ipr.Replicate(
// ctx,
// rec,
// rec,
// DiscardCopier{},
// test.Filesystem,
// test.Path,
// )
//
// assert.True(t, rec.Finished())
//
//}
type testLog struct {
t *testing.T
}
func (t testLog) Printf(fmt string, args ...interface{}) {
var _ replication.Logger = testLog{}
func (t testLog) Infof(fmt string, args ...interface{}) {
t.t.Logf(fmt, args)
}
func (t testLog) Errorf(fmt string, args ...interface{}) {
t.t.Logf(fmt, args)
}
func TestIncrementalPathReplicator_Replicate(t *testing.T) {
tbl := []IncrementalPathReplicatorTest{
{
Msg: "generic happy place with resume token",
Filesystem: &replication.Filesystem{
Path: "foo/bar",
ResumeToken: "blafoo",
},
Path: fsvlist("@a,1", "@b,2", "@c,3"),
Steps: []IncrementalPathSequenceStep{
{
SendRequest: &replication.SendReq{
Filesystem: "foo/bar",
From: "@a,1",
To: "@b,2",
ResumeToken: "blafoo",
},
SendResponse: &replication.SendRes{
UsedResumeToken: true,
},
},
{
ReceiveRequest: &replication.ReceiveReq{
Filesystem: "foo/bar",
ClearResumeToken: false,
},
},
{
SendRequest: &replication.SendReq{
Filesystem: "foo/bar",
From: "@b,2",
To: "@c,3",
},
},
{
ReceiveRequest: &replication.ReceiveReq{
Filesystem: "foo/bar",
},
},
},
},
{
Msg: "no action on empty sequence",
Filesystem: &replication.Filesystem{
Path: "foo/bar",
},
Path: fsvlist(),
Steps: []IncrementalPathSequenceStep{},
},
{
Msg: "full send on single entry path",
Filesystem: &replication.Filesystem{
Path: "foo/bar",
},
Path: fsvlist("@justone,1"),
Steps: []IncrementalPathSequenceStep{
{
SendRequest: &replication.SendReq{
Filesystem: "foo/bar",
From: "@justone,1",
To: "", // empty means full send
},
SendResponse: &replication.SendRes{
UsedResumeToken: false,
},
},
{
ReceiveRequest: &replication.ReceiveReq{
Filesystem: "foo/bar",
ClearResumeToken: false,
},
},
},
},
}
for _, test := range tbl {
test.Test(t)
}
}
//func TestIncrementalPathReplicator_Replicate(t *testing.T) {
//
// tbl := []IncrementalPathReplicatorTest{
// {
// Msg: "generic happy place with resume token",
// Filesystem: &replication.Filesystem{
// Path: "foo/bar",
// ResumeToken: "blafoo",
// },
// Path: fsvlist("@a,1", "@b,2", "@c,3"),
// Steps: []IncrementalPathSequenceStep{
// {
// SendRequest: &replication.SendReq{
// Filesystem: "foo/bar",
// From: "@a,1",
// To: "@b,2",
// ResumeToken: "blafoo",
// },
// SendResponse: &replication.SendRes{
// UsedResumeToken: true,
// },
// },
// {
// ReceiveRequest: &replication.ReceiveReq{
// Filesystem: "foo/bar",
// ClearResumeToken: false,
// },
// },
// {
// SendRequest: &replication.SendReq{
// Filesystem: "foo/bar",
// From: "@b,2",
// To: "@c,3",
// },
// },
// {
// ReceiveRequest: &replication.ReceiveReq{
// Filesystem: "foo/bar",
// },
// },
// },
// },
// {
// Msg: "no action on empty sequence",
// Filesystem: &replication.Filesystem{
// Path: "foo/bar",
// },
// Path: fsvlist(),
// Steps: []IncrementalPathSequenceStep{},
// },
// {
// Msg: "full send on single entry path",
// Filesystem: &replication.Filesystem{
// Path: "foo/bar",
// },
// Path: fsvlist("@justone,1"),
// Steps: []IncrementalPathSequenceStep{
// {
// SendRequest: &replication.SendReq{
// Filesystem: "foo/bar",
// From: "@justone,1",
// To: "", // empty means full send
// },
// SendResponse: &replication.SendRes{
// UsedResumeToken: false,
// },
// },
// {
// ReceiveRequest: &replication.ReceiveReq{
// Filesystem: "foo/bar",
// ClearResumeToken: false,
// },
// },
// },
// },
// }
//
// for _, test := range tbl {
// test.Test(t)
// }
//
//}