[WIP] factor out trace functionality into separate package and add Go docs

daemon/logging/build_logging.go

@@ -9,8 +9,8 @@ import (
 
 	"github.com/mattn/go-isatty"
 	"github.com/pkg/errors"
-
 	"github.com/zrepl/zrepl/config"
+	"github.com/zrepl/zrepl/daemon/logging/trace"
 	"github.com/zrepl/zrepl/logger"
 	"github.com/zrepl/zrepl/tlsconf"
 )
@@ -157,13 +157,7 @@ func getLoggerImpl(ctx context.Context, subsys Subsystem, panicIfEnded bool) log
 
 	l = l.WithField(SubsysField, subsys)
 
-	if nI := ctx.Value(contextKeyTraceNode); nI != nil {
-		n := nI.(*traceNode)
-		_, spanStack := currentTaskNameAndSpanStack(n)
-		l = l.WithField(SpanField, spanStack)
-	} else {
-		l = l.WithField(SpanField, "NOSPAN")
-	}
+	l = l.WithField(SpanField, trace.GetSpanStackOrDefault(ctx, "NOSPAN"))
 
 	fields := make(logger.Fields)
 	iterInjectedFields(ctx, func(field string, value interface{}) {

daemon/logging/logging_activity_trace_debug.go

@@ -1,15 +0,0 @@
-package logging
-
-import (
-	"fmt"
-	"os"
-)
-
-const chrometraceEnableDebug = false
-
-func chrometraceDebug(format string, args ...interface{}) {
-	if !chrometraceEnableDebug {
-		return
-	}
-	fmt.Fprintf(os.Stderr, format+"\n", args...)
-}

daemon/logging/logging_context.go

@@ -5,13 +5,11 @@ import "context"
 type contextKey int
 
 const (
-	contextKeyTraceNode contextKey = 1 + iota
-	contextKeyLoggers
+	contextKeyLoggers contextKey = 1 + iota
 	contextKeyInjectedField
 )
 
 var contextKeys = []contextKey{
-	contextKeyTraceNode,
 	contextKeyLoggers,
 	contextKeyInjectedField,
 }

daemon/logging/trace/trace.go

@@ -1,20 +1,103 @@
-package logging
+// package trace provides activity tracing via ctx through Tasks and Spans
+//
+// Basic Concepts
+//
+// Tracing can be used to identify where a piece of code spends its time.
+//
+// The Go standard library provides package runtime/trace which is useful to identify CPU bottlenecks or
+// to understand what happens inside the Go runtime.
+// However, it is not ideal for application level tracing, in particular if those traces should be understandable
+// to tech-savvy users (albeit not developers).
+//
+// This package provides the concept of Tasks and Spans to express what activity is happening within an application:
+//
+//  - Neither task nor span is really tangible but instead contained within the context.Context tree
+//  - Tasks represent concurrent activity (i.e. goroutines).
+//  - Spans represent a semantic stack trace within a task.
+//
+// As a consequence, whenever a context is propagated across goroutine boundary, you need to create a child task:
+//
+//   go func(ctx context.Context) {
+//     ctx, endTask = WithTask(ctx, "what-happens-inside-the-child-task")
+//     defer endTask()
+//     // ...
+//   }(ctx)
+//
+// Within the task, you can open up a hierarchy of spans.
+// In contrast to tasks, which have can multiple concurrently running child tasks,
+// spans must nest and not cross the goroutine boundary.
+//
+//  ctx, endSpan = WithSpan(ctx, "copy-dir")
+//  defer endSpan()
+//  for _, f := range dir.Files() {
+//    func() {
+//      ctx, endSpan := WithSpan(ctx, fmt.Sprintf("copy-file %q", f))
+//      defer endspan()
+//      b, _ := ioutil.ReadFile(f)
+//      _ = ioutil.WriteFile(f + ".copy", b, 0600)
+//    }()
+//  }
+//
+// In combination:
+//  ctx, endTask = WithTask(ctx, "copy-dirs")
+//  defer endTask()
+//  for i := range dirs {
+//    go func(dir string) {
+//      ctx, endTask := WithTask(ctx, "copy-dir")
+//      defer endTask()
+//      for _, f := range filesIn(dir) {
+//        func() {
+//          ctx, endSpan := WithSpan(ctx, fmt.Sprintf("copy-file %q", f))
+//          defer endspan()
+//          b, _ := ioutil.ReadFile(f)
+//          _ = ioutil.WriteFile(f + ".copy", b, 0600)
+//        }()
+//      }
+//    }()
+//  }
+//
+// Note that a span ends at the time you call endSpan - not before and not after that.
+// If you violate the stack-like nesting of spans by forgetting an endSpan() invocation,
+// the out-of-order endSpan() will panic.
+//
+// A similar rule applies to the endTask closure returned by WithTask:
+// If a task has live child tasks at the time you call endTask(), the call will panic.
+//
+// Recovering from endSpan() or endTask() panics will corrupt the trace stack and lead to corrupt tracefile output.
+//
+//
+// Best Practices For Naming Tasks And Spans
+//
+// Tasks should always have string constants as names, and must not contain the `#` character. WHy?
+// First, the visualization by chrome://tracing draws a horizontal bar for each task in the trace.
+// Also, the package appends `#NUM` for each concurrently running instance of a task name.
+// Note that the `#NUM` suffix will be reused if a task has ended, in order to avoid an
+// infinite number of horizontal bars in the visualization.
+//
+//
+// Chrome-compatible Tracefile Support
+//
+// The activity trace generated by usage of WithTask and WithSpan can be rendered to a JSON output file
+// that can be loaded into chrome://tracing .
+// Apart from function GetSpanStackOrDefault, this is the main benefit of this package.
+//
+// First, there is a convenience environment variable 'ZREPL_ACTIVITY_TRACE' that can be set to an output path.
+// From process start onward, a trace is written to that path.
+//
+// More consumers can attach to the activity trace through the ChrometraceClientWebsocketHandler websocket handler.
+//
+// If a write error is encountered with any consumer (including the env-var based one), the consumer is closed and
+// will not receive further trace output.
+package trace
 
 import (
 	"context"
-	"encoding/base64"
 	"fmt"
-	"math/rand"
-	"os"
-	"runtime"
 	"strings"
-	"sync"
 	"sync/atomic"
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
-
-	"github.com/zrepl/zrepl/util/envconst"
 )
 
 var metrics struct {
@@ -25,13 +108,13 @@ var metrics struct {
 func init() {
 	metrics.activeTasks = prometheus.NewGauge(prometheus.GaugeOpts{
 		Namespace: "zrepl",
-		Subsystem: "logging",
+		Subsystem: "trace",
 		Name:      "active_tasks",
 		Help:      "number of active (tracing-level) tasks in the daemon",
 	})
 	metrics.uniqueConcurrentTaskNameBitvecLength = prometheus.NewGaugeVec(prometheus.GaugeOpts{
 		Namespace: "zrepl",
-		Subsystem: "logging",
+		Subsystem: "trace",
 		Name:      "unique_concurrent_task_name_bitvec_length",
 		Help:      "length of the bitvec used to find unique names for concurrent tasks",
 	}, []string{"task_name"})
@@ -42,75 +125,27 @@ func RegisterMetrics(r prometheus.Registerer) {
 	r.MustRegister(metrics.uniqueConcurrentTaskNameBitvecLength)
 }
 
-type DoneFunc func()
-
-func getMyCallerOrPanic() string {
-	pc, _, _, ok := runtime.Caller(2)
-	if !ok {
-		panic("cannot get caller")
-	}
-	details := runtime.FuncForPC(pc)
-	if ok && details != nil {
-		const prefix = "github.com/zrepl/zrepl"
-		return strings.TrimPrefix(strings.TrimPrefix(details.Name(), prefix), "/")
-	}
-	return ""
-}
-
-// use like this:
-//
-//	defer WithSpanFromStackUpdateCtx(&existingCtx)()
-//
-//
-func WithSpanFromStackUpdateCtx(ctx *context.Context) DoneFunc {
-	childSpanCtx, end := WithSpan(*ctx, getMyCallerOrPanic())
-	*ctx = childSpanCtx
-	return end
-}
-
-// derive task name from call stack (caller's name)
-func WithTaskFromStack(ctx context.Context) (context.Context, DoneFunc) {
-	return WithTask(ctx, getMyCallerOrPanic())
-}
-
-// derive task name from call stack (caller's name) and update *ctx
-// to point to be the child task ctx
-func WithTaskFromStackUpdateCtx(ctx *context.Context) DoneFunc {
-	child, end := WithTask(*ctx, getMyCallerOrPanic())
-	*ctx = child
-	return end
-}
-
-// create a task and a span within it in one call
-func WithTaskAndSpan(ctx context.Context, task string, span string) (context.Context, DoneFunc) {
-	ctx, endTask := WithTask(ctx, task)
-	ctx, endSpan := WithSpan(ctx, fmt.Sprintf("%s %s", task, span))
-	return ctx, func() {
-		endSpan()
-		endTask()
-	}
-}
-
-// create a span during which several child tasks are spawned using the `add` function
-func WithTaskGroup(ctx context.Context, taskGroup string) (_ context.Context, add func(f func(context.Context)), waitEnd func()) {
-	var wg sync.WaitGroup
-	ctx, endSpan := WithSpan(ctx, taskGroup)
-	add = func(f func(context.Context)) {
-		wg.Add(1)
-		defer wg.Done()
-		ctx, endTask := WithTask(ctx, taskGroup)
-		defer endTask()
-		f(ctx)
-	}
-	waitEnd = func() {
-		wg.Wait()
-		endSpan()
-	}
-	return ctx, add, waitEnd
-}
-
 var taskNamer = newUniqueTaskNamer(metrics.uniqueConcurrentTaskNameBitvecLength)
 
+type traceNode struct {
+	id                 string
+	annotation         string
+	parentTask         *traceNode
+	activeChildTasks   int32 // only for task nodes, insignificant for span nodes
+	parentSpan         *traceNode
+	hasActiveChildSpan int32
+
+	startedAt time.Time
+	endedAt   time.Time
+	ended     int32
+}
+
+// Returned from WithTask or WithSpan.
+// Must be called once the task or span ends.
+// See package-level docs for nesting rules.
+// Wrong call order / forgetting to call it will result in panics.
+type DoneFunc func()
+
 // Start a new root task or create a child task of an existing task.
 //
 // This is required when starting a new goroutine and
@@ -137,7 +172,7 @@ func WithTask(ctx context.Context, taskName string) (context.Context, DoneFunc)
 	taskName, taskNameDone := taskNamer.UniqueConcurrentTaskName(taskName)
 
 	this := &traceNode{
-		id:                 newTraceNodeId(),
+		id:                 genID(),
 		annotation:         taskName,
 		parentTask:         parentTask,
 		activeChildTasks:   0,
@@ -185,9 +220,8 @@ func WithTask(ctx context.Context, taskName string) (context.Context, DoneFunc)
 	return ctx, endTaskFunc
 }
 
-// ctx must have an active task (see WithTask)
-//
-// spans must nest (stack-like), otherwise, this function panics
+// Start a new span.
+// Important: ctx must have an active task (see WithTask)
 func WithSpan(ctx context.Context, annotation string) (context.Context, DoneFunc) {
 	var parentSpan, parentTask *traceNode
 	nodeI := ctx.Value(contextKeyTraceNode)
@@ -203,7 +237,7 @@ func WithSpan(ctx context.Context, annotation string) (context.Context, DoneFunc
 	}
 
 	this := &traceNode{
-		id:                 newTraceNodeId(),
+		id:                 genID(),
 		annotation:         annotation,
 		parentTask:         parentTask,
 		parentSpan:         parentSpan,
@@ -233,19 +267,6 @@ func WithSpan(ctx context.Context, annotation string) (context.Context, DoneFunc
 	return ctx, endTaskFunc
 }
 
-type traceNode struct {
-	id                 string
-	annotation         string
-	parentTask         *traceNode
-	activeChildTasks   int32 // only for task nodes, insignificant for span nodes
-	parentSpan         *traceNode
-	hasActiveChildSpan int32
-
-	startedAt time.Time
-	endedAt   time.Time
-	ended     int32
-}
-
 func currentTaskNameAndSpanStack(this *traceNode) (taskName string, spanIdStack string) {
 
 	task := this.parentTask
@@ -279,38 +300,12 @@ func currentTaskNameAndSpanStack(this *traceNode) (taskName string, spanIdStack
 	return task.annotation, spanIdStack
 }
 
-var traceNodeIdPRNG = rand.New(rand.NewSource(1))
-
-func init() {
-	traceNodeIdPRNG.Seed(time.Now().UnixNano())
-	traceNodeIdPRNG.Seed(int64(os.Getpid()))
-}
-
-var traceNodeIdBytes = envconst.Int("ZREPL_LOGGING_TRACE_ID_BYTES", 3)
-
-func init() {
-	if traceNodeIdBytes < 1 {
-		panic("trace node id byte length must be at least 1")
+func GetSpanStackOrDefault(ctx context.Context, def string) string {
+	if nI := ctx.Value(contextKeyTraceNode); nI != nil {
+		n := nI.(*traceNode)
+		_, spanStack := currentTaskNameAndSpanStack(n)
+		return spanStack
+	} else {
+		return def
 	}
 }
-
-func newTraceNodeId() string {
-	var out strings.Builder
-	enc := base64.NewEncoder(base64.RawStdEncoding, &out)
-	buf := make([]byte, traceNodeIdBytes)
-	for i := 0; i < len(buf); {
-		n, err := traceNodeIdPRNG.Read(buf[i:])
-		if err != nil {
-			panic(err)
-		}
-		i += n
-	}
-	n, err := enc.Write(buf[:])
-	if err != nil || n != len(buf) {
-		panic(err)
-	}
-	if err := enc.Close(); err != nil {
-		panic(err)
-	}
-	return out.String()
-}

daemon/logging/trace/trace_chrometrace.go

@@ -1,4 +1,4 @@
-package logging
+package trace
 
 // The functions in this file are concerned with the generation
 // of trace files based on the information from WithTask and WithSpan.
@@ -134,7 +134,7 @@ func init() {
 	chrometraceConsumers.write = make(chan []byte)
 	go func() {
 		kickConsumer := func(c chrometraceConsumerRegistration, err error) {
-			chrometraceDebug("chrometrace kicking consumer %#v after error %v", c, err)
+			debug("chrometrace kicking consumer %#v after error %v", c, err)
 			select {
 			case c.errored <- err:
 			default:
@@ -145,7 +145,7 @@ func init() {
 		for {
 			select {
 			case reg := <-chrometraceConsumers.register:
-				chrometraceDebug("registered chrometrace consumer %#v", reg)
+				debug("registered chrometrace consumer %#v", reg)
 				chrometraceConsumers.consumers[reg] = true
 				n, err := reg.w.Write([]byte("[\n"))
 				if err != nil {
@@ -156,12 +156,12 @@ func init() {
 				// successfully registered
 
 			case buf := <-chrometraceConsumers.write:
-				chrometraceDebug("chrometrace write request: %s", string(buf))
+				debug("chrometrace write request: %s", string(buf))
 				var r bytes.Reader
 				for c := range chrometraceConsumers.consumers {
 					r.Reset(buf)
 					n, err := io.Copy(c.w, &r)
-					chrometraceDebug("chrometrace wrote n=%v bytes to consumer %#v", n, c)
+					debug("chrometrace wrote n=%v bytes to consumer %#v", n, c)
 					if err != nil {
 						kickConsumer(c, err)
 					}

daemon/logging/trace/trace_context.go

@@ -0,0 +1,27 @@
+package trace
+
+import "context"
+
+type contextKey int
+
+const (
+	contextKeyTraceNode contextKey = 1 + iota
+)
+
+var contextKeys = []contextKey{
+	contextKeyTraceNode,
+}
+
+// WithInherit inherits the task hierarchy from inheritFrom into ctx.
+// The returned context is a child of ctx, but its task and span are those of inheritFrom.
+//
+// Note that in most use cases, callers most likely want to call WithTask since it will most likely
+// be in some sort of connection handler context.
+func WithInherit(ctx, inheritFrom context.Context) context.Context {
+	for _, k := range contextKeys {
+		if v := inheritFrom.Value(k); v != nil {
+			ctx = context.WithValue(ctx, k, v) // no shadow
+		}
+	}
+	return ctx
+}

daemon/logging/trace/trace_convenience.go

@@ -0,0 +1,74 @@
+package trace
+
+import (
+	"context"
+	"fmt"
+	"runtime"
+	"strings"
+	"sync"
+)
+
+// use like this:
+//
+//	defer WithSpanFromStackUpdateCtx(&existingCtx)()
+//
+//
+func WithSpanFromStackUpdateCtx(ctx *context.Context) DoneFunc {
+	childSpanCtx, end := WithSpan(*ctx, getMyCallerOrPanic())
+	*ctx = childSpanCtx
+	return end
+}
+
+// derive task name from call stack (caller's name)
+func WithTaskFromStack(ctx context.Context) (context.Context, DoneFunc) {
+	return WithTask(ctx, getMyCallerOrPanic())
+}
+
+// derive task name from call stack (caller's name) and update *ctx
+// to point to be the child task ctx
+func WithTaskFromStackUpdateCtx(ctx *context.Context) DoneFunc {
+	child, end := WithTask(*ctx, getMyCallerOrPanic())
+	*ctx = child
+	return end
+}
+
+// create a task and a span within it in one call
+func WithTaskAndSpan(ctx context.Context, task string, span string) (context.Context, DoneFunc) {
+	ctx, endTask := WithTask(ctx, task)
+	ctx, endSpan := WithSpan(ctx, fmt.Sprintf("%s %s", task, span))
+	return ctx, func() {
+		endSpan()
+		endTask()
+	}
+}
+
+// create a span during which several child tasks are spawned using the `add` function
+func WithTaskGroup(ctx context.Context, taskGroup string) (_ context.Context, add func(f func(context.Context)), waitEnd DoneFunc) {
+	var wg sync.WaitGroup
+	ctx, endSpan := WithSpan(ctx, taskGroup)
+	add = func(f func(context.Context)) {
+		wg.Add(1)
+		defer wg.Done()
+		ctx, endTask := WithTask(ctx, taskGroup)
+		defer endTask()
+		f(ctx)
+	}
+	waitEnd = func() {
+		wg.Wait()
+		endSpan()
+	}
+	return ctx, add, waitEnd
+}
+
+func getMyCallerOrPanic() string {
+	pc, _, _, ok := runtime.Caller(2)
+	if !ok {
+		panic("cannot get caller")
+	}
+	details := runtime.FuncForPC(pc)
+	if ok && details != nil {
+		const prefix = "github.com/zrepl/zrepl"
+		return strings.TrimPrefix(strings.TrimPrefix(details.Name(), prefix), "/")
+	}
+	return ""
+}

daemon/logging/trace/trace_convenience_test.go

@@ -1,4 +1,4 @@
-package logging
+package trace
 
 import (
 	"testing"
@@ -12,5 +12,5 @@ func TestGetCallerOrPanic(t *testing.T) {
 	}
 	ret := withStackFromCtxMock()
 	// zrepl prefix is stripped
-	assert.Equal(t, "daemon/logging.TestGetCallerOrPanic", ret)
+	assert.Equal(t, "daemon/logging/trace.TestGetCallerOrPanic", ret)
 }

daemon/logging/trace/trace_debug.go

@@ -0,0 +1,15 @@
+package trace
+
+import (
+	"fmt"
+	"os"
+)
+
+const debugEnabled = false
+
+func debug(format string, args ...interface{}) {
+	if !debugEnabled {
+		return
+	}
+	fmt.Fprintf(os.Stderr, format+"\n", args...)
+}

daemon/logging/trace/trace_genID.go

@@ -0,0 +1,47 @@
+package trace
+
+import (
+	"encoding/base64"
+	"math/rand"
+	"os"
+	"strings"
+	"time"
+
+	"github.com/zrepl/zrepl/util/envconst"
+)
+
+var genIdPRNG = rand.New(rand.NewSource(1))
+
+func init() {
+	genIdPRNG.Seed(time.Now().UnixNano())
+	genIdPRNG.Seed(int64(os.Getpid()))
+}
+
+var genIdNumBytes = envconst.Int("ZREPL_TRACE_ID_NUM_BYTES", 3)
+
+func init() {
+	if genIdNumBytes < 1 {
+		panic("trace node id byte length must be at least 1")
+	}
+}
+
+func genID() string {
+	var out strings.Builder
+	enc := base64.NewEncoder(base64.RawStdEncoding, &out)
+	buf := make([]byte, genIdNumBytes)
+	for i := 0; i < len(buf); {
+		n, err := genIdPRNG.Read(buf[i:])
+		if err != nil {
+			panic(err)
+		}
+		i += n
+	}
+	n, err := enc.Write(buf[:])
+	if err != nil || n != len(buf) {
+		panic(err)
+	}
+	if err := enc.Close(); err != nil {
+		panic(err)
+	}
+	return out.String()
+}

daemon/logging/trace/trace_unique_concurrent_task_namer.go

@@ -1,4 +1,4 @@
-package logging
+package trace
 
 import (
 	"fmt"

daemon/logging/trace/trace_unique_concurrent_task_namer_test.go

@@ -1,4 +1,4 @@
-package logging
+package trace
 
 import (
 	"fmt"