src/log/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 }