add tracing package (forgot to commit)

client/signal.go

@@ -9,7 +9,7 @@ import (
 )
 
 var SignalCmd = &cli.Subcommand{
-	Use:   "signal [wakeup|reset] JOB [DATA]",
+	Use:   "signal [wakeup|reset] JOB",
 	Short: "wake up a job from wait state or abort its current invocation",
 	Run: func(subcommand *cli.Subcommand, args []string) error {
 		return runSignalCmd(subcommand.Config(), args)
@@ -17,13 +17,8 @@ var SignalCmd = &cli.Subcommand{
 }
 
 func runSignalCmd(config *config.Config, args []string) error {
-	if len(args) < 2 || len(args) > 3 {
-		return errors.Errorf("Expected 2 arguments: [wakeup|reset|set-concurrency] JOB [DATA]")
-	}
-
-	var data string
-	if len(args) == 3 {
-		data = args[2]
+	if len(args) != 2 {
+		return errors.Errorf("Expected 2 arguments: [wakeup|reset] JOB")
 	}
 
 	httpc, err := controlHttpClient(config.Global.Control.SockPath)
@@ -35,11 +30,9 @@ func runSignalCmd(config *config.Config, args []string) error {
 		struct {
 			Name string
 			Op   string
-			Data string
 		}{
 			Name: args[1],
 			Op:   args[0],
-			Data: data,
 		},
 		struct{}{},
 	)

daemon/control.go

@@ -8,7 +8,6 @@ import (
 	"io"
 	"net"
 	"net/http"
-	"strconv"
 	"time"
 
 	"github.com/pkg/errors"
@@ -48,8 +47,6 @@ func (j *controlJob) OwnedDatasetSubtreeRoot() (p *zfs.DatasetPath, ok bool) { r
 
 func (j *controlJob) SenderConfig() *endpoint.SenderConfig { return nil }
 
-func (j *controlJob) SetConcurrency(concurrency int) error { return errors.Errorf("not supported") }
-
 var promControl struct {
 	requestBegin    *prometheus.CounterVec
 	requestFinished *prometheus.HistogramVec
@@ -129,7 +126,6 @@ func (j *controlJob) Run(ctx context.Context) {
 			type reqT struct {
 				Name string
 				Op   string
-				Data string
 			}
 			var req reqT
 			if decoder(&req) != nil {
@@ -142,14 +138,6 @@ func (j *controlJob) Run(ctx context.Context) {
 				err = j.jobs.wakeup(req.Name)
 			case "reset":
 				err = j.jobs.reset(req.Name)
-			case "set-concurrency":
-				var concurrency int
-				concurrency, err = strconv.Atoi(req.Data) // shadow
-				if err != nil {
-					// fallthrough outer
-				} else {
-					err = j.jobs.setConcurrency(req.Name, concurrency)
-				}
 			default:
 				err = fmt.Errorf("operation %q is invalid", req.Op)
 			}

daemon/daemon.go

@@ -176,18 +176,6 @@ func (s *jobs) reset(job string) error {
 	return wu()
 }
 
-func (s *jobs) setConcurrency(jobName string, concurrency int) error {
-	s.m.RLock()
-	defer s.m.RUnlock()
-
-	job, ok := s.jobs[jobName]
-	if !ok {
-		return errors.Errorf("Job %q does not exist", job)
-	}
-
-	return job.SetConcurrency(concurrency)
-}
-
 const (
 	jobNamePrometheus = "_prometheus"
 	jobNameControl    = "_control"

daemon/job/active.go

@@ -55,12 +55,9 @@ const (
 type activeSideTasks struct {
 	state ActiveSideState
 
-	concurrency int
-
 	// valid for state ActiveSideReplicating, ActiveSidePruneSender, ActiveSidePruneReceiver, ActiveSideDone
-	replicationReport         driver.ReportFunc
-	replicationCancel         context.CancelFunc
-	replicationSetConcurrency driver.SetConcurrencyFunc
+	replicationReport driver.ReportFunc
+	replicationCancel context.CancelFunc
 
 	// valid for state ActiveSidePruneSender, ActiveSidePruneReceiver, ActiveSideDone
 	prunerSender, prunerReceiver *pruner.Pruner
@@ -281,8 +278,6 @@ func activeSide(g *config.Global, in *config.ActiveJob, configJob interface{}) (
 		return nil, errors.Wrap(err, "invalid job name")
 	}
 
-	j.tasks.concurrency = 1 // FIXME
-
 	switch v := configJob.(type) {
 	case *config.PushJob:
 		j.mode, err = modePushFromConfig(g, v, j.name) // shadow
@@ -380,22 +375,6 @@ func (j *ActiveSide) SenderConfig() *endpoint.SenderConfig {
 	return push.senderConfig
 }
 
-func (j *ActiveSide) SetConcurrency(concurrency int) (err error) {
-	j.updateTasks(func(tasks *activeSideTasks) {
-		if tasks.replicationSetConcurrency != nil {
-			err = tasks.replicationSetConcurrency(concurrency) // no shadow
-			if err == nil {
-				tasks.concurrency = concurrency
-			}
-		} else {
-			// FIXME this is not great, should always be able to set it
-			err = errors.Errorf("cannot set while not replicating")
-		}
-
-	})
-	return err
-}
-
 func (j *ActiveSide) Run(ctx context.Context) {
 	log := GetLogger(ctx)
 	ctx = logging.WithSubsystemLoggers(ctx, log)
@@ -457,14 +436,11 @@ func (j *ActiveSide) do(ctx context.Context) {
 		ctx, repCancel := context.WithCancel(ctx)
 		var repWait driver.WaitFunc
 		j.updateTasks(func(tasks *activeSideTasks) {
-			// reset it (almost)
-			old := *tasks
-			*tasks = activeSideTasks{
-				concurrency: old.concurrency,
-			}
+			// reset it
+			*tasks = activeSideTasks{}
 			tasks.replicationCancel = repCancel
-			tasks.replicationReport, repWait, tasks.replicationSetConcurrency = replication.Do(
-				ctx, tasks.concurrency, logic.NewPlanner(j.promRepStateSecs, j.promBytesReplicated, sender, receiver, j.mode.PlannerPolicy()),
+			tasks.replicationReport, repWait = replication.Do(
+				ctx, logic.NewPlanner(j.promRepStateSecs, j.promBytesReplicated, sender, receiver, j.mode.PlannerPolicy()),
 			)
 			tasks.state = ActiveSideReplicating
 		})

daemon/job/job.go

@@ -40,7 +40,6 @@ type Job interface {
 	// must return the root of that subtree as rfs and ok = true
 	OwnedDatasetSubtreeRoot() (rfs *zfs.DatasetPath, ok bool)
 	SenderConfig() *endpoint.SenderConfig
-	SetConcurrency(concurrency int) error
 }
 
 type Type string

daemon/job/passive.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 
+	"github.com/golang/protobuf/proto"
 	"github.com/pkg/errors"
 	"github.com/prometheus/client_golang/prometheus"
 
@@ -163,8 +164,6 @@ func (j *PassiveSide) SenderConfig() *endpoint.SenderConfig {
 
 func (*PassiveSide) RegisterMetrics(registerer prometheus.Registerer) {}
 
-func (*PassiveSide) SetConcurrency(concurrency int) error { return errors.Errorf("not supported") }
-
 func (j *PassiveSide) Run(ctx context.Context) {
 
 	log := GetLogger(ctx)
@@ -182,11 +181,39 @@ func (j *PassiveSide) Run(ctx context.Context) {
 	}
 
 	ctxInterceptor := func(handlerCtx context.Context) context.Context {
-		return logging.WithSubsystemLoggers(handlerCtx, log)
+		reqLog := log.WithField(logging.ReqIDField, rpc.MustGetRequestID(handlerCtx))
+		return logging.WithSubsystemLoggers(handlerCtx, reqLog)
+	}
+
+	// ctxInterceptor already injected request loggers (with request id)
+	pre := func(ctx context.Context, method string, req interface{}) {
+		l := endpoint.GetLogger(ctx).WithField("method", method).WithField("reqT", fmt.Sprintf("%T", req))
+		if p, ok := req.(proto.Message); ok {
+			l = l.WithField("req", proto.CompactTextString(p))
+		}
+		ci, ok := ctx.Value(endpoint.ClientIdentityKey).(string)
+		if !ok {
+			// like endpoint, we must assume that rpc.Server sets it
+			panic(method)
+		}
+		l = l.WithField("clientIdentity", ci)
+		l.Debug("incoming")
+	}
+	post := func(ctx context.Context, res interface{}, err error) {
+		l := endpoint.GetLogger(ctx).
+			WithField("responseT", fmt.Sprintf("%T", res)).
+			WithField("errT", fmt.Sprintf("%T", err))
+		if s, ok := res.(fmt.Stringer); ok {
+			l = l.WithField("response", s.String())
+		}
+		if err != nil {
+			l = l.WithError(err)
+		}
+		l.Debug("handler done")
 	}
 
 	rpcLoggers := rpc.GetLoggersOrPanic(ctx) // WithSubsystemLoggers above
-	server := rpc.NewServer(handler, rpcLoggers, ctxInterceptor)
+	server := rpc.NewServer(handler, rpcLoggers, ctxInterceptor, pre, post)
 
 	listener, err := j.listen()
 	if err != nil {

daemon/job/snapjob.go

@@ -117,8 +117,6 @@ outer:
 	}
 }
 
-func (*SnapJob) SetConcurrency(concurrency int) error { return errors.Errorf("not supported") }
-
 // Adaptor that implements pruner.History around a pruner.Target.
 // The ReplicationCursor method is Get-op only and always returns
 // the filesystem's most recent version's GUID.

daemon/logging/build_logging.go

@@ -96,6 +96,11 @@ func WithSubsystemLoggers(ctx context.Context, log logger.Logger) context.Contex
 			Control: log.WithField(SubsysField, SubsysRPCControl),
 			Data:    log.WithField(SubsysField, SubsysRPCData),
 		},
+		// rpc.Loggers{
+		// 	General: logger.NewNullLogger(),
+		// 	Control: logger.NewNullLogger(),
+		// 	Data:    logger.NewNullLogger(),
+		// },
 	)
 	return ctx
 }

daemon/logging/logging_formatters.go

@@ -22,6 +22,7 @@ const (
 const (
 	JobField    string = "job"
 	SubsysField string = "subsystem"
+	ReqIDField  string = "reqid"
 )
 
 type MetadataFlags int64
@@ -85,7 +86,7 @@ func (f *HumanFormatter) Format(e *logger.Entry) (out []byte, err error) {
 		fmt.Fprintf(&line, "[%s]", col.Sprint(e.Level.Short()))
 	}
 
-	prefixFields := []string{JobField, SubsysField}
+	prefixFields := []string{JobField, SubsysField, ReqIDField}
 	prefixed := make(map[string]bool, len(prefixFields)+2)
 	for _, field := range prefixFields {
 		val, ok := e.Fields[field]

daemon/prometheus.go

@@ -5,7 +5,6 @@ import (
 	"net"
 	"net/http"
 
-	"github.com/pkg/errors"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 
@@ -52,8 +51,6 @@ func (j *prometheusJob) OwnedDatasetSubtreeRoot() (p *zfs.DatasetPath, ok bool)
 
 func (j *prometheusJob) SenderConfig() *endpoint.SenderConfig { return nil }
 
-func (j *prometheusJob) SetConcurrency(concurrency int) error { return errors.Errorf("not supported") }
-
 func (j *prometheusJob) RegisterMetrics(registerer prometheus.Registerer) {}
 
 func (j *prometheusJob) Run(ctx context.Context) {

endpoint/context.go

@@ -19,6 +19,10 @@ func WithLogger(ctx context.Context, log Logger) context.Context {
 	return context.WithValue(ctx, contextKeyLogger, log)
 }
 
+func GetLogger(ctx context.Context) Logger {
+	return getLogger(ctx)
+}
+
 func getLogger(ctx context.Context) Logger {
 	if l, ok := ctx.Value(contextKeyLogger).(Logger); ok {
 		return l

endpoint/endpoint.go

@@ -159,6 +159,7 @@ func sendArgsFromPDUAndValidateExists(ctx context.Context, fs string, fsv *pdu.F
 }
 
 func (s *Sender) Send(ctx context.Context, r *pdu.SendReq) (*pdu.SendRes, zfs.StreamCopier, error) {
+	getLogger(ctx).WithField("req", r.String()).Debug("incoming Send request")
 
 	_, err := s.filterCheckFS(r.Filesystem)
 	if err != nil {
@@ -259,6 +260,7 @@ func (s *Sender) Send(ctx context.Context, r *pdu.SendReq) (*pdu.SendRes, zfs.St
 }
 
 func (p *Sender) SendCompleted(ctx context.Context, r *pdu.SendCompletedReq) (*pdu.SendCompletedRes, error) {
+	getLogger(ctx).WithField("req", r.String()).Debug("incoming SendCompleted request")
 	orig := r.GetOriginalReq() // may be nil, always use proto getters
 	fs := orig.GetFilesystem()
 
@@ -510,7 +512,7 @@ func (s *Receiver) ListFilesystems(ctx context.Context, req *pdu.ListFilesystemR
 	// present filesystem without the root_fs prefix
 	fss := make([]*pdu.Filesystem, 0, len(filtered))
 	for _, a := range filtered {
-		l := getLogger(ctx).WithField("fs", a)
+		l := getLogger(ctx).WithField("fs", a.ToString())
 		ph, err := zfs.ZFSGetFilesystemPlaceholderState(a)
 		if err != nil {
 			l.WithError(err).Error("error getting placeholder state")
@@ -597,7 +599,7 @@ func (s *Receiver) Send(ctx context.Context, req *pdu.SendReq) (*pdu.SendRes, zf
 var maxConcurrentZFSRecvSemaphore = semaphore.New(envconst.Int64("ZREPL_ENDPOINT_MAX_CONCURRENT_RECV", 10))
 
 func (s *Receiver) Receive(ctx context.Context, req *pdu.ReceiveReq, receive zfs.StreamCopier) (*pdu.ReceiveRes, error) {
-	getLogger(ctx).Debug("incoming Receive")
+	getLogger(ctx).WithField("rr", req.String()).Debug("incoming Receive")
 	defer receive.Close()
 
 	root := s.clientRootFromCtx(ctx)

go.mod

@@ -7,6 +7,7 @@ require (
 	github.com/gdamore/tcell v1.2.0
 	github.com/go-logfmt/logfmt v0.4.0
 	github.com/go-sql-driver/mysql v1.4.1-0.20190907122137-b2c03bcae3d4
+	github.com/gogo/protobuf v1.1.1
 	github.com/golang/protobuf v1.3.2
 	github.com/google/uuid v1.1.1
 	github.com/jinzhu/copier v0.0.0-20170922082739-db4671f3a9b8

go.sum

@@ -68,6 +68,7 @@ github.com/go-toolsmith/strparse v1.0.0/go.mod h1:YI2nUKP9YGZnL/L1/DLFBfixrcjslW
 github.com/go-toolsmith/typep v0.0.0-20181030061450-d63dc7650676/go.mod h1:JSQCQMUPdRlMZFswiq3TGpNp1GMktqkR2Ns5AIQkATU=
 github.com/go-toolsmith/typep v1.0.0/go.mod h1:JSQCQMUPdRlMZFswiq3TGpNp1GMktqkR2Ns5AIQkATU=
 github.com/gobwas/glob v0.2.3/go.mod h1:d3Ez4x06l9bZtSvzIay5+Yzi0fmZzPgnTbPcKjJAkT8=
+github.com/gogo/protobuf v1.1.1 h1:72R+M5VuhED/KujmZVcIquuo8mBgX4oVda//DQb3PXo=
 github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ=
 github.com/gogo/protobuf v1.2.1/go.mod h1:hp+jE20tsWTFYpLwKvXlhS1hjn+gTNwPg2I6zVXpSg4=
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b h1:VKtxabqXZkF25pY9ekfRL6a582T4P37/31XEstQ5p58=

replication/driver/replication_driver.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"net"
+	"os"
 	"sort"
 	"strings"
 	"sync"
@@ -14,6 +15,7 @@ import (
 	"google.golang.org/grpc/status"
 
 	"github.com/zrepl/zrepl/replication/report"
+	"github.com/zrepl/zrepl/tracing"
 	"github.com/zrepl/zrepl/util/chainlock"
 	"github.com/zrepl/zrepl/util/envconst"
 )
@@ -89,8 +91,6 @@ type attempt struct {
 	// if both are nil, it must be assumed that Planner.Plan is active
 	planErr *timedError
 	fss     []*fs
-
-	concurrency int
 }
 
 type timedError struct {
@@ -172,12 +172,11 @@ type step struct {
 
 type ReportFunc func() *report.Report
 type WaitFunc func(block bool) (done bool)
-type SetConcurrencyFunc func(concurrency int) error
 
 var maxAttempts = envconst.Int64("ZREPL_REPLICATION_MAX_ATTEMPTS", 3)
 var reconnectHardFailTimeout = envconst.Duration("ZREPL_REPLICATION_RECONNECT_HARD_FAIL_TIMEOUT", 10*time.Minute)
 
-func Do(ctx context.Context, initialConcurrency int, planner Planner) (ReportFunc, WaitFunc, SetConcurrencyFunc) {
+func Do(ctx context.Context, planner Planner) (ReportFunc, WaitFunc) {
 	log := getLog(ctx)
 	l := chainlock.New()
 	run := &run{
@@ -185,8 +184,6 @@ func Do(ctx context.Context, initialConcurrency int, planner Planner) (ReportFun
 		startedAt: time.Now(),
 	}
 
-	concurrencyChanges := make(chan concurrencyChange)
-
 	done := make(chan struct{})
 	go func() {
 		defer close(done)
@@ -203,21 +200,16 @@ func Do(ctx context.Context, initialConcurrency int, planner Planner) (ReportFun
 			run.waitReconnect.SetZero()
 			run.waitReconnectError = nil
 
-			prevConcurrency := initialConcurrency // FIXME default concurrency
-			if prev != nil {
-				prevConcurrency = prev.concurrency
-			}
-
 			// do current attempt
 			cur := &attempt{
-				l:           l,
-				startedAt:   time.Now(),
-				planner:     planner,
-				concurrency: prevConcurrency,
+				l:         l,
+				startedAt: time.Now(),
+				planner:   planner,
 			}
 			run.attempts = append(run.attempts, cur)
 			run.l.DropWhile(func() {
-				cur.do(ctx, prev, concurrencyChanges)
+				ctx := tracing.Child(ctx, fmt.Sprintf("attempt#%d", ano)) // shadow
+				cur.do(ctx, prev)
 			})
 			prev = cur
 			if ctx.Err() != nil {
@@ -288,26 +280,11 @@ func Do(ctx context.Context, initialConcurrency int, planner Planner) (ReportFun
 		defer run.l.Lock().Unlock()
 		return run.report()
 	}
-	setConcurrency := func(concurrency int) (reterr error) {
-		var wg sync.WaitGroup
-		wg.Add(1)
-		concurrencyChanges <- concurrencyChange{ concurrency, func(err error) {
-			defer wg.Done()
-			reterr = err // shadow
-		}}
-		wg.Wait()
-		return reterr
-	}
-	return report, wait, setConcurrency
+	return report, wait
 }
 
-type concurrencyChange struct {
-	value          int
-	resultCallback func(error)
-}
-
-func (a *attempt) do(ctx context.Context, prev *attempt, setConcurrency <-chan concurrencyChange) {
-	pfss, err := a.planner.Plan(ctx)
+func (a *attempt) do(ctx context.Context, prev *attempt) {
+	pfss, err := a.planner.Plan(tracing.Child(ctx, "plan"))
 	errTime := time.Now()
 	defer a.l.Lock().Unlock()
 	if err != nil {
@@ -380,43 +357,26 @@ func (a *attempt) do(ctx context.Context, prev *attempt, setConcurrency <-chan c
 	}
 	// invariant: prevs contains an entry for each unambigious correspondence
 
-	stepQueue := newStepQueue(a.concurrency)
-	defer stepQueue.Start()()
+	stepQueue := newStepQueue()
+	defer stepQueue.Start(1)() // TODO parallel replication
 	var fssesDone sync.WaitGroup
 	for _, f := range a.fss {
 		fssesDone.Add(1)
 		go func(f *fs) {
 			defer fssesDone.Done()
-			f.do(ctx, stepQueue, prevs[f])
+			f.do(tracing.Child(ctx, f.fs.ReportInfo().Name), stepQueue, prevs[f])
 		}(f)
 	}
-	changeConcurrencyDone := make(chan struct{})
-	go func() {
-		for {
-			select {
-			case change := <-setConcurrency:
-				err := stepQueue.SetConcurrency(change.value)
-				go change.resultCallback(err)
-				if err == nil {
-					a.l.Lock()
-					a.concurrency = change.value
-					a.l.Unlock()
-				}
-			case <-changeConcurrencyDone:
-				return
-				// not waiting for ctx.Done here, the main job are the fsses
-			}
-		}
-	}()
 	a.l.DropWhile(func() {
 		fssesDone.Wait()
-		close(changeConcurrencyDone)
 	})
 	a.finishedAt = time.Now()
 }
 
 func (fs *fs) do(ctx context.Context, pq *stepQueue, prev *fs) {
 
+	fmt.Fprintf(os.Stderr, "CHILD STACK: %v\n", tracing.GetStack(ctx))
+
 	defer fs.l.Lock().Unlock()
 
 	// get planned steps from replication logic
@@ -506,8 +466,7 @@ func (fs *fs) do(ctx context.Context, pq *stepQueue, prev *fs) {
 		// lock must not be held while executing step in order for reporting to work
 		fs.l.DropWhile(func() {
 			targetDate := s.step.TargetDate()
-			ctx, done := pq.WaitReady(ctx, fs, targetDate)()
-			defer done()
+			defer pq.WaitReady(fs, targetDate)()
 			err = s.step.Step(ctx) // no shadow
 			errTime = time.Now()   // no shadow
 		})
@@ -528,7 +487,6 @@ func (r *run) report() *report.Report {
 		WaitReconnectSince: r.waitReconnect.begin,
 		WaitReconnectUntil: r.waitReconnect.end,
 		WaitReconnectError: r.waitReconnectError.IntoReportError(),
-		// Concurrency:        r.concurrency,
 	}
 	for i := range report.Attempts {
 		report.Attempts[i] = r.attempts[i].report()

replication/driver/replication_driver_test.go

@@ -151,7 +151,7 @@ func TestReplication(t *testing.T) {
 	ctx := context.Background()
 
 	mp := &mockPlanner{}
-	getReport, wait, _ := Do(ctx, 1, mp)
+	getReport, wait := Do(ctx, mp)
 	begin := time.Now()
 	fireAt := []time.Duration{
 		// the following values are relative to the start

replication/driver/replication_stepqueue.go

@@ -2,8 +2,6 @@ package driver
 
 import (
 	"container/heap"
-	"fmt"
-	"sync"
 	"time"
 
 	"github.com/zrepl/zrepl/util/chainlock"
@@ -13,88 +11,51 @@ type stepQueueRec struct {
 	ident      interface{}
 	targetDate time.Time
 	wakeup     chan StepCompletedFunc
-	cancelDueToConcurrencyDownsize interace{}
 }
 
 type stepQueue struct {
 	stop chan struct{}
 	reqs chan stepQueueRec
-
-	// l protects all members except the channels above
-
-	l           *chainlock.L
-	pendingCond *sync.Cond
-
-	// ident => queueItem
-	pending    *stepQueueHeap
-	active     *stepQueueHeap
-	queueItems map[interface{}]*stepQueueHeapItem // for tracking used idents in both pending and active
-
-	// stopped is used for cancellation of "wake" goroutine
-	stopped bool
-
-	concurrency int
 }
 
 type stepQueueHeapItem struct {
 	idx int
-	req *stepQueueRec
-}
-type stepQueueHeap struct {
-	items   []*stepQueueHeapItem
-	reverse bool // never change after pushing first element
+	req stepQueueRec
 }
+type stepQueueHeap []*stepQueueHeapItem
 
 func (h stepQueueHeap) Less(i, j int) bool {
-	res := h.items[i].req.targetDate.Before(h.items[j].req.targetDate)
-	if h.reverse {
-		return !res
-	}
-	return res
+	return h[i].req.targetDate.Before(h[j].req.targetDate)
 }
 
 func (h stepQueueHeap) Swap(i, j int) {
-	h.items[i], h.items[j] = h.items[j], h.items[i]
-	h.items[i].idx = i
-	h.items[j].idx = j
+	h[i], h[j] = h[j], h[i]
+	h[i].idx = i
+	h[j].idx = j
 }
 
 func (h stepQueueHeap) Len() int {
-	return len(h.items)
+	return len(h)
 }
 
 func (h *stepQueueHeap) Push(elem interface{}) {
 	hitem := elem.(*stepQueueHeapItem)
 	hitem.idx = h.Len()
-	h.items = append(h.items, hitem)
+	*h = append(*h, hitem)
 }
 
 func (h *stepQueueHeap) Pop() interface{} {
-	elem := h.items[h.Len()-1]
+	elem := (*h)[h.Len()-1]
 	elem.idx = -1
-	h.items = h.items[:h.Len()-1]
+	*h = (*h)[:h.Len()-1]
 	return elem
 }
 
 // returned stepQueue must be closed with method Close
-func newStepQueue(concurrency int) *stepQueue {
-	l := chainlock.New()
+func newStepQueue() *stepQueue {
 	q := &stepQueue{
-		stop:        make(chan struct{}),
-		reqs:        make(chan stepQueueRec),
-		l:           l,
-		pendingCond: l.NewCond(),
-		// priority queue
-		pending: &stepQueueHeap{reverse: false},
-		active:  &stepQueueHeap{reverse: true},
-		// ident => queueItem
-		queueItems: make(map[interface{}]*stepQueueHeapItem),
-		// stopped is used for cancellation of "wake" goroutine
-		stopped: false,
-	}
-	err := q.setConcurrencyLocked(concurrency)
-	if err != nil {
-		panic(err)
+		stop: make(chan struct{}),
+		reqs: make(chan stepQueueRec),
 	}
 	return q
 }
@@ -104,12 +65,25 @@ func newStepQueue(concurrency int) *stepQueue {
 //
 // No WaitReady calls must be active at the time done is called
 // The behavior of calling WaitReady after done was called is undefined
-func (q *stepQueue) Start() (done func()) {
+func (q *stepQueue) Start(concurrency int) (done func()) {
+	if concurrency < 1 {
+		panic("concurrency must be >= 1")
+	}
+	// l protects pending and queueItems
+	l := chainlock.New()
+	pendingCond := l.NewCond()
+	// priority queue
+	pending := &stepQueueHeap{}
+	// ident => queueItem
+	queueItems := make(map[interface{}]*stepQueueHeapItem)
+	// stopped is used for cancellation of "wake" goroutine
+	stopped := false
+	active := 0
 	go func() { // "stopper" goroutine
 		<-q.stop
-		defer q.l.Lock().Unlock()
-		q.stopped = true
-		q.pendingCond.Broadcast()
+		defer l.Lock().Unlock()
+		stopped = true
+		pendingCond.Broadcast()
 	}()
 	go func() { // "reqs" goroutine
 		for {
@@ -123,52 +97,41 @@ func (q *stepQueue) Start() (done func()) {
 				}
 			case req := <-q.reqs:
 				func() {
-					defer q.l.Lock().Unlock()
-					if _, ok := q.queueItems[req.ident]; ok {
+					defer l.Lock().Unlock()
+					if _, ok := queueItems[req.ident]; ok {
 						panic("WaitReady must not be called twice for the same ident")
 					}
 					qitem := &stepQueueHeapItem{
 						req: req,
 					}
-					q.queueItems[req.ident] = qitem
-					heap.Push(q.pending, qitem)
-					q.pendingCond.Broadcast()
+					queueItems[req.ident] = qitem
+					heap.Push(pending, qitem)
+					pendingCond.Broadcast()
 				}()
 			}
 		}
 	}()
 	go func() { // "wake" goroutine
-		defer q.l.Lock().Unlock()
+		defer l.Lock().Unlock()
 		for {
 
-			for !q.stopped && (q.active.Len() >= q.concurrency || q.pending.Len() == 0) {
-				q.pendingCond.Wait()
+			for !stopped && (active >= concurrency || pending.Len() == 0) {
+				pendingCond.Wait()
 			}
-			if q.stopped {
+			if stopped {
 				return
 			}
-			if q.pending.Len() <= 0 {
+			if pending.Len() <= 0 {
 				return
 			}
+			active++
+			next := heap.Pop(pending).(*stepQueueHeapItem).req
+			delete(queueItems, next.ident)
 
-			// pop from tracked items
-			next := heap.Pop(q.pending).(*stepQueueHeapItem)
-
-			next.req.cancelDueToConcurrencyDownsize = 
-
-			heap.Push(q.active, next)
-
-			next.req.wakeup <- func() {
-				defer q.l.Lock().Unlock()
-
-				//
-				qitem := &stepQueueHeapItem{
-					req: req,
-				}
-
-				// delete(q.queueItems, next.req.ident) // def
-
-				q.pendingCond.Broadcast()
+			next.wakeup <- func() {
+				defer l.Lock().Unlock()
+				active--
+				pendingCond.Broadcast()
 			}
 		}
 	}()
@@ -198,24 +161,3 @@ func (q *stepQueue) WaitReady(ident interface{}, targetDate time.Time) StepCompl
 	}
 	return q.sendAndWaitForWakeup(ident, targetDate)
 }
-
-// caller must hold lock
-func (q *stepQueue) setConcurrencyLocked(newConcurrency int) error {
-	if !(newConcurrency >= 1) {
-		return fmt.Errorf("concurrency must be >= 1 but requested %v", newConcurrency)
-	}
-	q.concurrency = newConcurrency
-	q.pendingCond.Broadcast() // wake up waiters who could make progress
-
-	for q.active.Len() > q.concurrency {
-		item := heap.Pop(q.active).(*stepQueueHeapItem)
-		item.req.cancelDueToConcurrencyDownsize()
-		heap.Push(q.pending, item)
-	}
-	return nil
-}
-
-func (q *stepQueue) SetConcurrency(new int) error {
-	defer q.l.Lock().Unlock()
-	return q.setConcurrencyLocked(new)
-}

replication/driver/replication_stepqueue_test.go

@@ -17,7 +17,7 @@ import (
 // (relies on scheduler responsivity of < 500ms)
 func TestPqNotconcurrent(t *testing.T) {
 	var ctr uint32
-	q := newStepQueue(1)
+	q := newStepQueue()
 	var wg sync.WaitGroup
 	wg.Add(4)
 	go func() {
@@ -29,7 +29,7 @@ func TestPqNotconcurrent(t *testing.T) {
 	}()
 
 	// give goroutine "1" 500ms to enter queue, get the active slot and enter time.Sleep
-	defer q.Start()()
+	defer q.Start(1)()
 	time.Sleep(500 * time.Millisecond)
 
 	// while "1" is still running, queue in "2", "3" and "4"
@@ -77,9 +77,8 @@ func (r record) String() string {
 // Hence, perform some statistics on the wakeup times and assert that the mean wakeup
 // times for each step are close together.
 func TestPqConcurrent(t *testing.T) {
-	
-	concurrency := 5
-	q := newStepQueue(concurrency)
+
+	q := newStepQueue()
 	var wg sync.WaitGroup
 	filesystems := 100
 	stepsPerFS := 20
@@ -105,7 +104,8 @@ func TestPqConcurrent(t *testing.T) {
 			records <- recs
 		}(fs)
 	}
-	defer q.Start()()
+	concurrency := 5
+	defer q.Start(concurrency)()
 	wg.Wait()
 	close(records)
 	t.Logf("loop done")

replication/logic/replication_logic.go

@@ -606,7 +606,7 @@ func (s *Step) doReplication(ctx context.Context) error {
 	log := getLogger(ctx)
 	sr := s.buildSendRequest(false)
 
-	log.Debug("initiate send request")
+	log.WithField("sr", sr.String()).Debug("initiate send request")
 	sres, sstreamCopier, err := s.sender.Send(ctx, sr)
 	if err != nil {
 		log.WithError(err).Error("send request failed")
@@ -633,7 +633,7 @@ func (s *Step) doReplication(ctx context.Context) error {
 		To:               sr.GetTo(),
 		ClearResumeToken: !sres.UsedResumeToken,
 	}
-	log.Debug("initiate receive request")
+	log.WithField("rr", rr.String()).Debug("initiate receive request")
 	_, err = s.receiver.Receive(ctx, rr, byteCountingStream)
 	if err != nil {
 		log.
@@ -649,10 +649,11 @@ func (s *Step) doReplication(ctx context.Context) error {
 	}
 	log.Debug("receive finished")
 
-	log.Debug("tell sender replication completed")
-	_, err = s.sender.SendCompleted(ctx, &pdu.SendCompletedReq{
+	scr := &pdu.SendCompletedReq{
 		OriginalReq: sr,
-	})
+	}
+	log.WithField("scr", scr.String()).Debug("tell sender replication completed")
+	_, err = s.sender.SendCompleted(ctx, scr)
 	if err != nil {
 		log.WithError(err).Error("error telling sender that replication completed successfully")
 		return err

replication/replication.go

@@ -8,6 +8,6 @@ import (
 	"github.com/zrepl/zrepl/replication/driver"
 )
 
-func Do(ctx context.Context, initialConcurrency int, planner driver.Planner) (driver.ReportFunc, driver.WaitFunc, driver.SetConcurrencyFunc) {
-	return driver.Do(ctx, initialConcurrency, planner)
+func Do(ctx context.Context, planner driver.Planner) (driver.ReportFunc, driver.WaitFunc) {
+	return driver.Do(ctx, planner)
 }

replication/report/replication_report.go

@@ -10,7 +10,6 @@ type Report struct {
 	WaitReconnectSince, WaitReconnectUntil time.Time
 	WaitReconnectError                     *TimedError
 	Attempts                               []*AttemptReport
-	Concurrency                            int
 }
 
 var _, _ = json.Marshal(&Report{})

rpc/dataconn/dataconn_client.go

@@ -75,7 +75,7 @@ func (c *Client) recv(ctx context.Context, conn *stream.Conn, res proto.Message)
 	if err != nil {
 		return err
 	}
-	header := string(headerBuf)
+	header := string(headerBuf) // FIXME
 	if strings.HasPrefix(header, responseHeaderHandlerErrorPrefix) {
 		// FIXME distinguishable error type
 		return &RemoteHandlerError{strings.TrimPrefix(header, responseHeaderHandlerErrorPrefix)}

rpc/dataconn/dataconn_server.go

@@ -14,8 +14,8 @@ import (
 	"github.com/zrepl/zrepl/zfs"
 )
 
-// WireInterceptor has a chance to exchange the context and connection on each client connection.
-type WireInterceptor func(ctx context.Context, rawConn *transport.AuthConn) (context.Context, *transport.AuthConn)
+// ReqInterceptor has a chance to exchange the context and connection on each request.
+type ReqInterceptor func(ctx context.Context, rawConn *transport.AuthConn) (context.Context, *transport.AuthConn)
 
 // Handler implements the functionality that is exposed by Server to the Client.
 type Handler interface {
@@ -30,19 +30,27 @@ type Handler interface {
 	PingDataconn(ctx context.Context, r *pdu.PingReq) (*pdu.PingRes, error)
 }
 
+type PreHandlerInspector = func(ctx context.Context, endpoint string, req interface{})
+
+type PostHandlerInspector = func(ctx context.Context, response interface{}, err error)
+
 type Logger = logger.Logger
 
 type Server struct {
-	h   Handler
-	wi  WireInterceptor
-	log Logger
+	h    Handler
+	ri   ReqInterceptor
+	log  Logger
+	pre  PreHandlerInspector
+	post PostHandlerInspector
 }
 
-func NewServer(wi WireInterceptor, logger Logger, handler Handler) *Server {
+func NewServer(ri ReqInterceptor, logger Logger, pre PreHandlerInspector, handler Handler, post PostHandlerInspector) *Server {
 	return &Server{
 		h:   handler,
-		wi:  wi,
+		ri:  ri,
 		log: logger,
+		pre: pre,
+		post: post,
 	}
 }
 
@@ -83,8 +91,8 @@ func (s *Server) serveConn(nc *transport.AuthConn) {
 	defer s.log.Debug("serveConn done")
 
 	ctx := context.Background()
-	if s.wi != nil {
-		ctx, nc = s.wi(ctx, nc)
+	if s.ri != nil {
+		ctx, nc = s.ri(ctx, nc)
 	}
 
 	c := stream.Wrap(nc, HeartbeatInterval, HeartbeatPeerTimeout)
@@ -100,7 +108,7 @@ func (s *Server) serveConn(nc *transport.AuthConn) {
 		s.log.WithError(err).Error("error reading structured part")
 		return
 	}
-	endpoint := string(header)
+	endpoint := string(header) // FIXME
 
 	reqStructured, err := c.ReadStreamedMessage(ctx, RequestStructuredMaxSize, ReqStructured)
 	if err != nil {
@@ -120,6 +128,7 @@ func (s *Server) serveConn(nc *transport.AuthConn) {
 			s.log.WithError(err).Error("cannot unmarshal send request")
 			return
 		}
+		s.pre(ctx, endpoint, &req)
 		res, sendStream, handlerErr = s.h.Send(ctx, &req) // SHADOWING
 	case EndpointRecv:
 		var req pdu.ReceiveReq
@@ -127,6 +136,7 @@ func (s *Server) serveConn(nc *transport.AuthConn) {
 			s.log.WithError(err).Error("cannot unmarshal receive request")
 			return
 		}
+		s.pre(ctx, endpoint, &req)
 		res, handlerErr = s.h.Receive(ctx, &req, &streamCopier{streamConn: c, closeStreamOnClose: false}) // SHADOWING
 	case EndpointPing:
 		var req pdu.PingReq
@@ -134,6 +144,7 @@ func (s *Server) serveConn(nc *transport.AuthConn) {
 			s.log.WithError(err).Error("cannot unmarshal ping request")
 			return
 		}
+		s.pre(ctx, endpoint, &req)
 		res, handlerErr = s.h.PingDataconn(ctx, &req) // SHADOWING
 	default:
 		s.log.WithField("endpoint", endpoint).Error("unknown endpoint")
@@ -142,6 +153,8 @@ func (s *Server) serveConn(nc *transport.AuthConn) {
 
 	s.log.WithField("endpoint", endpoint).WithField("errType", fmt.Sprintf("%T", handlerErr)).Debug("handler returned")
 
+	s.post(ctx, res, handlerErr)
+
 	// prepare protobuf now to return the protobuf error in the header
 	// if marshaling fails. We consider failed marshaling a handler error
 	var protobuf *bytes.Buffer

rpc/grpcclientidentity/authlistener_grpc_adaptor.go

@@ -101,7 +101,11 @@ func (*transportCredentials) OverrideServerName(string) error {
 
 type ContextInterceptor = func(ctx context.Context) context.Context
 
-func NewInterceptors(logger Logger, clientIdentityKey interface{}, ctxInterceptor ContextInterceptor) (unary grpc.UnaryServerInterceptor, stream grpc.StreamServerInterceptor) {
+type PreHandlerInspector func(ctx context.Context, endpoint string, req interface{})
+
+type PostHandlerInspector func(ctx context.Context, response interface{}, err error)
+
+func NewInterceptors(logger Logger, clientIdentityKey interface{}, ctxInterceptor ContextInterceptor, pre PreHandlerInspector, post PostHandlerInspector) (unary grpc.UnaryServerInterceptor, stream grpc.StreamServerInterceptor) {
 	unary = func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
 		logger.WithField("fullMethod", info.FullMethod).Debug("request")
 		p, ok := peer.FromContext(ctx)
@@ -118,7 +122,10 @@ func NewInterceptors(logger Logger, clientIdentityKey interface{}, ctxIntercepto
 		if ctxInterceptor != nil {
 			ctx = ctxInterceptor(ctx)
 		}
-		return handler(ctx, req)
+		pre(ctx, info.FullMethod, req)
+		res, err := handler(ctx, req)
+		post(ctx, res, err)
+		return res, err
 	}
 	stream = func(srv interface{}, ss grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
 		panic("unimplemented")

rpc/grpcclientidentity/grpchelper/authlistener_grpc_adaptor_wrapper.go

@@ -4,14 +4,18 @@ package grpchelper
 
 import (
 	"context"
+	"fmt"
+	"strings"
 	"time"
 
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/keepalive"
+	"google.golang.org/grpc/metadata"
 
 	"github.com/zrepl/zrepl/logger"
 	"github.com/zrepl/zrepl/rpc/grpcclientidentity"
 	"github.com/zrepl/zrepl/rpc/netadaptor"
+	"github.com/zrepl/zrepl/tracing"
 	"github.com/zrepl/zrepl/transport"
 )
 
@@ -28,15 +32,40 @@ type Logger = logger.Logger
 
 // ClientConn is an easy-to-use wrapper around the Dialer and TransportCredentials interface
 // to produce a grpc.ClientConn
-func ClientConn(cn transport.Connecter, log Logger) *grpc.ClientConn {
+func ClientConn(cn transport.Connecter, log Logger, genReqID func() string) *grpc.ClientConn {
 	ka := grpc.WithKeepaliveParams(keepalive.ClientParameters{
 		Time:                StartKeepalivesAfterInactivityDuration,
 		Timeout:             KeepalivePeerTimeout,
 		PermitWithoutStream: true,
 	})
+	unaryIntcpt := grpc.WithUnaryInterceptor(func(ctx context.Context, method string, req, reply interface{}, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error {
+
+		traceStack := tracing.GetStack(ctx)
+		if len(traceStack) == 0 {
+			panic("implementation error: expecting trace stack")
+		}
+		reqId := genReqID() + " " + strings.Join(traceStack, " <> ")
+
+		l := log
+		l = l.WithField("reqID", reqId)
+		l = l.WithField("reqT", fmt.Sprintf("%T", req))
+		l = l.WithField("repT", fmt.Sprintf("%T", reply))
+		l = l.WithField("ctxT", fmt.Sprintf("%T", ctx))
+		l.Debug("unary intercepted")
+
+		ctx = metadata.AppendToOutgoingContext(ctx, "zrepl-req-id", reqId)
+
+		err := invoker(ctx, method, req, reply, cc, opts...)
+
+		l = log.WithField("repT", fmt.Sprintf("%T", reply))
+		l = log.WithField("errT", fmt.Sprintf("%T", err))
+		l.Debug("reply intercepted")
+
+		return err
+	})
 	dialerOption := grpc.WithDialer(grpcclientidentity.NewDialer(log, cn))
 	cred := grpc.WithTransportCredentials(grpcclientidentity.NewTransportCredentials(log))
-	cc, err := grpc.DialContext(context.Background(), "doesn't matter done by dialer", dialerOption, cred, ka)
+	cc, err := grpc.DialContext(context.Background(), "doesn't matter done by dialer", dialerOption, cred, ka, unaryIntcpt)
 	if err != nil {
 		log.WithError(err).Error("cannot create gRPC client conn (non-blocking)")
 		// It's ok to panic here: the we call grpc.DialContext without the
@@ -50,7 +79,7 @@ func ClientConn(cn transport.Connecter, log Logger) *grpc.ClientConn {
 }
 
 // NewServer is a convenience interface around the TransportCredentials and Interceptors interface.
-func NewServer(authListener transport.AuthenticatedListener, clientIdentityKey interface{}, logger grpcclientidentity.Logger, ctxInterceptor grpcclientidentity.ContextInterceptor) (srv *grpc.Server, serve func() error) {
+func NewServer(authListener transport.AuthenticatedListener, clientIdentityKey interface{}, logger grpcclientidentity.Logger, interceptor grpcclientidentity.ContextInterceptor, pre grpcclientidentity.PreHandlerInspector, post grpcclientidentity.PostHandlerInspector) (srv *grpc.Server, serve func() error) {
 	ka := grpc.KeepaliveParams(keepalive.ServerParameters{
 		Time:    StartKeepalivesAfterInactivityDuration,
 		Timeout: KeepalivePeerTimeout,
@@ -60,8 +89,17 @@ func NewServer(authListener transport.AuthenticatedListener, clientIdentityKey i
 		PermitWithoutStream: true,
 	})
 	tcs := grpcclientidentity.NewTransportCredentials(logger)
-	unary, stream := grpcclientidentity.NewInterceptors(logger, clientIdentityKey, ctxInterceptor)
-	srv = grpc.NewServer(grpc.Creds(tcs), grpc.UnaryInterceptor(unary), grpc.StreamInterceptor(stream), ka, ep)
+	unary, stream := grpcclientidentity.NewInterceptors(logger, clientIdentityKey, interceptor, pre, post)
+	unary2 := func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
+		md, ok := metadata.FromIncomingContext(ctx)
+		if !ok {
+			logger.Error("no request id in incoming request")
+		} else {
+			logger.Info(fmt.Sprintf("req-id = %v", md.Get("zrepl-req-id")))
+		}
+		return unary(ctx, req, info, handler)
+	}
+	srv = grpc.NewServer(grpc.Creds(tcs), grpc.UnaryInterceptor(unary2), grpc.StreamInterceptor(stream), ka, ep)
 
 	serve = func() error {
 		if err := srv.Serve(netadaptor.New(authListener, logger)); err != nil {

rpc/rpc_client.go

@@ -26,6 +26,7 @@ import (
 // Client implements the active side of a replication setup.
 // It satisfies the Endpoint, Sender and Receiver interface defined by package replication.
 type Client struct {
+	reqIDGen      *requestIDGenerator
 	dataClient    *dataconn.Client
 	controlClient pdu.ReplicationClient // this the grpc client instance, see constructor
 	controlConn   *grpc.ClientConn
@@ -47,10 +48,13 @@ func NewClient(cn transport.Connecter, loggers Loggers) *Client {
 	muxedConnecter := mux(cn)
 
 	c := &Client{
-		loggers: loggers,
-		closed:  make(chan struct{}),
+		loggers:  loggers,
+		closed:   make(chan struct{}),
+		reqIDGen: newRequestIDGenerator(),
 	}
-	grpcConn := grpchelper.ClientConn(muxedConnecter.control, loggers.Control)
+	grpcConn := grpchelper.ClientConn(muxedConnecter.control, loggers.Control, func() string {
+		return c.reqIDGen.newID().String()
+	})
 
 	go func() {
 		ctx, cancel := context.WithCancel(context.Background())

rpc/rpc_requestid.go

@@ -0,0 +1,58 @@
+package rpc
+
+import (
+	"context"
+	"encoding/base64"
+	"strings"
+
+	"github.com/google/uuid"
+)
+
+type requestIDGenerator struct{}
+
+func newRequestIDGenerator() *requestIDGenerator {
+	return &requestIDGenerator{}
+}
+
+type RequestID struct{ s string }
+
+func (r RequestID) String() string { return r.s }
+
+type requestIDContextKey int
+
+const (
+	requestIDContextKeyRequestID requestIDContextKey = 1 + iota
+)
+
+func (g *requestIDGenerator) newID() RequestID {
+	id := uuid.New()
+	var buf strings.Builder
+	enc := base64.NewEncoder(base64.RawStdEncoding, &buf)
+	n, err := enc.Write(id[:])
+	if err != nil {
+		panic(err)
+	} else if n != len(id) {
+		panic(n)
+	}
+	if err := enc.Close(); err != nil {
+		panic(err)
+	}
+	return RequestID{buf.String()}
+}
+
+func (g *requestIDGenerator) inject(ctx context.Context) context.Context {
+	return context.WithValue(ctx, requestIDContextKeyRequestID, g.newID())
+}
+
+func GetRequestID(ctx context.Context) (id RequestID, ok bool) {
+	id, ok = ctx.Value(requestIDContextKeyRequestID).(RequestID)
+	return id, ok
+}
+
+func MustGetRequestID(ctx context.Context) (id RequestID) {
+	id, ok := GetRequestID(ctx)
+	if !ok {
+		panic("calling context expectes request id to bet set")
+	}
+	return id
+}

rpc/rpc_server.go

@@ -7,6 +7,7 @@ import (
 	"github.com/zrepl/zrepl/endpoint"
 	"github.com/zrepl/zrepl/replication/logic/pdu"
 	"github.com/zrepl/zrepl/rpc/dataconn"
+	"github.com/zrepl/zrepl/rpc/grpcclientidentity"
 	"github.com/zrepl/zrepl/rpc/grpcclientidentity/grpchelper"
 	"github.com/zrepl/zrepl/rpc/versionhandshake"
 	"github.com/zrepl/zrepl/transport"
@@ -30,15 +31,35 @@ type Server struct {
 	dataServerServe    serveFunc
 }
 
-type HandlerContextInterceptor func(ctx context.Context) context.Context
+type CtxInterceptor = grpcclientidentity.ContextInterceptor
+
+func chainInterceptors(interceptors []CtxInterceptor) CtxInterceptor {
+	return func(ctx context.Context) (_ context.Context) {
+		for _, i := range interceptors {
+			ctx = i(ctx)
+		}
+		return ctx
+	}
+}
+
+type PreHandlerInspector = func(ctx context.Context, endpoint string, req interface{})
+
+type PostHandlerInspector = func(ctx context.Context, response interface{}, err error)
 
 // config must be valid (use its Validate function).
-func NewServer(handler Handler, loggers Loggers, ctxInterceptor HandlerContextInterceptor) *Server {
+func NewServer(handler Handler, loggers Loggers, ctxInterceptor CtxInterceptor, pre PreHandlerInspector, post PostHandlerInspector) *Server {
+
+	reqIdGen := newRequestIDGenerator()
+
+	ctxInterceptor = chainInterceptors([]CtxInterceptor{
+		reqIdGen.inject,
+		ctxInterceptor,
+	})
 
 	// setup control server
 	controlServerServe := func(ctx context.Context, controlListener transport.AuthenticatedListener, errOut chan<- error) {
 
-		controlServer, serve := grpchelper.NewServer(controlListener, endpoint.ClientIdentityKey, loggers.Control, ctxInterceptor)
+		controlServer, serve := grpchelper.NewServer(controlListener, endpoint.ClientIdentityKey, loggers.Control, ctxInterceptor, pre, post)
 		pdu.RegisterReplicationServer(controlServer, handler)
 
 		// give time for graceful stop until deadline expires, then hard stop
@@ -63,7 +84,7 @@ func NewServer(handler Handler, loggers Loggers, ctxInterceptor HandlerContextIn
 		}
 		return ctx, wire
 	}
-	dataServer := dataconn.NewServer(dataServerClientIdentitySetter, loggers.Data, handler)
+	dataServer := dataconn.NewServer(dataServerClientIdentitySetter, loggers.Data, pre, handler, post)
 	dataServerServe := func(ctx context.Context, dataListener transport.AuthenticatedListener, errOut chan<- error) {
 		dataServer.Serve(ctx, dataListener)
 		errOut <- nil // TODO bad design of dataServer?

tracing/tracing.go

@@ -0,0 +1,53 @@
+package tracing
+
+import "context"
+
+type tracingContextKey int
+
+const (
+	CallerContext tracingContextKey = 1 + iota
+)
+
+type jobSubtree struct {
+	jobid string
+}
+
+type ctx struct {
+	parent *ctx
+	job    *jobSubtree
+	ident  string
+}
+
+var root = &ctx{nil, nil, ""}
+
+func getParentOrRoot(c context.Context) *ctx {
+	parent, ok := c.Value(CallerContext).(*ctx)
+	if !ok {
+		parent = root
+	}
+	return parent
+}
+
+func makeChild(c context.Context, child *ctx) context.Context {
+	if child.parent == nil {
+		panic(child)
+	}
+	return context.WithValue(c, CallerContext, child)
+}
+
+func Child(c context.Context, ident string) context.Context {
+	parent := getParentOrRoot(c)
+	return makeChild(c, &ctx{parent: parent, ident: ident})
+}
+
+func GetStack(c context.Context) (idents []string) {
+	ct, ok := c.Value(CallerContext).(*ctx)
+	if !ok {
+		return idents
+	}
+	for ct.parent != nil {
+		idents = append(idents, ct.ident)
+		ct = ct.parent
+	}
+	return idents
+}

tracing/tracing_test.go

@@ -0,0 +1,21 @@
+package tracing
+
+import (
+	"context"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestIt(t *testing.T) {
+	ctx := context.Background()
+
+	ctx = Child(ctx, "a")
+	ctx = Child(ctx, "b")
+	ctx = Child(ctx, "c")
+	ctx = Child(ctx, "d")
+
+	assert.Equal(t, "dcba", strings.Join(GetStack(ctx), ""))
+
+}