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  	"bufio"
    11  	"bytes"
    12  	"errors"
    13  	"fmt"
    14  	"internal/testenv"
    15  	"io"
    16  	"os"
    17  	"os/exec"
    18  	"regexp"
    19  	"runtime"
    20  	"strings"
    21  	"sync"
    22  	"testing"
    23  	"time"
    24  )
    25  
    26  const (
    27  	Rdate         = `[0-9][0-9][0-9][0-9]/[0-9][0-9]/[0-9][0-9]`
    28  	Rtime         = `[0-9][0-9]:[0-9][0-9]:[0-9][0-9]`
    29  	Rmicroseconds = `\.[0-9][0-9][0-9][0-9][0-9][0-9]`
    30  	Rline         = `(67|69):` // must update if the calls to l.Printf / l.Print below move
    31  	Rlongfile     = `.*/[A-Za-z0-9_\-]+\.go:` + Rline
    32  	Rshortfile    = `[A-Za-z0-9_\-]+\.go:` + Rline
    33  )
    34  
    35  type tester struct {
    36  	flag    int
    37  	prefix  string
    38  	pattern string // regexp that log output must match; we add ^ and expected_text$ always
    39  }
    40  
    41  var tests = []tester{
    42  	// individual pieces:
    43  	{0, "", ""},
    44  	{0, "XXX", "XXX"},
    45  	{Ldate, "", Rdate + " "},
    46  	{Ltime, "", Rtime + " "},
    47  	{Ltime | Lmsgprefix, "XXX", Rtime + " XXX"},
    48  	{Ltime | Lmicroseconds, "", Rtime + Rmicroseconds + " "},
    49  	{Lmicroseconds, "", Rtime + Rmicroseconds + " "}, // microsec implies time
    50  	{Llongfile, "", Rlongfile + " "},
    51  	{Lshortfile, "", Rshortfile + " "},
    52  	{Llongfile | Lshortfile, "", Rshortfile + " "}, // shortfile overrides longfile
    53  	// everything at once:
    54  	{Ldate | Ltime | Lmicroseconds | Llongfile, "XXX", "XXX" + Rdate + " " + Rtime + Rmicroseconds + " " + Rlongfile + " "},
    55  	{Ldate | Ltime | Lmicroseconds | Lshortfile, "XXX", "XXX" + Rdate + " " + Rtime + Rmicroseconds + " " + Rshortfile + " "},
    56  	{Ldate | Ltime | Lmicroseconds | Llongfile | Lmsgprefix, "XXX", Rdate + " " + Rtime + Rmicroseconds + " " + Rlongfile + " XXX"},
    57  	{Ldate | Ltime | Lmicroseconds | Lshortfile | Lmsgprefix, "XXX", Rdate + " " + Rtime + Rmicroseconds + " " + Rshortfile + " XXX"},
    58  }
    59  
    60  // Test using Println("hello", 23, "world") or using Printf("hello %d world", 23)
    61  func testPrint(t *testing.T, flag int, prefix string, pattern string, useFormat bool) {
    62  	buf := new(strings.Builder)
    63  	SetOutput(buf)
    64  	SetFlags(flag)
    65  	SetPrefix(prefix)
    66  	if useFormat {
    67  		Printf("hello %d world", 23)
    68  	} else {
    69  		Println("hello", 23, "world")
    70  	}
    71  	line := buf.String()
    72  	line = line[0 : len(line)-1]
    73  	pattern = "^" + pattern + "hello 23 world$"
    74  	matched, err := regexp.MatchString(pattern, line)
    75  	if err != nil {
    76  		t.Fatal("pattern did not compile:", err)
    77  	}
    78  	if !matched {
    79  		t.Errorf("log output should match %q is %q", pattern, line)
    80  	}
    81  	SetOutput(os.Stderr)
    82  }
    83  
    84  func TestDefault(t *testing.T) {
    85  	if got := Default(); got != std {
    86  		t.Errorf("Default [%p] should be std [%p]", got, std)
    87  	}
    88  }
    89  
    90  func TestAll(t *testing.T) {
    91  	for _, testcase := range tests {
    92  		testPrint(t, testcase.flag, testcase.prefix, testcase.pattern, false)
    93  		testPrint(t, testcase.flag, testcase.prefix, testcase.pattern, true)
    94  	}
    95  }
    96  
    97  func TestOutput(t *testing.T) {
    98  	const testString = "test"
    99  	var b strings.Builder
   100  	l := New(&b, "", 0)
   101  	l.Println(testString)
   102  	if expect := testString + "\n"; b.String() != expect {
   103  		t.Errorf("log output should match %q is %q", expect, b.String())
   104  	}
   105  }
   106  
   107  func TestNonNewLogger(t *testing.T) {
   108  	var l Logger
   109  	l.SetOutput(new(bytes.Buffer)) // minimal work to initialize a Logger
   110  	l.Print("hello")
   111  }
   112  
   113  func TestOutputRace(t *testing.T) {
   114  	var b bytes.Buffer
   115  	l := New(&b, "", 0)
   116  	var wg sync.WaitGroup
   117  	wg.Add(100)
   118  	for i := 0; i < 100; i++ {
   119  		go func() {
   120  			defer wg.Done()
   121  			l.SetFlags(0)
   122  			l.Output(0, "")
   123  		}()
   124  	}
   125  	wg.Wait()
   126  }
   127  
   128  func TestFlagAndPrefixSetting(t *testing.T) {
   129  	var b bytes.Buffer
   130  	l := New(&b, "Test:", LstdFlags)
   131  	f := l.Flags()
   132  	if f != LstdFlags {
   133  		t.Errorf("Flags 1: expected %x got %x", LstdFlags, f)
   134  	}
   135  	l.SetFlags(f | Lmicroseconds)
   136  	f = l.Flags()
   137  	if f != LstdFlags|Lmicroseconds {
   138  		t.Errorf("Flags 2: expected %x got %x", LstdFlags|Lmicroseconds, f)
   139  	}
   140  	p := l.Prefix()
   141  	if p != "Test:" {
   142  		t.Errorf(`Prefix: expected "Test:" got %q`, p)
   143  	}
   144  	l.SetPrefix("Reality:")
   145  	p = l.Prefix()
   146  	if p != "Reality:" {
   147  		t.Errorf(`Prefix: expected "Reality:" got %q`, p)
   148  	}
   149  	// Verify a log message looks right, with our prefix and microseconds present.
   150  	l.Print("hello")
   151  	pattern := "^Reality:" + Rdate + " " + Rtime + Rmicroseconds + " hello\n"
   152  	matched, err := regexp.Match(pattern, b.Bytes())
   153  	if err != nil {
   154  		t.Fatalf("pattern %q did not compile: %s", pattern, err)
   155  	}
   156  	if !matched {
   157  		t.Error("message did not match pattern")
   158  	}
   159  
   160  	// Ensure that a newline is added only if the buffer lacks a newline suffix.
   161  	b.Reset()
   162  	l.SetFlags(0)
   163  	l.SetPrefix("\n")
   164  	l.Output(0, "")
   165  	if got := b.String(); got != "\n" {
   166  		t.Errorf("message mismatch:\ngot  %q\nwant %q", got, "\n")
   167  	}
   168  }
   169  
   170  func TestUTCFlag(t *testing.T) {
   171  	var b strings.Builder
   172  	l := New(&b, "Test:", LstdFlags)
   173  	l.SetFlags(Ldate | Ltime | LUTC)
   174  	// Verify a log message looks right in the right time zone. Quantize to the second only.
   175  	now := time.Now().UTC()
   176  	l.Print("hello")
   177  	want := fmt.Sprintf("Test:%d/%.2d/%.2d %.2d:%.2d:%.2d hello\n",
   178  		now.Year(), now.Month(), now.Day(), now.Hour(), now.Minute(), now.Second())
   179  	got := b.String()
   180  	if got == want {
   181  		return
   182  	}
   183  	// It's possible we crossed a second boundary between getting now and logging,
   184  	// so add a second and try again. This should very nearly always work.
   185  	now = now.Add(time.Second)
   186  	want = fmt.Sprintf("Test:%d/%.2d/%.2d %.2d:%.2d:%.2d hello\n",
   187  		now.Year(), now.Month(), now.Day(), now.Hour(), now.Minute(), now.Second())
   188  	if got == want {
   189  		return
   190  	}
   191  	t.Errorf("got %q; want %q", got, want)
   192  }
   193  
   194  func TestEmptyPrintCreatesLine(t *testing.T) {
   195  	var b strings.Builder
   196  	l := New(&b, "Header:", LstdFlags)
   197  	l.Print()
   198  	l.Println("non-empty")
   199  	output := b.String()
   200  	if n := strings.Count(output, "Header"); n != 2 {
   201  		t.Errorf("expected 2 headers, got %d", n)
   202  	}
   203  	if n := strings.Count(output, "\n"); n != 2 {
   204  		t.Errorf("expected 2 lines, got %d", n)
   205  	}
   206  }
   207  
   208  func TestDiscard(t *testing.T) {
   209  	l := New(io.Discard, "", 0)
   210  	s := strings.Repeat("a", 102400)
   211  	c := testing.AllocsPerRun(100, func() { l.Printf("%s", s) })
   212  	// One allocation for slice passed to Printf,
   213  	// but none for formatting of long string.
   214  	if c > 1 {
   215  		t.Errorf("got %v allocs, want at most 1", c)
   216  	}
   217  }
   218  
   219  func TestCallDepth(t *testing.T) {
   220  	if testing.Short() {
   221  		t.Skip("skipping test in short mode")
   222  	}
   223  
   224  	testenv.MustHaveExec(t)
   225  	ep, err := os.Executable()
   226  	if err != nil {
   227  		t.Fatalf("Executable failed: %v", err)
   228  	}
   229  
   230  	tests := []struct {
   231  		name string
   232  		log  func()
   233  	}{
   234  		{"Fatal", func() { Fatal("Fatal") }},
   235  		{"Fatalf", func() { Fatalf("Fatalf") }},
   236  		{"Fatalln", func() { Fatalln("Fatalln") }},
   237  		{"Output", func() { Output(1, "Output") }},
   238  		{"Panic", func() { Panic("Panic") }},
   239  		{"Panicf", func() { Panicf("Panicf") }},
   240  		{"Panicln", func() { Panicf("Panicln") }},
   241  		{"Default.Fatal", func() { Default().Fatal("Default.Fatal") }},
   242  		{"Default.Fatalf", func() { Default().Fatalf("Default.Fatalf") }},
   243  		{"Default.Fatalln", func() { Default().Fatalln("Default.Fatalln") }},
   244  		{"Default.Output", func() { Default().Output(1, "Default.Output") }},
   245  		{"Default.Panic", func() { Default().Panic("Default.Panic") }},
   246  		{"Default.Panicf", func() { Default().Panicf("Default.Panicf") }},
   247  		{"Default.Panicln", func() { Default().Panicf("Default.Panicln") }},
   248  	}
   249  
   250  	// calculate the line offset until the first test case
   251  	_, _, line, ok := runtime.Caller(0)
   252  	if !ok {
   253  		t.Fatalf("runtime.Caller failed")
   254  	}
   255  	line -= len(tests) + 3
   256  
   257  	for i, tt := range tests {
   258  		t.Run(tt.name, func(t *testing.T) {
   259  			// some of these calls uses os.Exit() to spawn a command and capture output
   260  			const envVar = "LOGTEST_CALL_DEPTH"
   261  			if os.Getenv(envVar) == "1" {
   262  				SetFlags(Lshortfile)
   263  				tt.log()
   264  				os.Exit(1)
   265  			}
   266  
   267  			// spawn test executable
   268  			cmd := testenv.Command(t, ep,
   269  				"-test.run=^"+regexp.QuoteMeta(t.Name())+"$",
   270  				"-test.count=1",
   271  			)
   272  			cmd.Env = append(cmd.Environ(), envVar+"=1")
   273  
   274  			out, err := cmd.CombinedOutput()
   275  			var exitErr *exec.ExitError
   276  			if !errors.As(err, &exitErr) {
   277  				t.Fatalf("expected exec.ExitError: %v", err)
   278  			}
   279  
   280  			_, firstLine, err := bufio.ScanLines(out, true)
   281  			if err != nil {
   282  				t.Fatalf("failed to split line: %v", err)
   283  			}
   284  			got := string(firstLine)
   285  
   286  			want := fmt.Sprintf(
   287  				"log_test.go:%d: %s",
   288  				line+i, tt.name,
   289  			)
   290  			if got != want {
   291  				t.Errorf(
   292  					"output from %s() mismatch:\n\t got: %s\n\twant: %s",
   293  					tt.name, got, want,
   294  				)
   295  			}
   296  		})
   297  	}
   298  }
   299  
   300  func BenchmarkItoa(b *testing.B) {
   301  	dst := make([]byte, 0, 64)
   302  	for i := 0; i < b.N; i++ {
   303  		dst = dst[0:0]
   304  		itoa(&dst, 2015, 4)   // year
   305  		itoa(&dst, 1, 2)      // month
   306  		itoa(&dst, 30, 2)     // day
   307  		itoa(&dst, 12, 2)     // hour
   308  		itoa(&dst, 56, 2)     // minute
   309  		itoa(&dst, 0, 2)      // second
   310  		itoa(&dst, 987654, 6) // microsecond
   311  	}
   312  }
   313  
   314  func BenchmarkPrintln(b *testing.B) {
   315  	const testString = "test"
   316  	var buf bytes.Buffer
   317  	l := New(&buf, "", LstdFlags)
   318  	b.ReportAllocs()
   319  	for i := 0; i < b.N; i++ {
   320  		buf.Reset()
   321  		l.Println(testString)
   322  	}
   323  }
   324  
   325  func BenchmarkPrintlnNoFlags(b *testing.B) {
   326  	const testString = "test"
   327  	var buf bytes.Buffer
   328  	l := New(&buf, "", 0)
   329  	b.ReportAllocs()
   330  	for i := 0; i < b.N; i++ {
   331  		buf.Reset()
   332  		l.Println(testString)
   333  	}
   334  }
   335  
   336  // discard is identical to io.Discard,
   337  // but copied here to avoid the io.Discard optimization in Logger.
   338  type discard struct{}
   339  
   340  func (discard) Write(p []byte) (int, error) {
   341  	return len(p), nil
   342  }
   343  
   344  func BenchmarkConcurrent(b *testing.B) {
   345  	l := New(discard{}, "prefix: ", Ldate|Ltime|Lmicroseconds|Llongfile|Lmsgprefix)
   346  	var group sync.WaitGroup
   347  	for i := runtime.NumCPU(); i > 0; i-- {
   348  		group.Add(1)
   349  		go func() {
   350  			for i := 0; i < b.N; i++ {
   351  				l.Output(0, "hello, world!")
   352  			}
   353  			defer group.Done()
   354  		}()
   355  	}
   356  	group.Wait()
   357  }
   358  
   359  func BenchmarkDiscard(b *testing.B) {
   360  	l := New(io.Discard, "", LstdFlags|Lshortfile)
   361  	b.ReportAllocs()
   362  	for i := 0; i < b.N; i++ {
   363  		l.Printf("processing %d objects from bucket %q", 1234, "fizzbuzz")
   364  	}
   365  }
   366
View as plain text