1// Go support for leveled logs, analogous to https://code.google.com/p/google-glog/ 2// 3// Copyright 2013 Google Inc. All Rights Reserved. 4// 5// Licensed under the Apache License, Version 2.0 (the "License"); 6// you may not use this file except in compliance with the License. 7// You may obtain a copy of the License at 8// 9// http://www.apache.org/licenses/LICENSE-2.0 10// 11// Unless required by applicable law or agreed to in writing, software 12// distributed under the License is distributed on an "AS IS" BASIS, 13// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14// See the License for the specific language governing permissions and 15// limitations under the License. 16 17package glog 18 19import ( 20 "bytes" 21 "fmt" 22 stdLog "log" 23 "path/filepath" 24 "runtime" 25 "strconv" 26 "strings" 27 "testing" 28 "time" 29) 30 31// Test that shortHostname works as advertised. 32func TestShortHostname(t *testing.T) { 33 for hostname, expect := range map[string]string{ 34 "": "", 35 "host": "host", 36 "host.google.com": "host", 37 } { 38 if got := shortHostname(hostname); expect != got { 39 t.Errorf("shortHostname(%q): expected %q, got %q", hostname, expect, got) 40 } 41 } 42} 43 44// flushBuffer wraps a bytes.Buffer to satisfy flushSyncWriter. 45type flushBuffer struct { 46 bytes.Buffer 47} 48 49func (f *flushBuffer) Flush() error { 50 return nil 51} 52 53func (f *flushBuffer) Sync() error { 54 return nil 55} 56 57// swap sets the log writers and returns the old array. 58func (l *loggingT) swap(writers [numSeverity]flushSyncWriter) (old [numSeverity]flushSyncWriter) { 59 l.mu.Lock() 60 defer l.mu.Unlock() 61 old = l.file 62 for i, w := range writers { 63 logging.file[i] = w 64 } 65 return 66} 67 68// newBuffers sets the log writers to all new byte buffers and returns the old array. 69func (l *loggingT) newBuffers() [numSeverity]flushSyncWriter { 70 return l.swap([numSeverity]flushSyncWriter{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)}) 71} 72 73// contents returns the specified log value as a string. 74func contents(s severity) string { 75 return logging.file[s].(*flushBuffer).String() 76} 77 78// contains reports whether the string is contained in the log. 79func contains(s severity, str string, t *testing.T) bool { 80 return strings.Contains(contents(s), str) 81} 82 83// setFlags configures the logging flags how the test expects them. 84func setFlags() { 85 logging.toStderr = false 86} 87 88// Test that Info works as advertised. 89func TestInfo(t *testing.T) { 90 setFlags() 91 defer logging.swap(logging.newBuffers()) 92 Info("test") 93 if !contains(infoLog, "I", t) { 94 t.Errorf("Info has wrong character: %q", contents(infoLog)) 95 } 96 if !contains(infoLog, "test", t) { 97 t.Error("Info failed") 98 } 99} 100 101func TestInfoDepth(t *testing.T) { 102 setFlags() 103 defer logging.swap(logging.newBuffers()) 104 105 f := func() { InfoDepth(1, "depth-test1") } 106 107 // The next three lines must stay together 108 _, _, wantLine, _ := runtime.Caller(0) 109 InfoDepth(0, "depth-test0") 110 f() 111 112 msgs := strings.Split(strings.TrimSuffix(contents(infoLog), "\n"), "\n") 113 if len(msgs) != 2 { 114 t.Fatalf("Got %d lines, expected 2", len(msgs)) 115 } 116 117 for i, m := range msgs { 118 if !strings.HasPrefix(m, "I") { 119 t.Errorf("InfoDepth[%d] has wrong character: %q", i, m) 120 } 121 w := fmt.Sprintf("depth-test%d", i) 122 if !strings.Contains(m, w) { 123 t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m) 124 } 125 126 // pull out the line number (between : and ]) 127 msg := m[strings.LastIndex(m, ":")+1:] 128 x := strings.Index(msg, "]") 129 if x < 0 { 130 t.Errorf("InfoDepth[%d]: missing ']': %q", i, m) 131 continue 132 } 133 line, err := strconv.Atoi(msg[:x]) 134 if err != nil { 135 t.Errorf("InfoDepth[%d]: bad line number: %q", i, m) 136 continue 137 } 138 wantLine++ 139 if wantLine != line { 140 t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine) 141 } 142 } 143} 144 145func init() { 146 CopyStandardLogTo("INFO") 147} 148 149// Test that CopyStandardLogTo panics on bad input. 150func TestCopyStandardLogToPanic(t *testing.T) { 151 defer func() { 152 if s, ok := recover().(string); !ok || !strings.Contains(s, "LOG") { 153 t.Errorf(`CopyStandardLogTo("LOG") should have panicked: %v`, s) 154 } 155 }() 156 CopyStandardLogTo("LOG") 157} 158 159// Test that using the standard log package logs to INFO. 160func TestStandardLog(t *testing.T) { 161 setFlags() 162 defer logging.swap(logging.newBuffers()) 163 stdLog.Print("test") 164 if !contains(infoLog, "I", t) { 165 t.Errorf("Info has wrong character: %q", contents(infoLog)) 166 } 167 if !contains(infoLog, "test", t) { 168 t.Error("Info failed") 169 } 170} 171 172// Test that the header has the correct format. 173func TestHeader(t *testing.T) { 174 setFlags() 175 defer logging.swap(logging.newBuffers()) 176 defer func(previous func() time.Time) { timeNow = previous }(timeNow) 177 timeNow = func() time.Time { 178 return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local) 179 } 180 pid = 1234 181 Info("test") 182 var line int 183 format := "I0102 15:04:05.067890 1234 glog_test.go:%d] test\n" 184 n, err := fmt.Sscanf(contents(infoLog), format, &line) 185 if n != 1 || err != nil { 186 t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog)) 187 } 188 // Scanf treats multiple spaces as equivalent to a single space, 189 // so check for correct space-padding also. 190 want := fmt.Sprintf(format, line) 191 if contents(infoLog) != want { 192 t.Errorf("log format error: got:\n\t%q\nwant:\t%q", contents(infoLog), want) 193 } 194} 195 196// Test that an Error log goes to Warning and Info. 197// Even in the Info log, the source character will be E, so the data should 198// all be identical. 199func TestError(t *testing.T) { 200 setFlags() 201 defer logging.swap(logging.newBuffers()) 202 Error("test") 203 if !contains(errorLog, "E", t) { 204 t.Errorf("Error has wrong character: %q", contents(errorLog)) 205 } 206 if !contains(errorLog, "test", t) { 207 t.Error("Error failed") 208 } 209 str := contents(errorLog) 210 if !contains(warningLog, str, t) { 211 t.Error("Warning failed") 212 } 213 if !contains(infoLog, str, t) { 214 t.Error("Info failed") 215 } 216} 217 218// Test that a Warning log goes to Info. 219// Even in the Info log, the source character will be W, so the data should 220// all be identical. 221func TestWarning(t *testing.T) { 222 setFlags() 223 defer logging.swap(logging.newBuffers()) 224 Warning("test") 225 if !contains(warningLog, "W", t) { 226 t.Errorf("Warning has wrong character: %q", contents(warningLog)) 227 } 228 if !contains(warningLog, "test", t) { 229 t.Error("Warning failed") 230 } 231 str := contents(warningLog) 232 if !contains(infoLog, str, t) { 233 t.Error("Info failed") 234 } 235} 236 237// Test that a V log goes to Info. 238func TestV(t *testing.T) { 239 setFlags() 240 defer logging.swap(logging.newBuffers()) 241 logging.verbosity.Set("2") 242 defer logging.verbosity.Set("0") 243 V(2).Info("test") 244 if !contains(infoLog, "I", t) { 245 t.Errorf("Info has wrong character: %q", contents(infoLog)) 246 } 247 if !contains(infoLog, "test", t) { 248 t.Error("Info failed") 249 } 250} 251 252// Test that a vmodule enables a log in this file. 253func TestVmoduleOn(t *testing.T) { 254 setFlags() 255 defer logging.swap(logging.newBuffers()) 256 logging.vmodule.Set("glog_test=2") 257 defer logging.vmodule.Set("") 258 if !V(1) { 259 t.Error("V not enabled for 1") 260 } 261 if !V(2) { 262 t.Error("V not enabled for 2") 263 } 264 if V(3) { 265 t.Error("V enabled for 3") 266 } 267 V(2).Info("test") 268 if !contains(infoLog, "I", t) { 269 t.Errorf("Info has wrong character: %q", contents(infoLog)) 270 } 271 if !contains(infoLog, "test", t) { 272 t.Error("Info failed") 273 } 274} 275 276// Test that a vmodule of another file does not enable a log in this file. 277func TestVmoduleOff(t *testing.T) { 278 setFlags() 279 defer logging.swap(logging.newBuffers()) 280 logging.vmodule.Set("notthisfile=2") 281 defer logging.vmodule.Set("") 282 for i := 1; i <= 3; i++ { 283 if V(Level(i)) { 284 t.Errorf("V enabled for %d", i) 285 } 286 } 287 V(2).Info("test") 288 if contents(infoLog) != "" { 289 t.Error("V logged incorrectly") 290 } 291} 292 293// vGlobs are patterns that match/don't match this file at V=2. 294var vGlobs = map[string]bool{ 295 // Easy to test the numeric match here. 296 "glog_test=1": false, // If -vmodule sets V to 1, V(2) will fail. 297 "glog_test=2": true, 298 "glog_test=3": true, // If -vmodule sets V to 1, V(3) will succeed. 299 // These all use 2 and check the patterns. All are true. 300 "*=2": true, 301 "?l*=2": true, 302 "????_*=2": true, 303 "??[mno]?_*t=2": true, 304 // These all use 2 and check the patterns. All are false. 305 "*x=2": false, 306 "m*=2": false, 307 "??_*=2": false, 308 "?[abc]?_*t=2": false, 309} 310 311// Test that vmodule globbing works as advertised. 312func testVmoduleGlob(pat string, match bool, t *testing.T) { 313 setFlags() 314 defer logging.swap(logging.newBuffers()) 315 defer logging.vmodule.Set("") 316 logging.vmodule.Set(pat) 317 if V(2) != Verbose(match) { 318 t.Errorf("incorrect match for %q: got %t expected %t", pat, V(2), match) 319 } 320} 321 322// Test that a vmodule globbing works as advertised. 323func TestVmoduleGlob(t *testing.T) { 324 for glob, match := range vGlobs { 325 testVmoduleGlob(glob, match, t) 326 } 327} 328 329func TestRollover(t *testing.T) { 330 setFlags() 331 var err error 332 defer func(previous func(error)) { logExitFunc = previous }(logExitFunc) 333 logExitFunc = func(e error) { 334 err = e 335 } 336 defer func(previous uint64) { MaxSize = previous }(MaxSize) 337 MaxSize = 512 338 339 Info("x") // Be sure we have a file. 340 info, ok := logging.file[infoLog].(*syncBuffer) 341 if !ok { 342 t.Fatal("info wasn't created") 343 } 344 if err != nil { 345 t.Fatalf("info has initial error: %v", err) 346 } 347 fname0 := info.file.Name() 348 Info(strings.Repeat("x", int(MaxSize))) // force a rollover 349 if err != nil { 350 t.Fatalf("info has error after big write: %v", err) 351 } 352 353 // Make sure the next log file gets a file name with a different 354 // time stamp. 355 // 356 // TODO: determine whether we need to support subsecond log 357 // rotation. C++ does not appear to handle this case (nor does it 358 // handle Daylight Savings Time properly). 359 time.Sleep(1 * time.Second) 360 361 Info("x") // create a new file 362 if err != nil { 363 t.Fatalf("error after rotation: %v", err) 364 } 365 fname1 := info.file.Name() 366 if fname0 == fname1 { 367 t.Errorf("info.f.Name did not change: %v", fname0) 368 } 369 if info.nbytes >= MaxSize { 370 t.Errorf("file size was not reset: %d", info.nbytes) 371 } 372} 373 374func TestLogBacktraceAt(t *testing.T) { 375 setFlags() 376 defer logging.swap(logging.newBuffers()) 377 // The peculiar style of this code simplifies line counting and maintenance of the 378 // tracing block below. 379 var infoLine string 380 setTraceLocation := func(file string, line int, ok bool, delta int) { 381 if !ok { 382 t.Fatal("could not get file:line") 383 } 384 _, file = filepath.Split(file) 385 infoLine = fmt.Sprintf("%s:%d", file, line+delta) 386 err := logging.traceLocation.Set(infoLine) 387 if err != nil { 388 t.Fatal("error setting log_backtrace_at: ", err) 389 } 390 } 391 { 392 // Start of tracing block. These lines know about each other's relative position. 393 _, file, line, ok := runtime.Caller(0) 394 setTraceLocation(file, line, ok, +2) // Two lines between Caller and Info calls. 395 Info("we want a stack trace here") 396 } 397 numAppearances := strings.Count(contents(infoLog), infoLine) 398 if numAppearances < 2 { 399 // Need 2 appearances, one in the log header and one in the trace: 400 // log_test.go:281: I0511 16:36:06.952398 02238 log_test.go:280] we want a stack trace here 401 // ... 402 // github.com/glog/glog_test.go:280 (0x41ba91) 403 // ... 404 // We could be more precise but that would require knowing the details 405 // of the traceback format, which may not be dependable. 406 t.Fatal("got no trace back; log is ", contents(infoLog)) 407 } 408} 409 410func BenchmarkHeader(b *testing.B) { 411 for i := 0; i < b.N; i++ { 412 buf, _, _ := logging.header(infoLog, 0) 413 logging.putBuffer(buf) 414 } 415} 416