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]) } }) }