debuglog_test.go

     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  
    23  package runtime_test
    24  
    25  import (
    26  	"bytes"
    27  	"fmt"
    28  	"regexp"
    29  	"runtime"
    30  	"strings"
    31  	"sync"
    32  	"sync/atomic"
    33  	"testing"
    34  )
    35  
    36  func skipDebugLog(t *testing.T) {
    37  	if !runtime.DlogEnabled {
    38  		t.Skip("debug log disabled (rebuild with -tags debuglog)")
    39  	}
    40  }
    41  
    42  func 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  
    50  func 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  
    60  func 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  
    71  func 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  
    83  func 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  
   116  func 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  
   147  func 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
View as plain text