go/tracing/loggingtracer/loggingtracer_test.go

package loggingtracer

import (
	"context"
	"fmt"
	"regexp"
	"testing"
	"time"

	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	"go.opencensus.io/trace"
	"go.skia.org/infra/go/now"
)

func TestLoggingTracer(t *testing.T) {
	fakeNow := time.Date(2023, time.January, 1, 0, 0, 0, 0, time.UTC)

	// Initialize logging tracer.
	originalTracer := trace.DefaultTracer
	Initialize()
	defer func() { trace.DefaultTracer = originalTracer }()

	// Capture logs.
	var logs []string
	originalLogf := Logf
	Logf = func(format string, v ...interface{}) {
		logs = append(logs, fmt.Sprintf(format, v...))
	}
	defer func() { Logf = originalLogf }()

	ctx := now.TimeTravelingContext(fakeNow)
	a(ctx)

	// These patterns make this test case fragile (i.e. inserting/deleting lines in this file might
	// break this test case), but it is important to test that we are reporting the correct line
	// numbers.
	expectedLogPatterns := []string{
		`^Starting span: a \[.*/loggingtracer_test.go:69]$`,
		`^Starting span: b \[.*/loggingtracer_test.go:77]$`,
		`^Starting span: c \[.*/loggingtracer_test.go:85]$`,
		`^Starting span: d \[.*/loggingtracer_test.go:92]$`,
		`^Ending span: d \[.*/loggingtracer_test.go:94] \(1s\)$`,
		`^Ending span: c \[.*/loggingtracer_test.go:88] \(3s\)$`,
		`^Starting span: c \[.*/loggingtracer_test.go:85]$`,
		`^Starting span: d \[.*/loggingtracer_test.go:92]$`,
		`^Ending span: d \[.*/loggingtracer_test.go:94] \(1s\)$`,
		`^Ending span: c \[.*/loggingtracer_test.go:88] \(3s\)$`,
		`^Ending span: b \[.*/loggingtracer_test.go:81] \(11s\)$`,
		`^Starting span: e \[.*/loggingtracer_test.go:98]$`,
		`^Ending span: e \[.*/loggingtracer_test.go:100] \(500ms\)$`,
		`^Ending span: a \[.*/loggingtracer_test.go:73] \(21.5s\)$`,
	}

	require.Len(t, logs, len(expectedLogPatterns))
	for i, pattern := range expectedLogPatterns {
		match, err := regexp.MatchString(pattern, logs[i])
		require.NoError(t, err)
		assert.Truef(
			t,
			match,
			"Log message does not match the expected pattern.\nActual message: %q.\nExpected pattern: %q.",
			logs[i],
			pattern)
	}
}

func a(ctx context.Context) context.Context {
	ctx, span := trace.StartSpan(ctx, "a")
	defer span.End()
	ctx = b(ctx)
	ctx = e(ctx)
	return fakeSpanDelay(ctx, span, 10*time.Second)
}

func b(ctx context.Context) context.Context {
	ctx, span := trace.StartSpan(ctx, "b")
	defer span.End()
	ctx = c(ctx)
	ctx = c(ctx)
	return fakeSpanDelay(ctx, span, 5*time.Second)
}

func c(ctx context.Context) context.Context {
	ctx, span := trace.StartSpan(ctx, "c")
	defer span.End()
	ctx = d(ctx)
	return fakeSpanDelay(ctx, span, 2*time.Second)
}

func d(ctx context.Context) context.Context {
	ctx, span := trace.StartSpan(ctx, "d")
	defer span.End()
	return fakeSpanDelay(ctx, span, time.Second)
}

func e(ctx context.Context) context.Context {
	ctx, span := trace.StartSpan(ctx, "e")
	defer span.End()
	return fakeSpanDelay(ctx, span, 500*time.Millisecond)
}

func fakeSpanDelay(ctx context.Context, span *trace.Span, duration time.Duration) context.Context {
	ctxGetterSetter := span.Internal().(spanCtxGetterSetter)
	ctx = context.WithValue(ctxGetterSetter.GetCtx(), now.ContextKey, now.Now(ctx).Add(duration))
	ctxGetterSetter.SetCtx(ctx)
	return ctx
}