log_test.go

     1  // Copyright 2009 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  package log
     6  
     7  // These tests are too simple.
     8  
     9  import (
    10  	"bytes"
    11  	"fmt"
    12  	"io"
    13  	"os"
    14  	"regexp"
    15  	"runtime"
    16  	"strings"
    17  	"sync"
    18  	"testing"
    19  	"time"
    20  )
    21  
    22  const (
    23  	Rdate         = `[0-9][0-9][0-9][0-9]/[0-9][0-9]/[0-9][0-9]`
    24  	Rtime         = `[0-9][0-9]:[0-9][0-9]:[0-9][0-9]`
    25  	Rmicroseconds = `\.[0-9][0-9][0-9][0-9][0-9][0-9]`
    26  	Rline         = `(63|65):` // must update if the calls to l.Printf / l.Print below move
    27  	Rlongfile     = `.*/[A-Za-z0-9_\-]+\.go:` + Rline
    28  	Rshortfile    = `[A-Za-z0-9_\-]+\.go:` + Rline
    29  )
    30  
    31  type tester struct {
    32  	flag    int
    33  	prefix  string
    34  	pattern string // regexp that log output must match; we add ^ and expected_text$ always
    35  }
    36  
    37  var tests = []tester{
    38  	// individual pieces:
    39  	{0, "", ""},
    40  	{0, "XXX", "XXX"},
    41  	{Ldate, "", Rdate + " "},
    42  	{Ltime, "", Rtime + " "},
    43  	{Ltime | Lmsgprefix, "XXX", Rtime + " XXX"},
    44  	{Ltime | Lmicroseconds, "", Rtime + Rmicroseconds + " "},
    45  	{Lmicroseconds, "", Rtime + Rmicroseconds + " "}, // microsec implies time
    46  	{Llongfile, "", Rlongfile + " "},
    47  	{Lshortfile, "", Rshortfile + " "},
    48  	{Llongfile | Lshortfile, "", Rshortfile + " "}, // shortfile overrides longfile
    49  	// everything at once:
    50  	{Ldate | Ltime | Lmicroseconds | Llongfile, "XXX", "XXX" + Rdate + " " + Rtime + Rmicroseconds + " " + Rlongfile + " "},
    51  	{Ldate | Ltime | Lmicroseconds | Lshortfile, "XXX", "XXX" + Rdate + " " + Rtime + Rmicroseconds + " " + Rshortfile + " "},
    52  	{Ldate | Ltime | Lmicroseconds | Llongfile | Lmsgprefix, "XXX", Rdate + " " + Rtime + Rmicroseconds + " " + Rlongfile + " XXX"},
    53  	{Ldate | Ltime | Lmicroseconds | Lshortfile | Lmsgprefix, "XXX", Rdate + " " + Rtime + Rmicroseconds + " " + Rshortfile + " XXX"},
    54  }
    55  
    56  // Test using Println("hello", 23, "world") or using Printf("hello %d world", 23)
    57  func testPrint(t *testing.T, flag int, prefix string, pattern string, useFormat bool) {
    58  	buf := new(strings.Builder)
    59  	SetOutput(buf)
    60  	SetFlags(flag)
    61  	SetPrefix(prefix)
    62  	if useFormat {
    63  		Printf("hello %d world", 23)
    64  	} else {
    65  		Println("hello", 23, "world")
    66  	}
    67  	line := buf.String()
    68  	line = line[0 : len(line)-1]
    69  	pattern = "^" + pattern + "hello 23 world$"
    70  	matched, err := regexp.MatchString(pattern, line)
    71  	if err != nil {
    72  		t.Fatal("pattern did not compile:", err)
    73  	}
    74  	if !matched {
    75  		t.Errorf("log output should match %q is %q", pattern, line)
    76  	}
    77  	SetOutput(os.Stderr)
    78  }
    79  
    80  func TestDefault(t *testing.T) {
    81  	if got := Default(); got != std {
    82  		t.Errorf("Default [%p] should be std [%p]", got, std)
    83  	}
    84  }
    85  
    86  func TestAll(t *testing.T) {
    87  	for _, testcase := range tests {
    88  		testPrint(t, testcase.flag, testcase.prefix, testcase.pattern, false)
    89  		testPrint(t, testcase.flag, testcase.prefix, testcase.pattern, true)
    90  	}
    91  }
    92  
    93  func TestOutput(t *testing.T) {
    94  	const testString = "test"
    95  	var b strings.Builder
    96  	l := New(&b, "", 0)
    97  	l.Println(testString)
    98  	if expect := testString + "\n"; b.String() != expect {
    99  		t.Errorf("log output should match %q is %q", expect, b.String())
   100  	}
   101  }
   102  
   103  func TestNonNewLogger(t *testing.T) {
   104  	var l Logger
   105  	l.SetOutput(new(bytes.Buffer)) // minimal work to initialize a Logger
   106  	l.Print("hello")
   107  }
   108  
   109  func TestOutputRace(t *testing.T) {
   110  	var b bytes.Buffer
   111  	l := New(&b, "", 0)
   112  	var wg sync.WaitGroup
   113  	wg.Add(100)
   114  	for i := 0; i < 100; i++ {
   115  		go func() {
   116  			defer wg.Done()
   117  			l.SetFlags(0)
   118  			l.Output(0, "")
   119  		}()
   120  	}
   121  	wg.Wait()
   122  }
   123  
   124  func TestFlagAndPrefixSetting(t *testing.T) {
   125  	var b bytes.Buffer
   126  	l := New(&b, "Test:", LstdFlags)
   127  	f := l.Flags()
   128  	if f != LstdFlags {
   129  		t.Errorf("Flags 1: expected %x got %x", LstdFlags, f)
   130  	}
   131  	l.SetFlags(f | Lmicroseconds)
   132  	f = l.Flags()
   133  	if f != LstdFlags|Lmicroseconds {
   134  		t.Errorf("Flags 2: expected %x got %x", LstdFlags|Lmicroseconds, f)
   135  	}
   136  	p := l.Prefix()
   137  	if p != "Test:" {
   138  		t.Errorf(`Prefix: expected "Test:" got %q`, p)
   139  	}
   140  	l.SetPrefix("Reality:")
   141  	p = l.Prefix()
   142  	if p != "Reality:" {
   143  		t.Errorf(`Prefix: expected "Reality:" got %q`, p)
   144  	}
   145  	// Verify a log message looks right, with our prefix and microseconds present.
   146  	l.Print("hello")
   147  	pattern := "^Reality:" + Rdate + " " + Rtime + Rmicroseconds + " hello\n"
   148  	matched, err := regexp.Match(pattern, b.Bytes())
   149  	if err != nil {
   150  		t.Fatalf("pattern %q did not compile: %s", pattern, err)
   151  	}
   152  	if !matched {
   153  		t.Error("message did not match pattern")
   154  	}
   155  
   156  	// Ensure that a newline is added only if the buffer lacks a newline suffix.
   157  	b.Reset()
   158  	l.SetFlags(0)
   159  	l.SetPrefix("\n")
   160  	l.Output(0, "")
   161  	if got := b.String(); got != "\n" {
   162  		t.Errorf("message mismatch:\ngot  %q\nwant %q", got, "\n")
   163  	}
   164  }
   165  
   166  func TestUTCFlag(t *testing.T) {
   167  	var b strings.Builder
   168  	l := New(&b, "Test:", LstdFlags)
   169  	l.SetFlags(Ldate | Ltime | LUTC)
   170  	// Verify a log message looks right in the right time zone. Quantize to the second only.
   171  	now := time.Now().UTC()
   172  	l.Print("hello")
   173  	want := fmt.Sprintf("Test:%d/%.2d/%.2d %.2d:%.2d:%.2d hello\n",
   174  		now.Year(), now.Month(), now.Day(), now.Hour(), now.Minute(), now.Second())
   175  	got := b.String()
   176  	if got == want {
   177  		return
   178  	}
   179  	// It's possible we crossed a second boundary between getting now and logging,
   180  	// so add a second and try again. This should very nearly always work.
   181  	now = now.Add(time.Second)
   182  	want = fmt.Sprintf("Test:%d/%.2d/%.2d %.2d:%.2d:%.2d hello\n",
   183  		now.Year(), now.Month(), now.Day(), now.Hour(), now.Minute(), now.Second())
   184  	if got == want {
   185  		return
   186  	}
   187  	t.Errorf("got %q; want %q", got, want)
   188  }
   189  
   190  func TestEmptyPrintCreatesLine(t *testing.T) {
   191  	var b strings.Builder
   192  	l := New(&b, "Header:", LstdFlags)
   193  	l.Print()
   194  	l.Println("non-empty")
   195  	output := b.String()
   196  	if n := strings.Count(output, "Header"); n != 2 {
   197  		t.Errorf("expected 2 headers, got %d", n)
   198  	}
   199  	if n := strings.Count(output, "\n"); n != 2 {
   200  		t.Errorf("expected 2 lines, got %d", n)
   201  	}
   202  }
   203  
   204  func TestDiscard(t *testing.T) {
   205  	l := New(io.Discard, "", 0)
   206  	s := strings.Repeat("a", 102400)
   207  	c := testing.AllocsPerRun(100, func() { l.Printf("%s", s) })
   208  	// One allocation for slice passed to Printf,
   209  	// but none for formatting of long string.
   210  	if c > 1 {
   211  		t.Errorf("got %v allocs, want at most 1", c)
   212  	}
   213  }
   214  
   215  func BenchmarkItoa(b *testing.B) {
   216  	dst := make([]byte, 0, 64)
   217  	for i := 0; i < b.N; i++ {
   218  		dst = dst[0:0]
   219  		itoa(&dst, 2015, 4)   // year
   220  		itoa(&dst, 1, 2)      // month
   221  		itoa(&dst, 30, 2)     // day
   222  		itoa(&dst, 12, 2)     // hour
   223  		itoa(&dst, 56, 2)     // minute
   224  		itoa(&dst, 0, 2)      // second
   225  		itoa(&dst, 987654, 6) // microsecond
   226  	}
   227  }
   228  
   229  func BenchmarkPrintln(b *testing.B) {
   230  	const testString = "test"
   231  	var buf bytes.Buffer
   232  	l := New(&buf, "", LstdFlags)
   233  	b.ReportAllocs()
   234  	for i := 0; i < b.N; i++ {
   235  		buf.Reset()
   236  		l.Println(testString)
   237  	}
   238  }
   239  
   240  func BenchmarkPrintlnNoFlags(b *testing.B) {
   241  	const testString = "test"
   242  	var buf bytes.Buffer
   243  	l := New(&buf, "", 0)
   244  	b.ReportAllocs()
   245  	for i := 0; i < b.N; i++ {
   246  		buf.Reset()
   247  		l.Println(testString)
   248  	}
   249  }
   250  
   251  // discard is identical to io.Discard,
   252  // but copied here to avoid the io.Discard optimization in Logger.
   253  type discard struct{}
   254  
   255  func (discard) Write(p []byte) (int, error) {
   256  	return len(p), nil
   257  }
   258  
   259  func BenchmarkConcurrent(b *testing.B) {
   260  	l := New(discard{}, "prefix: ", Ldate|Ltime|Lmicroseconds|Llongfile|Lmsgprefix)
   261  	var group sync.WaitGroup
   262  	for i := runtime.NumCPU(); i > 0; i-- {
   263  		group.Add(1)
   264  		go func() {
   265  			for i := 0; i < b.N; i++ {
   266  				l.Output(0, "hello, world!")
   267  			}
   268  			defer group.Done()
   269  		}()
   270  	}
   271  	group.Wait()
   272  }
   273  
   274  func BenchmarkDiscard(b *testing.B) {
   275  	l := New(io.Discard, "", LstdFlags|Lshortfile)
   276  	b.ReportAllocs()
   277  	for i := 0; i < b.N; i++ {
   278  		l.Printf("processing %d objects from bucket %q", 1234, "fizzbuzz")
   279  	}
   280  }
   281
View as plain text