137 lines
4.1 KiB
Go
137 lines
4.1 KiB
Go
package tracing
|
|
|
|
import (
|
|
"context"
|
|
"strings"
|
|
"testing"
|
|
|
|
"github.com/go-logr/logr"
|
|
"github.com/go-logr/logr/funcr"
|
|
sdktrace "go.opentelemetry.io/otel/sdk/trace"
|
|
"go.opentelemetry.io/otel/sdk/trace/tracetest"
|
|
"go.opentelemetry.io/otel/trace"
|
|
"go.opentelemetry.io/otel/trace/noop"
|
|
logf "sigs.k8s.io/controller-runtime/pkg/log"
|
|
)
|
|
|
|
// captureLogger records every emitted line so tests can assert on the
|
|
// rendered key/value output — the only place duplicate zap-style keys
|
|
// would show up.
|
|
func captureLogger(lines *[]string) logr.Logger {
|
|
return funcr.New(func(prefix, args string) {
|
|
*lines = append(*lines, prefix+" "+args)
|
|
}, funcr.Options{})
|
|
}
|
|
|
|
func recordingTracer(t *testing.T) (trace.Tracer, *tracetest.SpanRecorder) {
|
|
t.Helper()
|
|
sr := tracetest.NewSpanRecorder()
|
|
tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr))
|
|
t.Cleanup(func() { _ = tp.Shutdown(context.Background()) })
|
|
return tp.Tracer("test"), sr
|
|
}
|
|
|
|
func TestStartSpan_enrichesLoggerOncePerNesting(t *testing.T) {
|
|
t.Parallel()
|
|
tracer, sr := recordingTracer(t)
|
|
|
|
var lines []string
|
|
ctx := logf.IntoContext(context.Background(), captureLogger(&lines))
|
|
|
|
ctx1, span1 := StartSpan(ctx, tracer, "outer")
|
|
logf.FromContext(ctx1).Info("outer work")
|
|
|
|
ctx2, span2 := StartSpan(ctx1, tracer, "inner")
|
|
logf.FromContext(ctx2).Info("inner work")
|
|
|
|
span2.End()
|
|
span1.End()
|
|
|
|
if len(lines) != 2 {
|
|
t.Fatalf("got %d log lines, want 2: %v", len(lines), lines)
|
|
}
|
|
traceID := span1.SpanContext().TraceID().String()
|
|
for i, want := range []string{span1.SpanContext().SpanID().String(), span2.SpanContext().SpanID().String()} {
|
|
if n := strings.Count(lines[i], `"traceID"`); n != 1 {
|
|
t.Errorf("line %d: traceID appears %d times, want exactly 1: %s", i, n, lines[i])
|
|
}
|
|
if n := strings.Count(lines[i], `"spanID"`); n != 1 {
|
|
t.Errorf("line %d: spanID appears %d times, want exactly 1: %s", i, n, lines[i])
|
|
}
|
|
if !strings.Contains(lines[i], traceID) {
|
|
t.Errorf("line %d: missing traceID %s: %s", i, traceID, lines[i])
|
|
}
|
|
if !strings.Contains(lines[i], want) {
|
|
t.Errorf("line %d: missing spanID %s: %s", i, want, lines[i])
|
|
}
|
|
}
|
|
|
|
ended := sr.Ended()
|
|
if len(ended) != 2 {
|
|
t.Fatalf("got %d spans, want 2", len(ended))
|
|
}
|
|
// Ended in LIFO order: inner first.
|
|
if got := ended[0].Parent().SpanID(); got != span1.SpanContext().SpanID() {
|
|
t.Errorf("inner span parent = %s, want %s", got, span1.SpanContext().SpanID())
|
|
}
|
|
}
|
|
|
|
func TestStartSpan_noopTracerLeavesLoggerUntouched(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
var lines []string
|
|
ctx := logf.IntoContext(context.Background(), captureLogger(&lines))
|
|
|
|
ctx, span := StartSpan(ctx, noop.NewTracerProvider().Tracer("test"), "op")
|
|
defer span.End()
|
|
logf.FromContext(ctx).Info("work")
|
|
|
|
if len(lines) != 1 {
|
|
t.Fatalf("got %d log lines, want 1", len(lines))
|
|
}
|
|
if strings.Contains(lines[0], "traceID") {
|
|
t.Errorf("disabled tracing must not add traceID: %s", lines[0])
|
|
}
|
|
}
|
|
|
|
func TestContextWithLogger(t *testing.T) {
|
|
t.Parallel()
|
|
tracer, _ := recordingTracer(t)
|
|
|
|
t.Run("no span injects base as-is", func(t *testing.T) {
|
|
t.Parallel()
|
|
var lines []string
|
|
ctx := ContextWithLogger(context.Background(), captureLogger(&lines))
|
|
logf.FromContext(ctx).Info("plain")
|
|
if len(lines) != 1 || strings.Contains(lines[0], "traceID") {
|
|
t.Fatalf("want one line without traceID, got %v", lines)
|
|
}
|
|
})
|
|
|
|
t.Run("existing span enriches immediately and nested Start does not stack", func(t *testing.T) {
|
|
t.Parallel()
|
|
var lines []string
|
|
ctx, outer := tracer.Start(context.Background(), "server")
|
|
defer outer.End()
|
|
|
|
ctx = ContextWithLogger(ctx, captureLogger(&lines))
|
|
logf.FromContext(ctx).Info("handler")
|
|
|
|
ctx, inner := StartSpan(ctx, tracer, "child")
|
|
defer inner.End()
|
|
logf.FromContext(ctx).Info("nested")
|
|
|
|
if len(lines) != 2 {
|
|
t.Fatalf("got %d lines, want 2: %v", len(lines), lines)
|
|
}
|
|
for i, line := range lines {
|
|
if n := strings.Count(line, `"traceID"`); n != 1 {
|
|
t.Errorf("line %d: traceID appears %d times, want 1: %s", i, n, line)
|
|
}
|
|
}
|
|
if !strings.Contains(lines[1], inner.SpanContext().SpanID().String()) {
|
|
t.Errorf("nested line should carry the child spanID: %s", lines[1])
|
|
}
|
|
})
|
|
}
|