src/internal/trace/reader_test.go

// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package trace_test

import (
	"bytes"
	"flag"
	"fmt"
	"io"
	"os"
	"path/filepath"
	"runtime"
	"strings"
	"testing"
	"time"

	"internal/trace"
	"internal/trace/raw"
	"internal/trace/testtrace"
	"internal/trace/version"
)

var (
	logEvents  = flag.Bool("log-events", false, "whether to log high-level events; significantly slows down tests")
	dumpTraces = flag.Bool("dump-traces", false, "dump traces even on success")
)

func TestReaderGolden(t *testing.T) {
	matches, err := filepath.Glob("./testdata/tests/*.test")
	if err != nil {
		t.Fatalf("failed to glob for tests: %v", err)
	}
	for _, testPath := range matches {
		testPath := testPath
		testName, err := filepath.Rel("./testdata", testPath)
		if err != nil {
			t.Fatalf("failed to relativize testdata path: %v", err)
		}
		t.Run(testName, func(t *testing.T) {
			tr, ver, exp, err := testtrace.ParseFile(testPath)
			if err != nil {
				t.Fatalf("failed to parse test file at %s: %v", testPath, err)
			}
			v := testtrace.NewValidator()
			v.GoVersion = ver
			testReader(t, tr, v, exp)
		})
	}
}

func FuzzReader(f *testing.F) {
	// Currently disabled because the parser doesn't do much validation and most
	// getters can be made to panic. Turn this on once the parser is meant to
	// reject invalid traces.
	const testGetters = false

	f.Fuzz(func(t *testing.T, b []byte) {
		r, err := trace.NewReader(bytes.NewReader(b))
		if err != nil {
			return
		}
		for {
			ev, err := r.ReadEvent()
			if err != nil {
				break
			}

			if !testGetters {
				continue
			}
			// Make sure getters don't do anything that panics
			switch ev.Kind() {
			case trace.EventLabel:
				ev.Label()
			case trace.EventLog:
				ev.Log()
			case trace.EventMetric:
				ev.Metric()
			case trace.EventRangeActive, trace.EventRangeBegin:
				ev.Range()
			case trace.EventRangeEnd:
				ev.Range()
				ev.RangeAttributes()
			case trace.EventStateTransition:
				ev.StateTransition()
			case trace.EventRegionBegin, trace.EventRegionEnd:
				ev.Region()
			case trace.EventTaskBegin, trace.EventTaskEnd:
				ev.Task()
			case trace.EventSync:
			case trace.EventStackSample:
			case trace.EventBad:
			}
		}
	})
}

func testReader(t *testing.T, tr io.Reader, v *testtrace.Validator, exp *testtrace.Expectation) {
	r, err := trace.NewReader(tr)
	if err != nil {
		if err := exp.Check(err); err != nil {
			t.Error(err)
		}
		return
	}
	for {
		ev, err := r.ReadEvent()
		if err == io.EOF {
			break
		}
		v.GoVersion = r.GoVersion()
		if runtime.GOOS == "windows" || runtime.GOARCH == "wasm" {
			v.SkipClockSnapshotChecks()
		}
		if err != nil {
			if err := exp.Check(err); err != nil {
				t.Error(err)
			}
			return
		}
		if *logEvents {
			t.Log(ev.String())
		}
		if err := v.Event(ev); err != nil {
			t.Error(err)
		}
	}
	if err := exp.Check(nil); err != nil {
		t.Error(err)
	}
}

func dumpTraceToText(t *testing.T, b []byte) string {
	t.Helper()

	br, err := raw.NewReader(bytes.NewReader(b))
	if err != nil {
		t.Fatalf("dumping trace: %v", err)
	}
	var sb strings.Builder
	tw, err := raw.NewTextWriter(&sb, version.Current)
	if err != nil {
		t.Fatalf("dumping trace: %v", err)
	}
	for {
		ev, err := br.ReadEvent()
		if err == io.EOF {
			break
		}
		if err != nil {
			t.Fatalf("dumping trace: %v", err)
		}
		if err := tw.WriteEvent(ev); err != nil {
			t.Fatalf("dumping trace: %v", err)
		}
	}
	return sb.String()
}

func dumpTraceToFile(t *testing.T, testName string, stress bool, b []byte) string {
	t.Helper()

	desc := "default"
	if stress {
		desc = "stress"
	}
	name := fmt.Sprintf("%s.%s.trace.", testName, desc)
	f, err := os.CreateTemp("", name)
	if err != nil {
		t.Fatalf("creating temp file: %v", err)
	}
	defer f.Close()
	if _, err := io.Copy(f, bytes.NewReader(b)); err != nil {
		t.Fatalf("writing trace dump to %q: %v", f.Name(), err)
	}
	return f.Name()
}

func TestTraceGenSync(t *testing.T) {
	type sync struct {
		Time          trace.Time
		ClockSnapshot *trace.ClockSnapshot
	}
	runTest := func(testName string, wantSyncs []sync) {
		t.Run(testName, func(t *testing.T) {
			testPath := "testdata/tests/" + testName
			r, _, _, err := testtrace.ParseFile(testPath)
			if err != nil {
				t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
			}
			tr, err := trace.NewReader(r)
			if err != nil {
				t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
			}
			var syncEvents []trace.Event
			for {
				ev, err := tr.ReadEvent()
				if err == io.EOF {
					break
				}
				if err != nil {
					t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
				}
				if ev.Kind() == trace.EventSync {
					syncEvents = append(syncEvents, ev)
				}
			}

			if got, want := len(syncEvents), len(wantSyncs); got != want {
				t.Errorf("got %d sync events, want %d", got, want)
			}

			for i, want := range wantSyncs {
				got := syncEvents[i]
				gotSync := syncEvents[i].Sync()
				if got.Time() != want.Time {
					t.Errorf("sync=%d got time %d, want %d", i+1, got.Time(), want.Time)
				}
				if gotSync.ClockSnapshot == nil && want.ClockSnapshot == nil {
					continue
				}
				if gotSync.ClockSnapshot.Trace != want.ClockSnapshot.Trace {
					t.Errorf("sync=%d got trace time %d, want %d", i+1, gotSync.ClockSnapshot.Trace, want.ClockSnapshot.Trace)
				}
				if !gotSync.ClockSnapshot.Wall.Equal(want.ClockSnapshot.Wall) {
					t.Errorf("sync=%d got wall time %s, want %s", i+1, gotSync.ClockSnapshot.Wall, want.ClockSnapshot.Wall)
				}
				if gotSync.ClockSnapshot.Mono != want.ClockSnapshot.Mono {
					t.Errorf("sync=%d got mono time %d, want %d", i+1, gotSync.ClockSnapshot.Mono, want.ClockSnapshot.Mono)
				}
			}
		})
	}

	runTest("go123-sync.test", []sync{
		{10, nil},
		{40, nil},
		// The EvFrequency batch for generation 3 is emitted at trace.Time(80),
		// but 60 is the minTs of the generation, see b30 in the go generator.
		{60, nil},
		{63, nil},
	})

	runTest("go125-sync.test", []sync{
		{9, &trace.ClockSnapshot{Trace: 10, Mono: 99, Wall: time.Date(2025, 2, 28, 15, 4, 9, 123, time.UTC)}},
		{38, &trace.ClockSnapshot{Trace: 40, Mono: 199, Wall: time.Date(2025, 2, 28, 15, 4, 10, 123, time.UTC)}},
		{58, &trace.ClockSnapshot{Trace: 60, Mono: 299, Wall: time.Date(2025, 2, 28, 15, 4, 11, 123, time.UTC)}},
		{83, nil},
	})
}