src/runtime/debuglog_test.go

// Copyright 2019 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.

// TODO(austin): All of these tests are skipped if the debuglog build
// tag isn't provided. That means we basically never test debuglog.
// There are two potential ways around this:
//
// 1. Make these tests re-build the runtime test with the debuglog
// build tag and re-invoke themselves.
//
// 2. Always build the whole debuglog infrastructure and depend on
// linker dead-code elimination to drop it. This is easy for dlog()
// since there won't be any calls to it. For printDebugLog, we can
// make panic call a wrapper that is call printDebugLog if the
// debuglog build tag is set, or otherwise do nothing. Then tests
// could call printDebugLog directly. This is the right answer in
// principle, but currently our linker reads in all symbols
// regardless, so this would slow down and bloat all links. If the
// linker gets more efficient about this, we should revisit this
// approach.

package runtime_test

import (
	"fmt"
	"regexp"
	"runtime"
	"strings"
	"sync"
	"testing"
)

func skipDebugLog(t *testing.T) {
	if runtime.DlogEnabled {
		t.Skip("debug log tests disabled to avoid collisions with real debug logs")
	}
}

func dlogCanonicalize(x string) string {
	begin := regexp.MustCompile(`(?m)^>> begin log \d+ <<\n`)
	x = begin.ReplaceAllString(x, "")
	prefix := regexp.MustCompile(`(?m)^\[[^]]+\]`)
	x = prefix.ReplaceAllString(x, "[]")
	return x
}

func TestDebugLog(t *testing.T) {
	skipDebugLog(t)
	runtime.ResetDebugLog()
	runtime.Dlog().S("testing").End()
	got := dlogCanonicalize(runtime.DumpDebugLog())
	if want := "[] testing\n"; got != want {
		t.Fatalf("want %q, got %q", want, got)
	}
}

func TestDebugLogTypes(t *testing.T) {
	skipDebugLog(t)
	runtime.ResetDebugLog()
	var varString = strings.Repeat("a", 4)
	runtime.Dlog().B(true).B(false).I(-42).I16(0x7fff).U64(^uint64(0)).Hex(0xfff).P(nil).S(varString).S("const string").End()
	got := dlogCanonicalize(runtime.DumpDebugLog())
	if want := "[] true false -42 32767 18446744073709551615 0xfff 0x0 aaaa const string\n"; got != want {
		t.Fatalf("want %q, got %q", want, got)
	}
}

func TestDebugLogSym(t *testing.T) {
	skipDebugLog(t)
	runtime.ResetDebugLog()
	pc, _, _, _ := runtime.Caller(0)
	runtime.Dlog().PC(pc).End()
	got := dlogCanonicalize(runtime.DumpDebugLog())
	want := regexp.MustCompile(`\[\] 0x[0-9a-f]+ \[runtime_test\.TestDebugLogSym\+0x[0-9a-f]+ .*/debuglog_test\.go:[0-9]+\]\n`)
	if !want.MatchString(got) {
		t.Fatalf("want matching %s, got %q", want, got)
	}
}

func TestDebugLogInterleaving(t *testing.T) {
	skipDebugLog(t)
	runtime.ResetDebugLog()

	n1 := runtime.CountDebugLog()
	t.Logf("number of log shards at start: %d", n1)

	const limit = 1000
	const concurrency = 10

	// Start several goroutines writing to the log simultaneously.
	var wg sync.WaitGroup
	i := 0
	chans := make([]chan bool, concurrency)
	for gid := range concurrency {
		chans[gid] = make(chan bool)
		wg.Add(1)
		go func() {
			defer wg.Done()
			var log *runtime.Dlogger
			for {
				<-chans[gid]
				if log != nil {
					log.End()
				}
				next := chans[(gid+1)%len(chans)]
				if i >= limit {
					close(next)
					break
				}
				// Log an entry, but *don't* release the log shard until its our
				// turn again. This should result in at least n=concurrency log
				// shards.
				log = runtime.Dlog().I(i)
				i++
				// Wake up the next logger goroutine.
				next <- true
			}
		}()
	}
	// Start the chain reaction.
	chans[0] <- true

	// Wait for them to finish and get the log.
	wg.Wait()
	gotFull := runtime.DumpDebugLog()
	got := dlogCanonicalize(gotFull)

	n2 := runtime.CountDebugLog()
	t.Logf("number of log shards at end: %d", n2)
	if n2 < concurrency {
		t.Errorf("created %d log shards, expected >= %d", n2, concurrency)
	}

	// Construct the desired output.
	var want strings.Builder
	for i := 0; i < limit; i++ {
		fmt.Fprintf(&want, "[] %d\n", i)
	}

	if got != want.String() {
		// Since the timestamps are useful in understand
		// failures of this test, we print the uncanonicalized
		// output.
		t.Fatalf("want %q, got (uncanonicalized) %q", want.String(), gotFull)
	}
}

func TestDebugLogWraparound(t *testing.T) {
	skipDebugLog(t)

	// Make sure we don't switch logs so it's easier to fill one up.
	runtime.LockOSThread()
	defer runtime.UnlockOSThread()

	runtime.ResetDebugLog()
	var longString = strings.Repeat("a", 128)
	var want strings.Builder
	for i, j := 0, 0; j < 2*runtime.DebugLogBytes; i, j = i+1, j+len(longString) {
		runtime.Dlog().I(i).S(longString).End()
		fmt.Fprintf(&want, "[] %d %s\n", i, longString)
	}
	log := runtime.DumpDebugLog()

	// Check for "lost" message.
	lost := regexp.MustCompile(`^>> begin log \d+; lost first \d+KB <<\n`)
	if !lost.MatchString(log) {
		t.Fatalf("want matching %s, got %q", lost, log)
	}
	idx := lost.FindStringIndex(log)
	// Strip lost message.
	log = dlogCanonicalize(log[idx[1]:])

	// Check log.
	if !strings.HasSuffix(want.String(), log) {
		t.Fatalf("wrong suffix:\n%s", log)
	}
}

func TestDebugLogLongString(t *testing.T) {
	skipDebugLog(t)

	runtime.ResetDebugLog()
	var longString = strings.Repeat("a", runtime.DebugLogStringLimit+1)
	runtime.Dlog().S(longString).End()
	got := dlogCanonicalize(runtime.DumpDebugLog())
	want := "[] " + strings.Repeat("a", runtime.DebugLogStringLimit) + " ..(1 more bytes)..\n"
	if got != want {
		t.Fatalf("want %q, got %q", want, got)
	}
}