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  	"fmt"
    27  	"regexp"
    28  	"runtime"
    29  	"strings"
    30  	"sync"
    31  	"testing"
    32  )
    33  
    34  func skipDebugLog(t *testing.T) {
    35  	if runtime.DlogEnabled {
    36  		t.Skip("debug log tests disabled to avoid collisions with real debug logs")
    37  	}
    38  }
    39  
    40  func dlogCanonicalize(x string) string {
    41  	begin := regexp.MustCompile(`(?m)^>> begin log \d+ <<\n`)
    42  	x = begin.ReplaceAllString(x, "")
    43  	prefix := regexp.MustCompile(`(?m)^\[[^]]+\]`)
    44  	x = prefix.ReplaceAllString(x, "[]")
    45  	return x
    46  }
    47  
    48  func TestDebugLog(t *testing.T) {
    49  	skipDebugLog(t)
    50  	runtime.ResetDebugLog()
    51  	runtime.Dlog().S("testing").End()
    52  	got := dlogCanonicalize(runtime.DumpDebugLog())
    53  	if want := "[] testing\n"; got != want {
    54  		t.Fatalf("want %q, got %q", want, got)
    55  	}
    56  }
    57  
    58  func TestDebugLogTypes(t *testing.T) {
    59  	skipDebugLog(t)
    60  	runtime.ResetDebugLog()
    61  	var varString = strings.Repeat("a", 4)
    62  	runtime.Dlog().B(true).B(false).I(-42).I16(0x7fff).U64(^uint64(0)).Hex(0xfff).P(nil).S(varString).S("const string").End()
    63  	got := dlogCanonicalize(runtime.DumpDebugLog())
    64  	if want := "[] true false -42 32767 18446744073709551615 0xfff 0x0 aaaa const string\n"; got != want {
    65  		t.Fatalf("want %q, got %q", want, got)
    66  	}
    67  }
    68  
    69  func TestDebugLogSym(t *testing.T) {
    70  	skipDebugLog(t)
    71  	runtime.ResetDebugLog()
    72  	pc, _, _, _ := runtime.Caller(0)
    73  	runtime.Dlog().PC(pc).End()
    74  	got := dlogCanonicalize(runtime.DumpDebugLog())
    75  	want := regexp.MustCompile(`\[\] 0x[0-9a-f]+ \[runtime_test\.TestDebugLogSym\+0x[0-9a-f]+ .*/debuglog_test\.go:[0-9]+\]\n`)
    76  	if !want.MatchString(got) {
    77  		t.Fatalf("want matching %s, got %q", want, got)
    78  	}
    79  }
    80  
    81  func TestDebugLogInterleaving(t *testing.T) {
    82  	skipDebugLog(t)
    83  	runtime.ResetDebugLog()
    84  
    85  	n1 := runtime.CountDebugLog()
    86  	t.Logf("number of log shards at start: %d", n1)
    87  
    88  	const limit = 1000
    89  	const concurrency = 10
    90  
    91  	// Start several goroutines writing to the log simultaneously.
    92  	var wg sync.WaitGroup
    93  	i := 0
    94  	chans := make([]chan bool, concurrency)
    95  	for gid := range concurrency {
    96  		chans[gid] = make(chan bool)
    97  		wg.Add(1)
    98  		go func() {
    99  			defer wg.Done()
   100  			var log *runtime.Dlogger
   101  			for {
   102  				<-chans[gid]
   103  				if log != nil {
   104  					log.End()
   105  				}
   106  				next := chans[(gid+1)%len(chans)]
   107  				if i >= limit {
   108  					close(next)
   109  					break
   110  				}
   111  				// Log an entry, but *don't* release the log shard until its our
   112  				// turn again. This should result in at least n=concurrency log
   113  				// shards.
   114  				log = runtime.Dlog().I(i)
   115  				i++
   116  				// Wake up the next logger goroutine.
   117  				next <- true
   118  			}
   119  		}()
   120  	}
   121  	// Start the chain reaction.
   122  	chans[0] <- true
   123  
   124  	// Wait for them to finish and get the log.
   125  	wg.Wait()
   126  	gotFull := runtime.DumpDebugLog()
   127  	got := dlogCanonicalize(gotFull)
   128  
   129  	n2 := runtime.CountDebugLog()
   130  	t.Logf("number of log shards at end: %d", n2)
   131  	if n2 < concurrency {
   132  		t.Errorf("created %d log shards, expected >= %d", n2, concurrency)
   133  	}
   134  
   135  	// Construct the desired output.
   136  	var want strings.Builder
   137  	for i := 0; i < limit; i++ {
   138  		fmt.Fprintf(&want, "[] %d\n", i)
   139  	}
   140  
   141  	if got != want.String() {
   142  		// Since the timestamps are useful in understand
   143  		// failures of this test, we print the uncanonicalized
   144  		// output.
   145  		t.Fatalf("want %q, got (uncanonicalized) %q", want.String(), gotFull)
   146  	}
   147  }
   148  
   149  func TestDebugLogWraparound(t *testing.T) {
   150  	skipDebugLog(t)
   151  
   152  	// Make sure we don't switch logs so it's easier to fill one up.
   153  	runtime.LockOSThread()
   154  	defer runtime.UnlockOSThread()
   155  
   156  	runtime.ResetDebugLog()
   157  	var longString = strings.Repeat("a", 128)
   158  	var want strings.Builder
   159  	for i, j := 0, 0; j < 2*runtime.DebugLogBytes; i, j = i+1, j+len(longString) {
   160  		runtime.Dlog().I(i).S(longString).End()
   161  		fmt.Fprintf(&want, "[] %d %s\n", i, longString)
   162  	}
   163  	log := runtime.DumpDebugLog()
   164  
   165  	// Check for "lost" message.
   166  	lost := regexp.MustCompile(`^>> begin log \d+; lost first \d+KB <<\n`)
   167  	if !lost.MatchString(log) {
   168  		t.Fatalf("want matching %s, got %q", lost, log)
   169  	}
   170  	idx := lost.FindStringIndex(log)
   171  	// Strip lost message.
   172  	log = dlogCanonicalize(log[idx[1]:])
   173  
   174  	// Check log.
   175  	if !strings.HasSuffix(want.String(), log) {
   176  		t.Fatalf("wrong suffix:\n%s", log)
   177  	}
   178  }
   179  
   180  func TestDebugLogLongString(t *testing.T) {
   181  	skipDebugLog(t)
   182  
   183  	runtime.ResetDebugLog()
   184  	var longString = strings.Repeat("a", runtime.DebugLogStringLimit+1)
   185  	runtime.Dlog().S(longString).End()
   186  	got := dlogCanonicalize(runtime.DumpDebugLog())
   187  	want := "[] " + strings.Repeat("a", runtime.DebugLogStringLimit) + " ..(1 more bytes)..\n"
   188  	if got != want {
   189  		t.Fatalf("want %q, got %q", want, got)
   190  	}
   191  }
   192
View as plain text