move implementation to internal/ directory (#828)

internal/daemon/logging/build_logging.go

@@ -0,0 +1,303 @@
+package logging
+
+import (
+	"context"
+	"crypto/tls"
+	"crypto/x509"
+	"log/syslog"
+	"os"
+
+	"github.com/mattn/go-isatty"
+	"github.com/pkg/errors"
+
+	"github.com/zrepl/zrepl/internal/config"
+	"github.com/zrepl/zrepl/internal/daemon/logging/trace"
+	"github.com/zrepl/zrepl/internal/logger"
+	"github.com/zrepl/zrepl/internal/tlsconf"
+)
+
+func OutletsFromConfig(in config.LoggingOutletEnumList) (*logger.Outlets, error) {
+
+	outlets := logger.NewOutlets()
+
+	if len(in) == 0 {
+		// Default config
+		out := WriterOutlet{&HumanFormatter{}, os.Stdout}
+		outlets.Add(out, logger.Warn)
+		return outlets, nil
+	}
+
+	var syslogOutlets, stdoutOutlets int
+	for lei, le := range in {
+
+		outlet, minLevel, err := ParseOutlet(le)
+		if err != nil {
+			return nil, errors.Wrapf(err, "cannot parse outlet #%d", lei)
+		}
+		var _ logger.Outlet = WriterOutlet{}
+		var _ logger.Outlet = &SyslogOutlet{}
+		switch outlet.(type) {
+		case *SyslogOutlet:
+			syslogOutlets++
+		case WriterOutlet:
+			stdoutOutlets++
+		}
+
+		outlets.Add(outlet, minLevel)
+
+	}
+
+	if syslogOutlets > 1 {
+		return nil, errors.Errorf("can only define one 'syslog' outlet")
+	}
+	if stdoutOutlets > 1 {
+		return nil, errors.Errorf("can only define one 'stdout' outlet")
+	}
+
+	return outlets, nil
+
+}
+
+type Subsystem string
+
+const (
+	SubsysMeta         Subsystem = "meta"
+	SubsysJob          Subsystem = "job"
+	SubsysReplication  Subsystem = "repl"
+	SubsysEndpoint     Subsystem = "endpoint"
+	SubsysPruning      Subsystem = "pruning"
+	SubsysSnapshot     Subsystem = "snapshot"
+	SubsysHooks        Subsystem = "hook"
+	SubsysTransport    Subsystem = "transport"
+	SubsysTransportMux Subsystem = "transportmux"
+	SubsysRPC          Subsystem = "rpc"
+	SubsysRPCControl   Subsystem = "rpc.ctrl"
+	SubsysRPCData      Subsystem = "rpc.data"
+	SubsysZFSCmd       Subsystem = "zfs.cmd"
+	SubsysTraceData    Subsystem = "trace.data"
+	SubsysPlatformtest Subsystem = "platformtest"
+)
+
+var AllSubsystems = []Subsystem{
+	SubsysMeta,
+	SubsysJob,
+	SubsysReplication,
+	SubsysEndpoint,
+	SubsysPruning,
+	SubsysSnapshot,
+	SubsysHooks,
+	SubsysTransport,
+	SubsysTransportMux,
+	SubsysRPC,
+	SubsysRPCControl,
+	SubsysRPCData,
+	SubsysZFSCmd,
+	SubsysTraceData,
+	SubsysPlatformtest,
+}
+
+type injectedField struct {
+	field  string
+	value  interface{}
+	parent *injectedField
+}
+
+func WithInjectedField(ctx context.Context, field string, value interface{}) context.Context {
+	var parent *injectedField
+	parentI := ctx.Value(contextKeyInjectedField)
+	if parentI != nil {
+		parent = parentI.(*injectedField)
+	}
+	// TODO sanity-check `field` now
+	this := &injectedField{field, value, parent}
+	return context.WithValue(ctx, contextKeyInjectedField, this)
+}
+
+func iterInjectedFields(ctx context.Context, cb func(field string, value interface{})) {
+	injI := ctx.Value(contextKeyInjectedField)
+	if injI == nil {
+		return
+	}
+	inj := injI.(*injectedField)
+	for ; inj != nil; inj = inj.parent {
+		cb(inj.field, inj.value)
+	}
+}
+
+type SubsystemLoggers map[Subsystem]logger.Logger
+
+func SubsystemLoggersWithUniversalLogger(l logger.Logger) SubsystemLoggers {
+	loggers := make(SubsystemLoggers)
+	for _, s := range AllSubsystems {
+		loggers[s] = l
+	}
+	return loggers
+}
+
+func WithLoggers(ctx context.Context, loggers SubsystemLoggers) context.Context {
+	return context.WithValue(ctx, contextKeyLoggers, loggers)
+}
+
+func GetLoggers(ctx context.Context) SubsystemLoggers {
+	loggers, ok := ctx.Value(contextKeyLoggers).(SubsystemLoggers)
+	if !ok {
+		return nil
+	}
+	return loggers
+}
+
+func GetLogger(ctx context.Context, subsys Subsystem) logger.Logger {
+	return getLoggerImpl(ctx, subsys, true)
+}
+
+func getLoggerImpl(ctx context.Context, subsys Subsystem, panicIfEnded bool) logger.Logger {
+	loggers, ok := ctx.Value(contextKeyLoggers).(SubsystemLoggers)
+	if !ok || loggers == nil {
+		return logger.NewNullLogger()
+	}
+	l, ok := loggers[subsys]
+	if !ok {
+		return logger.NewNullLogger()
+	}
+
+	l = l.WithField(SubsysField, subsys)
+
+	l = l.WithField(SpanField, trace.GetSpanStackOrDefault(ctx, *trace.StackKindId, "NOSPAN"))
+
+	fields := make(logger.Fields)
+	iterInjectedFields(ctx, func(field string, value interface{}) {
+		fields[field] = value
+	})
+	l = l.WithFields(fields)
+
+	return l
+}
+
+func parseLogFormat(i interface{}) (f EntryFormatter, err error) {
+	var is string
+	switch j := i.(type) {
+	case string:
+		is = j
+	default:
+		return nil, errors.Errorf("invalid log format: wrong type: %T", i)
+	}
+
+	switch is {
+	case "human":
+		return &HumanFormatter{}, nil
+	case "logfmt":
+		return &LogfmtFormatter{}, nil
+	case "json":
+		return &JSONFormatter{}, nil
+	default:
+		return nil, errors.Errorf("invalid log format: '%s'", is)
+	}
+
+}
+
+func ParseOutlet(in config.LoggingOutletEnum) (o logger.Outlet, level logger.Level, err error) {
+
+	parseCommon := func(common config.LoggingOutletCommon) (logger.Level, EntryFormatter, error) {
+		if common.Level == "" || common.Format == "" {
+			return 0, nil, errors.Errorf("must specify 'level' and 'format' field")
+		}
+
+		minLevel, err := logger.ParseLevel(common.Level)
+		if err != nil {
+			return 0, nil, errors.Wrap(err, "cannot parse 'level' field")
+		}
+		formatter, err := parseLogFormat(common.Format)
+		if err != nil {
+			return 0, nil, errors.Wrap(err, "cannot parse 'formatter' field")
+		}
+		return minLevel, formatter, nil
+	}
+
+	var f EntryFormatter
+
+	switch v := in.Ret.(type) {
+	case *config.StdoutLoggingOutlet:
+		level, f, err = parseCommon(v.LoggingOutletCommon)
+		if err != nil {
+			break
+		}
+		o, err = parseStdoutOutlet(v, f)
+	case *config.TCPLoggingOutlet:
+		level, f, err = parseCommon(v.LoggingOutletCommon)
+		if err != nil {
+			break
+		}
+		o, err = parseTCPOutlet(v, f)
+	case *config.SyslogLoggingOutlet:
+		level, f, err = parseCommon(v.LoggingOutletCommon)
+		if err != nil {
+			break
+		}
+		o, err = parseSyslogOutlet(v, f)
+	default:
+		panic(v)
+	}
+	return o, level, err
+}
+
+func parseStdoutOutlet(in *config.StdoutLoggingOutlet, formatter EntryFormatter) (WriterOutlet, error) {
+	flags := MetadataAll
+	writer := os.Stdout
+	if !isatty.IsTerminal(writer.Fd()) && !in.Time {
+		flags &= ^MetadataTime
+	}
+	if isatty.IsTerminal(writer.Fd()) && !in.Color {
+		flags &= ^MetadataColor
+	}
+
+	formatter.SetMetadataFlags(flags)
+	return WriterOutlet{
+		formatter,
+		os.Stdout,
+	}, nil
+}
+
+func parseTCPOutlet(in *config.TCPLoggingOutlet, formatter EntryFormatter) (out *TCPOutlet, err error) {
+	var tlsConfig *tls.Config
+	if in.TLS != nil {
+		tlsConfig, err = func(m *config.TCPLoggingOutletTLS, host string) (*tls.Config, error) {
+			clientCert, err := tls.LoadX509KeyPair(m.Cert, m.Key)
+			if err != nil {
+				return nil, errors.Wrap(err, "cannot load client cert")
+			}
+
+			var rootCAs *x509.CertPool
+			if m.CA == "" {
+				if rootCAs, err = x509.SystemCertPool(); err != nil {
+					return nil, errors.Wrap(err, "cannot open system cert pool")
+				}
+			} else {
+				rootCAs, err = tlsconf.ParseCAFile(m.CA)
+				if err != nil {
+					return nil, errors.Wrap(err, "cannot parse CA cert")
+				}
+			}
+			if rootCAs == nil {
+				panic("invariant violated")
+			}
+
+			return tlsconf.ClientAuthClient(host, rootCAs, clientCert)
+		}(in.TLS, in.Address)
+		if err != nil {
+			return nil, errors.New("cannot not parse TLS config in field 'tls'")
+		}
+	}
+
+	formatter.SetMetadataFlags(MetadataAll)
+	return NewTCPOutlet(formatter, in.Net, in.Address, tlsConfig, in.RetryInterval), nil
+
+}
+
+func parseSyslogOutlet(in *config.SyslogLoggingOutlet, formatter EntryFormatter) (out *SyslogOutlet, err error) {
+	out = &SyslogOutlet{}
+	out.Formatter = formatter
+	out.Formatter.SetMetadataFlags(MetadataNone)
+	out.Facility = syslog.Priority(*in.Facility)
+	out.RetryInterval = in.RetryInterval
+	return out, nil
+}

internal/daemon/logging/logging_context.go

@@ -0,0 +1,24 @@
+package logging
+
+import "context"
+
+type contextKey int
+
+const (
+	contextKeyLoggers contextKey = 1 + iota
+	contextKeyInjectedField
+)
+
+var contextKeys = []contextKey{
+	contextKeyLoggers,
+	contextKeyInjectedField,
+}
+
+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
+}

internal/daemon/logging/logging_formatters.go

@@ -0,0 +1,221 @@
+package logging
+
+import (
+	"bytes"
+	"encoding/json"
+	"fmt"
+	"time"
+
+	"github.com/fatih/color"
+	"github.com/go-logfmt/logfmt"
+	"github.com/pkg/errors"
+
+	"github.com/zrepl/zrepl/internal/logger"
+)
+
+const (
+	FieldLevel   = "level"
+	FieldMessage = "msg"
+	FieldTime    = "time"
+)
+
+const (
+	JobField    string = "job"
+	SubsysField string = "subsystem"
+	SpanField   string = "span"
+)
+
+type MetadataFlags int64
+
+const (
+	MetadataTime MetadataFlags = 1 << iota
+	MetadataLevel
+	MetadataColor
+
+	MetadataNone MetadataFlags = 0
+	MetadataAll  MetadataFlags = ^0
+)
+
+type NoFormatter struct{}
+
+func (f NoFormatter) SetMetadataFlags(flags MetadataFlags) {}
+
+func (f NoFormatter) Format(e *logger.Entry) ([]byte, error) {
+	return []byte(e.Message), nil
+}
+
+type HumanFormatter struct {
+	metadataFlags MetadataFlags
+	ignoreFields  map[string]bool
+}
+
+const HumanFormatterDateFormat = time.RFC3339
+
+func (f *HumanFormatter) SetMetadataFlags(flags MetadataFlags) {
+	f.metadataFlags = flags
+}
+
+func (f *HumanFormatter) SetIgnoreFields(ignore []string) {
+	if ignore == nil {
+		f.ignoreFields = nil
+		return
+	}
+	f.ignoreFields = make(map[string]bool, len(ignore))
+
+	for _, field := range ignore {
+		f.ignoreFields[field] = true
+	}
+}
+
+func (f *HumanFormatter) ignored(field string) bool {
+	return f.ignoreFields != nil && f.ignoreFields[field]
+}
+
+func (f *HumanFormatter) Format(e *logger.Entry) (out []byte, err error) {
+
+	var line bytes.Buffer
+	col := color.New()
+	if f.metadataFlags&MetadataColor != 0 {
+		col = e.Color()
+	}
+
+	if f.metadataFlags&MetadataTime != 0 {
+		fmt.Fprintf(&line, "%s ", e.Time.Format(HumanFormatterDateFormat))
+	}
+	if f.metadataFlags&MetadataLevel != 0 {
+		fmt.Fprintf(&line, "[%s]", col.Sprint(e.Level.Short()))
+	}
+
+	prefixFields := []string{JobField, SubsysField, SpanField}
+	prefixed := make(map[string]bool, len(prefixFields)+2)
+	for _, field := range prefixFields {
+		val, ok := e.Fields[field]
+		if !ok {
+			continue
+		}
+		if !f.ignored(field) {
+			fmt.Fprintf(&line, "[%s]", col.Sprint(val))
+			prefixed[field] = true
+		}
+	}
+
+	if line.Len() > 0 {
+		fmt.Fprint(&line, ": ")
+	}
+	fmt.Fprint(&line, e.Message)
+
+	if len(e.Fields)-len(prefixed) > 0 {
+		for field, value := range e.Fields {
+			if prefixed[field] || f.ignored(field) {
+				continue
+			}
+			fmt.Fprintf(&line, " %s=%q", col.Sprint(field), fmt.Sprint(value))
+		}
+	}
+
+	return line.Bytes(), nil
+}
+
+type JSONFormatter struct {
+	metadataFlags MetadataFlags
+}
+
+func (f *JSONFormatter) SetMetadataFlags(flags MetadataFlags) {
+	f.metadataFlags = flags
+}
+
+func (f *JSONFormatter) Format(e *logger.Entry) ([]byte, error) {
+	data := make(logger.Fields, len(e.Fields)+3)
+	for k, v := range e.Fields {
+		switch v := v.(type) {
+		case error:
+			// Otherwise errors are ignored by `encoding/json`
+			// https://github.com/sirupsen/logrus/issues/137
+			data[k] = v.Error()
+		default:
+			_, err := json.Marshal(v)
+			if err != nil {
+				return nil, errors.Errorf("field is not JSON encodable: %s", k)
+			}
+			data[k] = v
+		}
+	}
+
+	data[FieldMessage] = e.Message
+	data[FieldTime] = e.Time.Format(time.RFC3339)
+	data[FieldLevel] = e.Level
+
+	return json.Marshal(data)
+
+}
+
+type LogfmtFormatter struct {
+	metadataFlags MetadataFlags
+}
+
+func (f *LogfmtFormatter) SetMetadataFlags(flags MetadataFlags) {
+	f.metadataFlags = flags
+}
+
+func (f *LogfmtFormatter) Format(e *logger.Entry) ([]byte, error) {
+	var buf bytes.Buffer
+	enc := logfmt.NewEncoder(&buf)
+
+	if f.metadataFlags&MetadataTime != 0 {
+		err := enc.EncodeKeyval(FieldTime, e.Time)
+		if err != nil {
+			return nil, errors.Wrap(err, "logfmt: encode time")
+		}
+	}
+	if f.metadataFlags&MetadataLevel != 0 {
+		err := enc.EncodeKeyval(FieldLevel, e.Level)
+		if err != nil {
+			return nil, errors.Wrap(err, "logfmt: encode level")
+		}
+	}
+
+	// at least try and put job and task in front
+	prefixed := make(map[string]bool, 3)
+	prefix := []string{JobField, SubsysField, SpanField}
+	for _, pf := range prefix {
+		v, ok := e.Fields[pf]
+		if !ok {
+			break
+		}
+		if err := logfmtTryEncodeKeyval(enc, pf, v); err != nil {
+			return nil, err // unlikely
+		}
+		prefixed[pf] = true
+	}
+
+	err := enc.EncodeKeyval(FieldMessage, e.Message)
+	if err != nil {
+		return nil, errors.Wrap(err, "logfmt: encode message")
+	}
+	for k, v := range e.Fields {
+		if !prefixed[k] {
+			if err := logfmtTryEncodeKeyval(enc, k, v); err != nil {
+				return nil, err
+			}
+		}
+	}
+
+	return buf.Bytes(), nil
+}
+
+func logfmtTryEncodeKeyval(enc *logfmt.Encoder, field, value interface{}) error {
+
+	err := enc.EncodeKeyval(field, value)
+	switch err {
+	case nil: // ok
+		return nil
+	case logfmt.ErrUnsupportedValueType:
+		err := enc.EncodeKeyval(field, fmt.Sprintf("<%T>", value))
+		if err != nil {
+			return errors.Wrap(err, "cannot encode unsupported value type Go type")
+		}
+		return nil
+	}
+	return errors.Wrapf(err, "cannot encode field '%s'", field)
+
+}

internal/daemon/logging/logging_outlets.go

@@ -0,0 +1,174 @@
+package logging
+
+import (
+	"bytes"
+	"context"
+	"crypto/tls"
+	"io"
+	"log/syslog"
+	"net"
+	"time"
+
+	"github.com/pkg/errors"
+
+	"github.com/zrepl/zrepl/internal/logger"
+)
+
+type EntryFormatter interface {
+	SetMetadataFlags(flags MetadataFlags)
+	Format(e *logger.Entry) ([]byte, error)
+}
+
+type WriterOutlet struct {
+	formatter EntryFormatter
+	writer    io.Writer
+}
+
+func (h WriterOutlet) WriteEntry(entry logger.Entry) error {
+	bytes, err := h.formatter.Format(&entry)
+	if err != nil {
+		return err
+	}
+	_, err = h.writer.Write(bytes)
+	if err != nil {
+		return err
+	}
+	_, err = h.writer.Write([]byte("\n"))
+	return err
+}
+
+type TCPOutlet struct {
+	formatter EntryFormatter
+	// Specifies how much time must pass between a connection error and a reconnection attempt
+	// Log entries written to the outlet during this time interval are silently dropped.
+	connect   func(ctx context.Context) (net.Conn, error)
+	entryChan chan *bytes.Buffer
+}
+
+func NewTCPOutlet(formatter EntryFormatter, network, address string, tlsConfig *tls.Config, retryInterval time.Duration) *TCPOutlet {
+
+	connect := func(ctx context.Context) (conn net.Conn, err error) {
+		deadl, ok := ctx.Deadline()
+		if !ok {
+			deadl = time.Time{}
+		}
+		dialer := net.Dialer{
+			Deadline: deadl,
+		}
+		if tlsConfig != nil {
+			conn, err = tls.DialWithDialer(&dialer, network, address, tlsConfig)
+		} else {
+			conn, err = dialer.DialContext(ctx, network, address)
+		}
+		return
+	}
+
+	entryChan := make(chan *bytes.Buffer, 1) // allow one message in flight while previous is in io.Copy()
+
+	o := &TCPOutlet{
+		formatter: formatter,
+		connect:   connect,
+		entryChan: entryChan,
+	}
+
+	go o.outLoop(retryInterval)
+
+	return o
+}
+
+// FIXME: use this method
+func (h *TCPOutlet) Close() {
+	close(h.entryChan)
+}
+
+func (h *TCPOutlet) outLoop(retryInterval time.Duration) {
+
+	var retry time.Time
+	var conn net.Conn
+	for msg := range h.entryChan {
+		var err error
+		for conn == nil {
+			time.Sleep(time.Until(retry))
+			ctx, cancel := context.WithDeadline(context.TODO(), time.Now().Add(retryInterval))
+			conn, err = h.connect(ctx)
+			cancel()
+			if err != nil {
+				retry = time.Now().Add(retryInterval)
+				conn = nil
+			}
+		}
+		err = conn.SetWriteDeadline(time.Now().Add(retryInterval))
+		if err == nil {
+			_, err = io.Copy(conn, msg)
+		}
+		if err != nil {
+			retry = time.Now().Add(retryInterval)
+			conn.Close()
+			conn = nil
+		}
+	}
+}
+
+func (h *TCPOutlet) WriteEntry(e logger.Entry) error {
+
+	ebytes, err := h.formatter.Format(&e)
+	if err != nil {
+		return err
+	}
+
+	buf := new(bytes.Buffer)
+	buf.Write(ebytes)
+	buf.WriteString("\n")
+
+	select {
+	case h.entryChan <- buf:
+		return nil
+	default:
+		return errors.New("connection broken or not fast enough")
+	}
+}
+
+type SyslogOutlet struct {
+	Formatter          EntryFormatter
+	RetryInterval      time.Duration
+	Facility           syslog.Priority
+	writer             *syslog.Writer
+	lastConnectAttempt time.Time
+}
+
+func (o *SyslogOutlet) WriteEntry(entry logger.Entry) error {
+
+	bytes, err := o.Formatter.Format(&entry)
+	if err != nil {
+		return err
+	}
+
+	s := string(bytes)
+
+	if o.writer == nil {
+		now := time.Now()
+		if now.Sub(o.lastConnectAttempt) < o.RetryInterval {
+			return nil // not an error toward logger
+		}
+		o.writer, err = syslog.New(o.Facility, "zrepl")
+		o.lastConnectAttempt = time.Now()
+		if err != nil {
+			o.writer = nil
+			return err
+		}
+	}
+
+	switch entry.Level {
+	case logger.Debug:
+		return o.writer.Debug(s)
+	case logger.Info:
+		return o.writer.Info(s)
+	case logger.Warn:
+		return o.writer.Warning(s)
+	case logger.Error:
+		return o.writer.Err(s)
+	default:
+		return o.writer.Err(s) // write as error as reaching this case is in fact an error
+	}
+
+}

internal/daemon/logging/trace/trace.go

@@ -0,0 +1,422 @@
+// 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"
+	"fmt"
+	"os"
+	runtimedebug "runtime/debug"
+	"strings"
+	"time"
+
+	"github.com/kr/pretty"
+	"github.com/pkg/errors"
+	"github.com/prometheus/client_golang/prometheus"
+
+	"github.com/zrepl/zrepl/internal/util/chainlock"
+)
+
+var metrics struct {
+	activeTasks prometheus.Gauge
+}
+var taskNamer *uniqueConcurrentTaskNamer = newUniqueTaskNamer()
+
+func init() {
+	metrics.activeTasks = prometheus.NewGauge(prometheus.GaugeOpts{
+		Namespace: "zrepl",
+		Subsystem: "trace",
+		Name:      "active_tasks",
+		Help:      "number of active (tracing-level) tasks in the daemon",
+	})
+}
+
+func RegisterMetrics(r prometheus.Registerer) {
+	r.MustRegister(metrics.activeTasks)
+}
+
+type traceNode struct {
+	// NOTE: members with prefix debug are only valid if the package variable debugEnabled is true.
+
+	id                 string
+	annotation         string
+	parentTask         *traceNode
+	debugCreationStack string // debug: stack trace of when the traceNode was created
+
+	mtx chainlock.L
+
+	activeChildTasks      int32               // only for task nodes, insignificant for span nodes
+	debugActiveChildTasks map[*traceNode]bool // debug: set of active child tasks
+	parentSpan            *traceNode
+	activeChildSpan       *traceNode // nil if task or span doesn't have an active child span
+
+	startedAt time.Time
+	endedAt   time.Time
+}
+
+func (s *traceNode) StartedAt() time.Time { return s.startedAt }
+func (s *traceNode) EndedAt() time.Time   { return s.endedAt }
+
+// caller must hold mtx
+func (s *traceNode) debugString() string {
+	if !debugEnabled {
+		return "<debugEnabled=false>"
+	}
+	return pretty.Sprint(s)
+}
+
+// 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()
+
+var ErrTaskStillHasActiveChildTasks = fmt.Errorf("end task: task still has active child tasks")
+
+// Start a new root task or create a child task of an existing task.
+//
+// This is required when starting a new goroutine and
+// passing an existing task context to it.
+//
+// taskName should be a constantand must not contain '#'
+//
+// The implementation ensures that,
+// if multiple tasks with the same name exist simultaneously,
+// a unique suffix is appended to uniquely identify the task opened with this function.
+func WithTask(ctx context.Context, taskName string) (context.Context, DoneFunc) {
+
+	var parentTask *traceNode
+	nodeI := ctx.Value(contextKeyTraceNode)
+	if nodeI != nil {
+		node := nodeI.(*traceNode)
+		if node.parentSpan != nil {
+			parentTask = node.parentTask
+		} else {
+			parentTask = node
+		}
+	}
+	// find the first ancestor that hasn't ended yet (nil if need be)
+	if parentTask != nil {
+		parentTask.mtx.Lock()
+	}
+	for parentTask != nil && !parentTask.endedAt.IsZero() {
+		thisParent := parentTask
+		parentTask = parentTask.parentTask
+		// lock parent first such that it isn't modified by other callers to thisParent
+		if parentTask != nil {
+			parentTask.mtx.Lock()
+		}
+		thisParent.mtx.Unlock()
+	}
+	// invariant: either parentTask != nil and we hold the lock on parentTask, or parentTask is nil
+
+	taskName, taskNameDone := taskNamer.UniqueConcurrentTaskName(taskName)
+
+	this := &traceNode{
+		id:               genID(),
+		annotation:       taskName,
+		parentTask:       parentTask,
+		activeChildTasks: 0,
+		parentSpan:       nil,
+		activeChildSpan:  nil,
+
+		startedAt: time.Now(),
+		endedAt:   time.Time{},
+	}
+
+	if debugEnabled {
+		this.debugCreationStack = string(runtimedebug.Stack())
+		this.debugActiveChildTasks = map[*traceNode]bool{}
+	}
+
+	if parentTask != nil {
+		this.parentTask.activeChildTasks++
+		if debugEnabled {
+			this.parentTask.debugActiveChildTasks[this] = true
+		}
+		parentTask.mtx.Unlock()
+	}
+
+	ctx = context.WithValue(ctx, contextKeyTraceNode, this)
+
+	chrometraceBeginTask(this)
+
+	metrics.activeTasks.Inc()
+
+	endTaskFunc := func() {
+
+		// only hold locks while manipulating the tree
+		// (trace writer might block too long and unlike spans, tasks are updated concurrently)
+		alreadyEnded := func() (alreadyEnded bool) {
+			if this.parentTask != nil {
+				defer this.parentTask.mtx.Lock().Unlock()
+			}
+			defer this.mtx.Lock().Unlock()
+
+			if this.activeChildTasks != 0 {
+				if debugEnabled {
+					// the debugString can be quite long and panic won't print it completely
+					fmt.Fprintf(os.Stderr, "going to panic due to activeChildTasks:\n%s\n", this.debugString())
+				}
+				panic(errors.WithMessagef(ErrTaskStillHasActiveChildTasks, "end task: %v active child tasks (run daemon with env var %s=1 for more details)\n", this.activeChildTasks, debugEnabledEnvVar))
+			}
+
+			// support idempotent task ends
+			if !this.endedAt.IsZero() {
+				return true
+			}
+			this.endedAt = time.Now()
+
+			if this.parentTask != nil {
+				this.parentTask.activeChildTasks--
+				if debugEnabled {
+					delete(this.parentTask.debugActiveChildTasks, this)
+				}
+				if this.parentTask.activeChildTasks < 0 {
+					if debugEnabled {
+						// the debugString can be quite long and panic won't print it completely
+						fmt.Fprintf(os.Stderr, "going to panic due to activeChildTasks < 0:\n%s\n", this.parentTask.debugString())
+					}
+					panic(fmt.Sprintf("impl error: parent task with negative activeChildTasks count: %v", this.parentTask.activeChildTasks))
+				}
+			}
+			return false
+		}()
+		if alreadyEnded {
+			return
+		}
+
+		chrometraceEndTask(this)
+
+		metrics.activeTasks.Dec()
+
+		taskNameDone()
+	}
+
+	return ctx, endTaskFunc
+}
+
+var ErrAlreadyActiveChildSpan = fmt.Errorf("create child span: span already has an active child span")
+var ErrSpanStillHasActiveChildSpan = fmt.Errorf("end span: span still has active child spans")
+
+// 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)
+	if nodeI != nil {
+		parentSpan = nodeI.(*traceNode)
+		if parentSpan.parentSpan == nil {
+			parentTask = parentSpan
+		} else {
+			parentTask = parentSpan.parentTask
+		}
+	} else {
+		panic("must be called from within a task")
+	}
+
+	this := &traceNode{
+		id:              genID(),
+		annotation:      annotation,
+		parentTask:      parentTask,
+		parentSpan:      parentSpan,
+		activeChildSpan: nil,
+
+		startedAt: time.Now(),
+		endedAt:   time.Time{},
+	}
+
+	if debugEnabled {
+		this.debugCreationStack = string(runtimedebug.Stack())
+	}
+
+	parentSpan.mtx.HoldWhile(func() {
+		if parentSpan.activeChildSpan != nil {
+			panic(ErrAlreadyActiveChildSpan)
+		}
+		parentSpan.activeChildSpan = this
+	})
+
+	ctx = context.WithValue(ctx, contextKeyTraceNode, this)
+	chrometraceBeginSpan(this)
+	callbackEndSpan := callbackBeginSpan(ctx)
+
+	endTaskFunc := func() {
+
+		defer parentSpan.mtx.Lock().Unlock()
+		if parentSpan.activeChildSpan != this && this.endedAt.IsZero() {
+			panic("impl error: activeChildSpan should not change while != nil because there can only be one")
+		}
+
+		defer this.mtx.Lock().Unlock()
+		if this.activeChildSpan != nil {
+			panic(ErrSpanStillHasActiveChildSpan)
+		}
+
+		if !this.endedAt.IsZero() {
+			return // support idempotent span ends
+		}
+
+		parentSpan.activeChildSpan = nil
+		this.endedAt = time.Now()
+
+		chrometraceEndSpan(this)
+		callbackEndSpan(this)
+	}
+
+	return ctx, endTaskFunc
+}
+
+type StackKind struct {
+	symbolizeTask func(t *traceNode) string
+	symbolizeSpan func(s *traceNode) string
+}
+
+var (
+	StackKindId = &StackKind{
+		symbolizeTask: func(t *traceNode) string { return t.id },
+		symbolizeSpan: func(s *traceNode) string { return s.id },
+	}
+	SpanStackKindCombined = &StackKind{
+		symbolizeTask: func(t *traceNode) string { return fmt.Sprintf("(%s %q)", t.id, t.annotation) },
+		symbolizeSpan: func(s *traceNode) string { return fmt.Sprintf("(%s %q)", s.id, s.annotation) },
+	}
+	SpanStackKindAnnotation = &StackKind{
+		symbolizeTask: func(t *traceNode) string { return t.annotation },
+		symbolizeSpan: func(s *traceNode) string { return s.annotation },
+	}
+)
+
+func (n *traceNode) task() *traceNode {
+	task := n.parentTask
+	if n.parentSpan == nil {
+		task = n
+	}
+	return task
+}
+
+func (n *traceNode) TaskName() string {
+	task := n.task()
+	return task.annotation
+}
+
+func (this *traceNode) TaskAndSpanStack(kind *StackKind) (spanIdStack string) {
+	task := this.task()
+
+	var spansInTask []*traceNode
+	for s := this; s != nil; s = s.parentSpan {
+		spansInTask = append(spansInTask, s)
+	}
+
+	var tasks []*traceNode
+	for t := task; t != nil; t = t.parentTask {
+		tasks = append(tasks, t)
+	}
+
+	var taskIdsRev []string
+	for i := len(tasks) - 1; i >= 0; i-- {
+		taskIdsRev = append(taskIdsRev, kind.symbolizeTask(tasks[i]))
+	}
+
+	var spanIdsRev []string
+	for i := len(spansInTask) - 1; i >= 0; i-- {
+		spanIdsRev = append(spanIdsRev, kind.symbolizeSpan(spansInTask[i]))
+	}
+
+	taskStack := strings.Join(taskIdsRev, "$")
+	return fmt.Sprintf("%s$%s", taskStack, strings.Join(spanIdsRev, "."))
+}
+
+func GetSpanStackOrDefault(ctx context.Context, kind StackKind, def string) string {
+	if nI := ctx.Value(contextKeyTraceNode); nI != nil {
+		n := nI.(*traceNode)
+		return n.TaskAndSpanStack(StackKindId)
+	} else {
+		return def
+	}
+}

internal/daemon/logging/trace/trace_callback.go

@@ -0,0 +1,54 @@
+package trace
+
+import (
+	"context"
+	"time"
+
+	"github.com/zrepl/zrepl/internal/util/chainlock"
+)
+
+type SpanInfo interface {
+	StartedAt() time.Time
+	EndedAt() time.Time
+	TaskAndSpanStack(kind *StackKind) string
+}
+
+type Callback struct {
+	OnBegin func(ctx context.Context)
+	OnEnd   func(ctx context.Context, spanInfo SpanInfo)
+}
+
+var callbacks struct {
+	mtx chainlock.L
+	cs  []Callback
+}
+
+func RegisterCallback(c Callback) {
+	callbacks.mtx.HoldWhile(func() {
+		callbacks.cs = append(callbacks.cs, c)
+	})
+}
+
+func callbackBeginSpan(ctx context.Context) func(SpanInfo) {
+	// capture the current state of callbacks into a local variable
+	// this is safe because the slice is append-only and immutable
+
+	// (it is important that a callback registered _after_ callbackBeginSpin is called does not get called on OnEnd)
+
+	var cbs []Callback
+	callbacks.mtx.HoldWhile(func() {
+		cbs = callbacks.cs
+	})
+	for _, cb := range cbs {
+		if cb.OnBegin != nil {
+			cb.OnBegin(ctx)
+		}
+	}
+	return func(spanInfo SpanInfo) {
+		for _, cb := range cbs {
+			if cb.OnEnd != nil {
+				cb.OnEnd(ctx, spanInfo)
+			}
+		}
+	}
+}

internal/daemon/logging/trace/trace_chrometrace.go

@@ -0,0 +1,230 @@
+package trace
+
+// The functions in this file are concerned with the generation
+// of trace files based on the information from WithTask and WithSpan.
+//
+// The emitted trace files are open-ended array of JSON objects
+// that follow the Chrome trace file format:
+//   https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
+//
+// The emitted JSON can be loaded into Chrome's chrome://tracing view.
+//
+// The trace file can be written to a file whose path is specified in an env file,
+// and be written to web sockets established on ChrometraceHttpHandler
+
+import (
+	"bufio"
+	"bytes"
+	"encoding/json"
+	"fmt"
+	"io"
+	"os"
+	"sync"
+	"sync/atomic"
+
+	"golang.org/x/net/websocket"
+
+	"github.com/zrepl/zrepl/internal/util/envconst"
+)
+
+var chrometracePID string
+
+func init() {
+	var err error
+	chrometracePID, err = os.Hostname()
+	if err != nil {
+		panic(err)
+	}
+	chrometracePID = fmt.Sprintf("%q", chrometracePID)
+}
+
+type chrometraceEvent struct {
+	Cat                       string   `json:"cat,omitempty"`
+	Name                      string   `json:"name"`
+	Stack                     []string `json:"stack,omitempty"`
+	Phase                     string   `json:"ph"`
+	TimestampUnixMicroseconds int64    `json:"ts"`
+	DurationMicroseconds      int64    `json:"dur,omitempty"`
+	Pid                       string   `json:"pid"`
+	Tid                       string   `json:"tid"`
+	Id                        string   `json:"id,omitempty"`
+}
+
+func chrometraceBeginSpan(s *traceNode) {
+	taskName := s.TaskName()
+	chrometraceWrite(chrometraceEvent{
+		Name:                      s.annotation,
+		Phase:                     "B",
+		TimestampUnixMicroseconds: s.startedAt.UnixNano() / 1000,
+		Pid:                       chrometracePID,
+		Tid:                       taskName,
+	})
+}
+
+func chrometraceEndSpan(s *traceNode) {
+	taskName := s.TaskName()
+	chrometraceWrite(chrometraceEvent{
+		Name:                      s.annotation,
+		Phase:                     "E",
+		TimestampUnixMicroseconds: s.endedAt.UnixNano() / 1000,
+		Pid:                       chrometracePID,
+		Tid:                       taskName,
+	})
+}
+
+var chrometraceFlowId uint64
+
+func chrometraceBeginTask(s *traceNode) {
+	chrometraceBeginSpan(s)
+
+	if s.parentTask == nil {
+		return
+	}
+	// beginning of a task that has a parent
+	// => use flow events to link parent and child
+
+	flowId := atomic.AddUint64(&chrometraceFlowId, 1)
+	flowIdStr := fmt.Sprintf("%x", flowId)
+
+	parentTask := s.parentTask.TaskName()
+	chrometraceWrite(chrometraceEvent{
+		Cat:                       "task", // seems to be necessary, otherwise the GUI shows some `indexOf` JS error
+		Name:                      "child-task",
+		Phase:                     "s",
+		TimestampUnixMicroseconds: s.startedAt.UnixNano() / 1000, // yes, the child's timestamp (=> from-point of the flow line is at right x-position of parent's bar)
+		Pid:                       chrometracePID,
+		Tid:                       parentTask,
+		Id:                        flowIdStr,
+	})
+
+	childTask := s.TaskName()
+	if parentTask == childTask {
+		panic(parentTask)
+	}
+	chrometraceWrite(chrometraceEvent{
+		Cat:                       "task", // seems to be necessary, otherwise the GUI shows some `indexOf` JS error
+		Name:                      "child-task",
+		Phase:                     "f",
+		TimestampUnixMicroseconds: s.startedAt.UnixNano() / 1000,
+		Pid:                       chrometracePID,
+		Tid:                       childTask,
+		Id:                        flowIdStr,
+	})
+}
+
+func chrometraceEndTask(s *traceNode) {
+	chrometraceEndSpan(s)
+}
+
+type chrometraceConsumerRegistration struct {
+	w io.Writer
+	// errored must have capacity 1, the writer thread will send to it non-blocking, then close it
+	errored chan error
+}
+
+var chrometraceConsumers struct {
+	register  chan chrometraceConsumerRegistration
+	consumers map[chrometraceConsumerRegistration]bool
+	write     chan []byte
+}
+
+func init() {
+	chrometraceConsumers.register = make(chan chrometraceConsumerRegistration)
+	chrometraceConsumers.consumers = make(map[chrometraceConsumerRegistration]bool)
+	chrometraceConsumers.write = make(chan []byte)
+	go func() {
+		kickConsumer := func(c chrometraceConsumerRegistration, err error) {
+			debug("chrometrace kicking consumer %#v after error %v", c, err)
+			select {
+			case c.errored <- err:
+			default:
+			}
+			close(c.errored)
+			delete(chrometraceConsumers.consumers, c)
+		}
+		for {
+			select {
+			case reg := <-chrometraceConsumers.register:
+				debug("registered chrometrace consumer %#v", reg)
+				chrometraceConsumers.consumers[reg] = true
+				n, err := reg.w.Write([]byte("[\n"))
+				if err != nil {
+					kickConsumer(reg, err)
+				} else if n != 2 {
+					kickConsumer(reg, fmt.Errorf("short write: %v", n))
+				}
+				// successfully registered
+
+			case buf := <-chrometraceConsumers.write:
+				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)
+					debug("chrometrace wrote n=%v bytes to consumer %#v", n, c)
+					if err != nil {
+						kickConsumer(c, err)
+					}
+				}
+			}
+		}
+	}()
+}
+
+func chrometraceWrite(i interface{}) {
+	var buf bytes.Buffer
+	err := json.NewEncoder(&buf).Encode(i)
+	if err != nil {
+		panic(err)
+	}
+	buf.WriteString(",")
+	chrometraceConsumers.write <- buf.Bytes()
+}
+
+func ChrometraceClientWebsocketHandler(conn *websocket.Conn) {
+	defer conn.Close()
+
+	var wg sync.WaitGroup
+	defer wg.Wait()
+	wg.Add(1)
+	go func() {
+		defer wg.Done()
+		r := bufio.NewReader(conn)
+		_, _, _ = r.ReadLine() // ignore errors
+		conn.Close()
+	}()
+
+	errored := make(chan error, 1)
+	chrometraceConsumers.register <- chrometraceConsumerRegistration{
+		w:       conn,
+		errored: errored,
+	}
+
+	wg.Add(1)
+	go func() {
+		defer wg.Done()
+		<-errored
+		conn.Close()
+	}()
+}
+
+var chrometraceFileConsumerPath = envconst.String("ZREPL_ACTIVITY_TRACE", "")
+
+func init() {
+	if chrometraceFileConsumerPath != "" {
+		var err error
+		f, err := os.Create(chrometraceFileConsumerPath)
+		if err != nil {
+			panic(err)
+		}
+		errored := make(chan error, 1)
+		chrometraceConsumers.register <- chrometraceConsumerRegistration{
+			w:       f,
+			errored: errored,
+		}
+		go func() {
+			<-errored
+			f.Close()
+		}()
+	}
+}

internal/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
+}

internal/daemon/logging/trace/trace_convenience.go

@@ -0,0 +1,76 @@
+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
+//
+// IMPORTANT FOR USERS: Caller must ensure that the capturing behavior is correct, the Go linter doesn't catch this.
+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)
+		go func() {
+			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 ""
+}

internal/daemon/logging/trace/trace_convenience_test.go

@@ -0,0 +1,62 @@
+package trace
+
+import (
+	"context"
+	"sync/atomic"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestGetCallerOrPanic(t *testing.T) {
+	withStackFromCtxMock := func() string {
+		return getMyCallerOrPanic()
+	}
+	ret := withStackFromCtxMock()
+	// zrepl prefix is stripped
+	assert.Equal(t, "internal/daemon/logging/trace.TestGetCallerOrPanic", ret)
+}
+
+func TestWithTaskGroupRunTasksConcurrently(t *testing.T) {
+
+	// spawn a task group where each task waits for the other to start
+	// => without concurrency, they would hang
+
+	rootCtx, endRoot := WithTaskFromStack(context.Background())
+	defer endRoot()
+
+	_, add, waitEnd := WithTaskGroup(rootCtx, "test-task-group")
+
+	schedulerTimeout := 2 * time.Second
+	timeout := time.After(schedulerTimeout)
+	var hadTimeout uint32
+	started0, started1 := make(chan struct{}), make(chan struct{})
+	for i := 0; i < 2; i++ {
+		i := i // capture by copy
+		add(func(ctx context.Context) {
+			switch i {
+			case 0:
+				close(started0)
+				select {
+				case <-started1:
+				case <-timeout:
+					atomic.AddUint32(&hadTimeout, 1)
+				}
+			case 1:
+				close(started1)
+				select {
+				case <-started0:
+				case <-timeout:
+					atomic.AddUint32(&hadTimeout, 1)
+				}
+			default:
+				panic("unreachable")
+			}
+		})
+	}
+
+	waitEnd()
+	assert.Zero(t, hadTimeout, "either bad impl or scheduler timeout (which is %v)", schedulerTimeout)
+
+}

internal/daemon/logging/trace/trace_debug.go

@@ -0,0 +1,19 @@
+package trace
+
+import (
+	"fmt"
+	"os"
+
+	"github.com/zrepl/zrepl/internal/util/envconst"
+)
+
+const debugEnabledEnvVar = "ZREPL_TRACE_DEBUG_ENABLED"
+
+var debugEnabled = envconst.Bool(debugEnabledEnvVar, false)
+
+func debug(format string, args ...interface{}) {
+	if !debugEnabled {
+		return
+	}
+	fmt.Fprintf(os.Stderr, format+"\n", args...)
+}

internal/daemon/logging/trace/trace_genID.go

@@ -0,0 +1,35 @@
+package trace
+
+import (
+	"crypto/rand"
+	"encoding/base64"
+	"strings"
+
+	"github.com/zrepl/zrepl/internal/util/envconst"
+)
+
+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)
+	_, err := rand.Read(buf)
+	if err != nil {
+		panic(err)
+	}
+	n, err := enc.Write(buf[:])
+	if err != nil || n != len(buf) {
+		panic(err)
+	}
+	if err := enc.Close(); err != nil {
+		panic(err)
+	}
+	return out.String()
+}

internal/daemon/logging/trace/trace_test.go

@@ -0,0 +1,205 @@
+package trace
+
+import (
+	"context"
+	"fmt"
+	"testing"
+
+	"github.com/gitchander/permutation"
+	"github.com/pkg/errors"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestRegularSpanUsage(t *testing.T) {
+	root, endRoot := WithTask(context.Background(), "root")
+	defer endRoot()
+
+	s1, endS1 := WithSpan(root, "parent")
+	s2, endS2 := WithSpan(s1, "child")
+	_, endS3 := WithSpan(s2, "grand-child")
+	require.NotPanics(t, func() { endS3() })
+	require.NotPanics(t, func() { endS2() })
+
+	// reuse
+	_, endS4 := WithSpan(s1, "child-2")
+	require.NotPanics(t, func() { endS4() })
+
+	// close parent
+	require.NotPanics(t, func() { endS1() })
+}
+
+func TestMultipleActiveChildSpansNotAllowed(t *testing.T) {
+	root, endRoot := WithTask(context.Background(), "root")
+	defer endRoot()
+
+	s1, _ := WithSpan(root, "s1")
+	_, endS2 := WithSpan(s1, "s1-child1")
+
+	require.PanicsWithValue(t, ErrAlreadyActiveChildSpan, func() {
+		_, _ = WithSpan(s1, "s1-child2")
+	})
+
+	endS2()
+
+	require.NotPanics(t, func() {
+		_, _ = WithSpan(s1, "s1-child2")
+	})
+}
+
+func TestForkingChildSpansNotAllowed(t *testing.T) {
+	root, endRoot := WithTask(context.Background(), "root")
+	defer endRoot()
+
+	s1, _ := WithSpan(root, "s1")
+	sc, endSC := WithSpan(s1, "s1-child")
+	_, _ = WithSpan(sc, "s1-child-child")
+
+	require.PanicsWithValue(t, ErrSpanStillHasActiveChildSpan, func() {
+		endSC()
+	})
+}
+
+func TestRegularTaskUsage(t *testing.T) {
+	// assert concurrent activities on different tasks can end in any order
+	closeOrder := []int{0, 1, 2}
+	closeOrders := permutation.New(permutation.IntSlice(closeOrder))
+	for closeOrders.Next() {
+		t.Run(fmt.Sprintf("%v", closeOrder), func(t *testing.T) {
+			root, endRoot := WithTask(context.Background(), "root")
+			defer endRoot()
+
+			c1, endC1 := WithTask(root, "c1")
+			defer endC1()
+			c2, endC2 := WithTask(root, "c2")
+			defer endC2()
+
+			// begin 3 concurrent activities
+			_, endAR := WithSpan(root, "aR")
+			_, endAC1 := WithSpan(c1, "aC1")
+			_, endAC2 := WithSpan(c2, "aC2")
+
+			endFuncs := []DoneFunc{endAR, endAC1, endAC2}
+			for _, i := range closeOrder {
+				require.NotPanics(t, func() {
+					endFuncs[i]()
+				}, "%v", i)
+			}
+		})
+	}
+}
+
+func TestTaskEndWithActiveChildTaskNotAllowed(t *testing.T) {
+	root, _ := WithTask(context.Background(), "root")
+	c, endC := WithTask(root, "child")
+	_, _ = WithTask(c, "grand-child")
+	func() {
+		defer func() {
+			r := recover()
+			require.NotNil(t, r)
+			err, ok := r.(error)
+			require.True(t, ok)
+			require.Equal(t, ErrTaskStillHasActiveChildTasks, errors.Cause(err))
+		}()
+		endC()
+	}()
+
+}
+
+func TestIdempotentEndTask(t *testing.T) {
+	_, end := WithTask(context.Background(), "root")
+	end()
+	require.NotPanics(t, func() { end() })
+}
+
+func TestSpansPanicIfNoParentTask(t *testing.T) {
+	require.Panics(t, func() { WithSpan(context.Background(), "taskless-span") })
+}
+
+func TestIdempotentEndSpan(t *testing.T) {
+	root, _ := WithTask(context.Background(), "root")
+	_, end := WithSpan(root, "span")
+	end()
+	require.NotPanics(t, func() { end() })
+}
+
+func logAndGetTraceNode(t *testing.T, descr string, ctx context.Context) *traceNode {
+	n, ok := ctx.Value(contextKeyTraceNode).(*traceNode)
+	require.True(t, ok)
+	t.Logf("% 20s %p %#v", descr, n, n)
+	return n
+}
+
+func TestWhiteboxHierachy(t *testing.T) {
+	root, e1 := WithTask(context.Background(), "root")
+	rootN := logAndGetTraceNode(t, "root", root)
+	assert.Nil(t, rootN.parentTask)
+	assert.Nil(t, rootN.parentSpan)
+
+	child, e2 := WithSpan(root, "child")
+	childN := logAndGetTraceNode(t, "child", child)
+	assert.Equal(t, rootN, childN.parentTask)
+	assert.Equal(t, rootN, childN.parentSpan)
+
+	grandchild, e3 := WithSpan(child, "grandchild")
+	grandchildN := logAndGetTraceNode(t, "grandchild", grandchild)
+	assert.Equal(t, rootN, grandchildN.parentTask)
+	assert.Equal(t, childN, grandchildN.parentSpan)
+
+	gcTask, e4 := WithTask(grandchild, "grandchild-task")
+	gcTaskN := logAndGetTraceNode(t, "grandchild-task", gcTask)
+	assert.Equal(t, rootN, gcTaskN.parentTask)
+	assert.Nil(t, gcTaskN.parentSpan)
+
+	// it is allowed that a child task outlives the _span_ in which it was created
+	// (albeit not its parent task)
+	e3()
+	e2()
+	gcTaskSpan, e5 := WithSpan(gcTask, "granschild-task-span")
+	gcTaskSpanN := logAndGetTraceNode(t, "granschild-task-span", gcTaskSpan)
+	assert.Equal(t, gcTaskN, gcTaskSpanN.parentTask)
+	assert.Equal(t, gcTaskN, gcTaskSpanN.parentSpan)
+	e5()
+
+	e4()
+	e1()
+}
+
+func TestOrphanTasksBecomeNewRootWhenAllAncestorsAreDead(t *testing.T) {
+	parent, e1 := WithTask(context.Background(), "parent")
+	_ = logAndGetTraceNode(t, "parent-task", parent)
+	e1()
+
+	var child context.Context
+	var e2 DoneFunc
+	require.NotPanics(t, func() {
+		child, e2 = WithTask(parent, "child")
+	})
+	childN := logAndGetTraceNode(t, "child-task", child)
+	assert.Nil(t, childN.parentTask)
+
+	grandchild, _ := WithTask(child, "grandchild")
+	grandchildN := logAndGetTraceNode(t, "grandchild-task", grandchild)
+	assert.Equal(t, childN, grandchildN.parentTask)
+
+	require.Panics(t, func() { e2() }, "if the parent was alive at creation of child task, wrong termination order remains a panicable offense though")
+}
+
+func TestOrphanTaskBecomesChildToNearestLiveAncestor(t *testing.T) {
+	parent, e1 := WithTask(context.Background(), "parent")
+	parentN := logAndGetTraceNode(t, "parent-task", parent)
+
+	child, e2 := WithTask(parent, "child")
+	childN := logAndGetTraceNode(t, "child-task", child)
+	assert.Equal(t, parentN, childN.parentTask)
+	e2()
+
+	grandchild, e3 := WithTask(child, "grandchild")
+	grandchildN := logAndGetTraceNode(t, "grandchild-task", grandchild)
+	assert.Equal(t, parentN, grandchildN.parentTask) // child is already dead
+
+	require.NotPanics(t, func() {
+		e3()
+		e1()
+	})
+}

internal/daemon/logging/trace/trace_unique_concurrent_task_namer.go

@@ -0,0 +1,53 @@
+package trace
+
+import (
+	"fmt"
+	"strings"
+	"sync"
+
+	"github.com/bits-and-blooms/bitset"
+)
+
+type uniqueConcurrentTaskNamer struct {
+	mtx    sync.Mutex
+	active map[string]*bitset.BitSet
+}
+
+// bitvecLengthGauge may be nil
+func newUniqueTaskNamer() *uniqueConcurrentTaskNamer {
+	return &uniqueConcurrentTaskNamer{
+		active: make(map[string]*bitset.BitSet),
+	}
+}
+
+// appends `#%d` to `name` such that until `done` is called,
+// it is guaranteed that `#%d` is not returned a second time for the same `name`
+func (namer *uniqueConcurrentTaskNamer) UniqueConcurrentTaskName(name string) (uniqueName string, done func()) {
+	if strings.Contains(name, "#") {
+		panic(name)
+	}
+	namer.mtx.Lock()
+	act, ok := namer.active[name]
+	if !ok {
+		act = bitset.New(64) // FIXME magic const
+		namer.active[name] = act
+	}
+	id, ok := act.NextClear(0)
+	if !ok {
+		// if !ok, all bits are 1 and act.Len() returns the next bit
+		id = act.Len()
+		// FIXME unbounded growth without reclamation
+	}
+	act.Set(id)
+	namer.mtx.Unlock()
+
+	return fmt.Sprintf("%s#%d", name, id), func() {
+		namer.mtx.Lock()
+		defer namer.mtx.Unlock()
+		act, ok := namer.active[name]
+		if !ok {
+			panic("must be initialized upon entry")
+		}
+		act.Clear(id)
+	}
+}

internal/daemon/logging/trace/trace_unique_concurrent_task_namer_test.go

@@ -0,0 +1,58 @@
+package trace
+
+import (
+	"fmt"
+	"sync"
+	"sync/atomic"
+	"testing"
+
+	"github.com/bits-and-blooms/bitset"
+	"github.com/stretchr/testify/require"
+)
+
+func TestBitsetFeaturesForUniqueConcurrentTaskNamer(t *testing.T) {
+	var b bitset.BitSet
+	require.Equal(t, uint(0), b.Len())
+	require.Equal(t, uint(0), b.Count())
+
+	b.Set(0)
+	require.Equal(t, uint(1), b.Len())
+	require.Equal(t, uint(1), b.Count())
+
+	b.Set(8)
+	require.Equal(t, uint(9), b.Len())
+	require.Equal(t, uint(2), b.Count())
+
+	b.Set(1)
+	require.Equal(t, uint(9), b.Len())
+	require.Equal(t, uint(3), b.Count())
+}
+
+func TestUniqueConcurrentTaskNamer(t *testing.T) {
+	namer := newUniqueTaskNamer()
+
+	var wg sync.WaitGroup
+
+	const N = 8128
+	const Q = 23
+
+	var fails uint32
+	var m sync.Map
+	wg.Add(N)
+	for i := 0; i < N; i++ {
+		go func(i int) {
+			defer wg.Done()
+			name := fmt.Sprintf("%d", i/Q)
+			uniqueName, done := namer.UniqueConcurrentTaskName(name)
+			act, _ := m.LoadOrStore(uniqueName, i)
+			if act.(int) != i {
+				atomic.AddUint32(&fails, 1)
+			}
+			m.Delete(uniqueName)
+			done()
+		}(i)
+	}
+	wg.Wait()
+
+	require.Equal(t, uint32(0), fails)
+}