trace/flightrecorder_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.

//go:build go1.22

package trace_test

import (
	"bytes"
	"context"
	"io"
	"runtime/trace"
	"sync"
	"sync/atomic"
	"testing"
	"time"

	"golang.org/x/exp/trace/internal/testtrace"

	. "golang.org/x/exp/trace"
)

func TestFlightRecorderDoubleStart(t *testing.T) {
	fr := NewFlightRecorder()

	if err := fr.Start(); err != nil {
		t.Fatalf("unexpected error on Start: %v", err)
	}
	if err := fr.Start(); err == nil {
		t.Fatalf("expected error from double Start: %v", err)
	}
	if err := fr.Stop(); err != nil {
		t.Fatalf("unexpected error on Stop: %v", err)
	}
}

func TestFlightRecorderDoubleStop(t *testing.T) {
	fr := NewFlightRecorder()

	if err := fr.Start(); err != nil {
		t.Fatalf("unexpected error on Start: %v", err)
	}
	if err := fr.Stop(); err != nil {
		t.Fatalf("unexpected error on Stop: %v", err)
	}
	if err := fr.Stop(); err == nil {
		t.Fatalf("expected error from double Stop: %v", err)
	}
}

func TestFlightRecorderEnabled(t *testing.T) {
	fr := NewFlightRecorder()

	if fr.Enabled() {
		t.Fatal("flight recorder is enabled, but never started")
	}
	if err := fr.Start(); err != nil {
		t.Fatalf("unexpected error on Start: %v", err)
	}
	if !fr.Enabled() {
		t.Fatal("flight recorder is not enabled, but started")
	}
	if err := fr.Stop(); err != nil {
		t.Fatalf("unexpected error on Stop: %v", err)
	}
	if fr.Enabled() {
		t.Fatal("flight recorder is enabled, but stopped")
	}
}

func TestFlightRecorderWriteToDisabled(t *testing.T) {
	var buf bytes.Buffer

	fr := NewFlightRecorder()
	if n, err := fr.WriteTo(&buf); err == nil {
		t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
	}
	if err := fr.Start(); err != nil {
		t.Fatalf("unexpected error on Start: %v", err)
	}
	if err := fr.Stop(); err != nil {
		t.Fatalf("unexpected error on Stop: %v", err)
	}
	if n, err := fr.WriteTo(&buf); err == nil {
		t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
	}
}

func TestFlightRecorderConcurrentWriteTo(t *testing.T) {
	fr := NewFlightRecorder()
	if err := fr.Start(); err != nil {
		t.Fatalf("unexpected error on Start: %v", err)
	}

	// Start two goroutines to write snapshots.
	//
	// Most of the time one will fail and one will succeed, but we don't require this.
	// Due to a variety of factors, it's definitely possible for them both to succeed.
	// However, at least one should succeed.
	var bufs [2]bytes.Buffer
	var wg sync.WaitGroup
	var successes atomic.Uint32
	for i := range bufs {
		wg.Add(1)
		go func() {
			defer wg.Done()

			n, err := fr.WriteTo(&bufs[i])
			if err == ErrSnapshotActive {
				if n != 0 {
					t.Errorf("(goroutine %d) WriteTo bytes written is non-zero for early bail out: %d", i, n)
				}
				return
			}
			if err != nil {
				t.Errorf("(goroutine %d) failed to write snapshot for unexpected reason: %v", i, err)
			}
			successes.Add(1)

			if n == 0 {
				t.Errorf("(goroutine %d) wrote invalid trace of zero bytes in size", i)
			}
			if n != bufs[i].Len() {
				t.Errorf("(goroutine %d) trace length doesn't match WriteTo result: got %d, want %d", i, n, bufs[i].Len())
			}
		}()
	}
	wg.Wait()

	// Stop tracing.
	if err := fr.Stop(); err != nil {
		t.Fatalf("unexpected error on Stop: %v", err)
	}

	// Make sure at least one succeeded to write.
	if successes.Load() == 0 {
		t.Fatal("expected at least one success to write a snapshot, got zero")
	}

	// Validate the traces that came out.
	for i := range bufs {
		buf := &bufs[i]
		if buf.Len() == 0 {
			continue
		}
		testReader(t, buf, testtrace.ExpectSuccess())
	}
}

func TestFlightRecorder(t *testing.T) {
	testFlightRecorder(t, NewFlightRecorder(), func(snapshot func()) {
		snapshot()
	})
}

func TestFlightRecorderStartStop(t *testing.T) {
	fr := NewFlightRecorder()
	for i := 0; i < 5; i++ {
		testFlightRecorder(t, fr, func(snapshot func()) {
			snapshot()
		})
	}
}

func TestFlightRecorderLog(t *testing.T) {
	tr := testFlightRecorder(t, NewFlightRecorder(), func(snapshot func()) {
		trace.Log(context.Background(), "message", "hello")
		snapshot()
	})

	// Prepare to read the trace snapshot.
	r, err := NewReader(bytes.NewReader(tr))
	if err != nil {
		t.Fatalf("unexpected error creating trace reader: %v", err)
	}

	// Find the log message in the trace.
	found := false
	for {
		ev, err := r.ReadEvent()
		if err == io.EOF {
			break
		}
		if err != nil {
			t.Fatalf("unexpected error reading trace: %v", err)
		}
		if !found && ev.Kind() == EventLog {
			log := ev.Log()
			found = log.Category == "message" && log.Message == "hello"
		}
	}
	if !found {
		t.Errorf("failed to find expected log message (%q, %q) in snapshot", "message", "hello")
	}
}

func TestFlightRecorderOneGeneration(t *testing.T) {
	test := func(t *testing.T, fr *FlightRecorder) {
		tr := testFlightRecorder(t, fr, func(snapshot func()) {
			// Sleep to let a few generations pass.
			time.Sleep(3 * time.Second)
			snapshot()
		})

		// Prepare to read the trace snapshot.
		r, err := NewReader(bytes.NewReader(tr))
		if err != nil {
			t.Fatalf("unexpected error creating trace reader: %v", err)
		}

		// Make sure there's only exactly one Sync event.
		sync := 0
		for {
			ev, err := r.ReadEvent()
			if err == io.EOF {
				break
			}
			if err != nil {
				t.Fatalf("unexpected error reading trace: %v", err)
			}
			if ev.Kind() == EventSync {
				sync++
			}
		}
		if sync != 1 {
			t.Errorf("expected one sync event, found %d", sync)
		}
	}
	t.Run("SetPeriod", func(t *testing.T) {
		// Set the period to 0 so that we're always throwing away old generations.
		// This should always result in exactly one generation.
		// Note: this is always going to result in taking the second generation
		// flushed, which is the much less useful one. That's OK, because in practice
		// SetPeriod shouldn't ever be called with a value this low.
		fr := NewFlightRecorder()
		fr.SetPeriod(0)
		test(t, fr)
	})
	t.Run("SetSize", func(t *testing.T) {
		// Set the size to 0 so that we're always throwing away old generations.
		// This should always result in exactly one generation.
		// Note: this is always going to result in taking the second generation
		// flushed, which is the much less useful one. That's OK, because in practice
		// SetPeriod shouldn't ever be called with a value this low.
		fr := NewFlightRecorder()
		fr.SetSize(0)
		test(t, fr)
	})
}

type flightRecorderTestFunc func(snapshot func())

func testFlightRecorder(t *testing.T, fr *FlightRecorder, f flightRecorderTestFunc) []byte {
	if trace.IsEnabled() {
		t.Skip("cannot run flight recorder tests when tracing is enabled")
	}

	// Start the flight recorder.
	if err := fr.Start(); err != nil {
		t.Fatalf("unexpected error on Start: %v", err)
	}

	// Set up snapshot callback.
	var buf bytes.Buffer
	callback := func() {
		n, err := fr.WriteTo(&buf)
		if err != nil {
			t.Errorf("unexpected failure during flight recording: %v", err)
			return
		}
		if n < 16 {
			t.Errorf("expected a trace size of at least 16 bytes, got %d", n)
		}
		if n != buf.Len() {
			t.Errorf("WriteTo result doesn't match trace size: got %d, want %d", n, buf.Len())
		}
	}

	// Call the test function.
	f(callback)

	// Stop the flight recorder.
	if err := fr.Stop(); err != nil {
		t.Fatalf("unexpected error on Stop: %v", err)
	}

	// Get the trace bytes; we don't want to use the Buffer as a Reader directly
	// since we may want to consume this data more than once.
	traceBytes := buf.Bytes()

	// Parse the trace to make sure it's not broken.
	testReader(t, bytes.NewReader(traceBytes), testtrace.ExpectSuccess())
	return traceBytes
}