1// Copyright 2019 The Go Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style
3// license that can be found in the LICENSE file.
4
5// TODO(austin): All of these tests are skipped if the debuglog build
6// tag isn't provided. That means we basically never test debuglog.
7// There are two potential ways around this:
8//
9// 1. Make these tests re-build the runtime test with the debuglog
10// build tag and re-invoke themselves.
11//
12// 2. Always build the whole debuglog infrastructure and depend on
13// linker dead-code elimination to drop it. This is easy for dlog()
14// since there won't be any calls to it. For printDebugLog, we can
15// make panic call a wrapper that is call printDebugLog if the
16// debuglog build tag is set, or otherwise do nothing. Then tests
17// could call printDebugLog directly. This is the right answer in
18// principle, but currently our linker reads in all symbols
19// regardless, so this would slow down and bloat all links. If the
20// linker gets more efficient about this, we should revisit this
21// approach.
22
23package runtime_test
24
25import (
26	"bytes"
27	"fmt"
28	"regexp"
29	"runtime"
30	"strings"
31	"sync"
32	"sync/atomic"
33	"testing"
34)
35
36func skipDebugLog(t *testing.T) {
37	if !runtime.DlogEnabled {
38		t.Skip("debug log disabled (rebuild with -tags debuglog)")
39	}
40}
41
42func dlogCanonicalize(x string) string {
43	begin := regexp.MustCompile(`(?m)^>> begin log \d+ <<\n`)
44	x = begin.ReplaceAllString(x, "")
45	prefix := regexp.MustCompile(`(?m)^\[[^]]+\]`)
46	x = prefix.ReplaceAllString(x, "[]")
47	return x
48}
49
50func TestDebugLog(t *testing.T) {
51	skipDebugLog(t)
52	runtime.ResetDebugLog()
53	runtime.Dlog().S("testing").End()
54	got := dlogCanonicalize(runtime.DumpDebugLog())
55	if want := "[] testing\n"; got != want {
56		t.Fatalf("want %q, got %q", want, got)
57	}
58}
59
60func TestDebugLogTypes(t *testing.T) {
61	skipDebugLog(t)
62	runtime.ResetDebugLog()
63	var varString = strings.Repeat("a", 4)
64	runtime.Dlog().B(true).B(false).I(-42).I16(0x7fff).U64(^uint64(0)).Hex(0xfff).P(nil).S(varString).S("const string").End()
65	got := dlogCanonicalize(runtime.DumpDebugLog())
66	if want := "[] true false -42 32767 18446744073709551615 0xfff 0x0 aaaa const string\n"; got != want {
67		t.Fatalf("want %q, got %q", want, got)
68	}
69}
70
71func TestDebugLogSym(t *testing.T) {
72	skipDebugLog(t)
73	runtime.ResetDebugLog()
74	pc, _, _, _ := runtime.Caller(0)
75	runtime.Dlog().PC(pc).End()
76	got := dlogCanonicalize(runtime.DumpDebugLog())
77	want := regexp.MustCompile(`\[\] 0x[0-9a-f]+ \[runtime_test\.TestDebugLogSym\+0x[0-9a-f]+ .*/debuglog_test\.go:[0-9]+\]\n`)
78	if !want.MatchString(got) {
79		t.Fatalf("want matching %s, got %q", want, got)
80	}
81}
82
83func TestDebugLogInterleaving(t *testing.T) {
84	skipDebugLog(t)
85	runtime.ResetDebugLog()
86	var wg sync.WaitGroup
87	done := int32(0)
88	wg.Add(1)
89	go func() {
90		// Encourage main goroutine to move around to
91		// different Ms and Ps.
92		for atomic.LoadInt32(&done) == 0 {
93			runtime.Gosched()
94		}
95		wg.Done()
96	}()
97	var want bytes.Buffer
98	for i := 0; i < 1000; i++ {
99		runtime.Dlog().I(i).End()
100		fmt.Fprintf(&want, "[] %d\n", i)
101		runtime.Gosched()
102	}
103	atomic.StoreInt32(&done, 1)
104	wg.Wait()
105
106	gotFull := runtime.DumpDebugLog()
107	got := dlogCanonicalize(gotFull)
108	if got != want.String() {
109		// Since the timestamps are useful in understand
110		// failures of this test, we print the uncanonicalized
111		// output.
112		t.Fatalf("want %q, got (uncanonicalized) %q", want.String(), gotFull)
113	}
114}
115
116func TestDebugLogWraparound(t *testing.T) {
117	skipDebugLog(t)
118
119	// Make sure we don't switch logs so it's easier to fill one up.
120	runtime.LockOSThread()
121	defer runtime.UnlockOSThread()
122
123	runtime.ResetDebugLog()
124	var longString = strings.Repeat("a", 128)
125	var want bytes.Buffer
126	for i, j := 0, 0; j < 2*runtime.DebugLogBytes; i, j = i+1, j+len(longString) {
127		runtime.Dlog().I(i).S(longString).End()
128		fmt.Fprintf(&want, "[] %d %s\n", i, longString)
129	}
130	log := runtime.DumpDebugLog()
131
132	// Check for "lost" message.
133	lost := regexp.MustCompile(`^>> begin log \d+; lost first \d+KB <<\n`)
134	if !lost.MatchString(log) {
135		t.Fatalf("want matching %s, got %q", lost, log)
136	}
137	idx := lost.FindStringIndex(log)
138	// Strip lost message.
139	log = dlogCanonicalize(log[idx[1]:])
140
141	// Check log.
142	if !strings.HasSuffix(want.String(), log) {
143		t.Fatalf("wrong suffix:\n%s", log)
144	}
145}
146
147func TestDebugLogLongString(t *testing.T) {
148	skipDebugLog(t)
149
150	runtime.ResetDebugLog()
151	var longString = strings.Repeat("a", runtime.DebugLogStringLimit+1)
152	runtime.Dlog().S(longString).End()
153	got := dlogCanonicalize(runtime.DumpDebugLog())
154	want := "[] " + strings.Repeat("a", runtime.DebugLogStringLimit) + " ..(1 more bytes)..\n"
155	if got != want {
156		t.Fatalf("want %q, got %q", want, got)
157	}
158}
159