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
5package log
6
7// These tests are too simple.
8
9import (
10	"bytes"
11	"fmt"
12	"io"
13	"os"
14	"regexp"
15	"runtime"
16	"strings"
17	"sync"
18	"testing"
19	"time"
20)
21
22const (
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
31type 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
37var 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)
57func 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
80func TestDefault(t *testing.T) {
81	if got := Default(); got != std {
82		t.Errorf("Default [%p] should be std [%p]", got, std)
83	}
84}
85
86func 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
93func 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
103func 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
109func 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
124func 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
166func 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
190func 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
204func 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
215func 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
229func 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
240func 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.
253type discard struct{}
254
255func (discard) Write(p []byte) (int, error) {
256	return len(p), nil
257}
258
259func 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
274func 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