| // Go support for leveled logs, analogous to https://code.google.com/p/google-glog/ |
| // |
| // Copyright 2013 Google Inc. All Rights Reserved. |
| // |
| // Licensed under the Apache License, Version 2.0 (the "License"); |
| // you may not use this file except in compliance with the License. |
| // You may obtain a copy of the License at |
| // |
| // http://www.apache.org/licenses/LICENSE-2.0 |
| // |
| // Unless required by applicable law or agreed to in writing, software |
| // distributed under the License is distributed on an "AS IS" BASIS, |
| // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| // See the License for the specific language governing permissions and |
| // limitations under the License. |
| |
| package glog |
| |
| import ( |
| "bytes" |
| "fmt" |
| stdLog "log" |
| "path/filepath" |
| "runtime" |
| "strconv" |
| "strings" |
| "testing" |
| "time" |
| ) |
| |
| // Test that shortHostname works as advertised. |
| func TestShortHostname(t *testing.T) { |
| for hostname, expect := range map[string]string{ |
| "": "", |
| "host": "host", |
| "host.google.com": "host", |
| } { |
| if got := shortHostname(hostname); expect != got { |
| t.Errorf("shortHostname(%q): expected %q, got %q", hostname, expect, got) |
| } |
| } |
| } |
| |
| // flushBuffer wraps a bytes.Buffer to satisfy flushSyncWriter. |
| type flushBuffer struct { |
| bytes.Buffer |
| } |
| |
| func (f *flushBuffer) Flush() error { |
| return nil |
| } |
| |
| func (f *flushBuffer) Sync() error { |
| return nil |
| } |
| |
| // swap sets the log writers and returns the old array. |
| func (l *loggingT) swap(writers [numSeverity]flushSyncWriter) (old [numSeverity]flushSyncWriter) { |
| l.mu.Lock() |
| defer l.mu.Unlock() |
| old = l.file |
| for i, w := range writers { |
| logging.file[i] = w |
| } |
| return |
| } |
| |
| // newBuffers sets the log writers to all new byte buffers and returns the old array. |
| func (l *loggingT) newBuffers() [numSeverity]flushSyncWriter { |
| return l.swap([numSeverity]flushSyncWriter{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)}) |
| } |
| |
| // contents returns the specified log value as a string. |
| func contents(s severity) string { |
| return logging.file[s].(*flushBuffer).String() |
| } |
| |
| // contains reports whether the string is contained in the log. |
| func contains(s severity, str string, t *testing.T) bool { |
| return strings.Contains(contents(s), str) |
| } |
| |
| // setFlags configures the logging flags how the test expects them. |
| func setFlags() { |
| logging.toStderr = false |
| } |
| |
| // Test that Info works as advertised. |
| func TestInfo(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| Info("test") |
| if !contains(infoLog, "I", t) { |
| t.Errorf("Info has wrong character: %q", contents(infoLog)) |
| } |
| if !contains(infoLog, "test", t) { |
| t.Error("Info failed") |
| } |
| } |
| |
| func TestInfoDepth(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| |
| f := func() { InfoDepth(1, "depth-test1") } |
| |
| // The next three lines must stay together |
| _, _, wantLine, _ := runtime.Caller(0) |
| InfoDepth(0, "depth-test0") |
| f() |
| |
| msgs := strings.Split(strings.TrimSuffix(contents(infoLog), "\n"), "\n") |
| if len(msgs) != 2 { |
| t.Fatalf("Got %d lines, expected 2", len(msgs)) |
| } |
| |
| for i, m := range msgs { |
| if !strings.HasPrefix(m, "I") { |
| t.Errorf("InfoDepth[%d] has wrong character: %q", i, m) |
| } |
| w := fmt.Sprintf("depth-test%d", i) |
| if !strings.Contains(m, w) { |
| t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m) |
| } |
| |
| // pull out the line number (between : and ]) |
| msg := m[strings.LastIndex(m, ":")+1:] |
| x := strings.Index(msg, "]") |
| if x < 0 { |
| t.Errorf("InfoDepth[%d]: missing ']': %q", i, m) |
| continue |
| } |
| line, err := strconv.Atoi(msg[:x]) |
| if err != nil { |
| t.Errorf("InfoDepth[%d]: bad line number: %q", i, m) |
| continue |
| } |
| wantLine++ |
| if wantLine != line { |
| t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine) |
| } |
| } |
| } |
| |
| func init() { |
| CopyStandardLogTo("INFO") |
| } |
| |
| // Test that CopyStandardLogTo panics on bad input. |
| func TestCopyStandardLogToPanic(t *testing.T) { |
| defer func() { |
| if s, ok := recover().(string); !ok || !strings.Contains(s, "LOG") { |
| t.Errorf(`CopyStandardLogTo("LOG") should have panicked: %v`, s) |
| } |
| }() |
| CopyStandardLogTo("LOG") |
| } |
| |
| // Test that using the standard log package logs to INFO. |
| func TestStandardLog(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| stdLog.Print("test") |
| if !contains(infoLog, "I", t) { |
| t.Errorf("Info has wrong character: %q", contents(infoLog)) |
| } |
| if !contains(infoLog, "test", t) { |
| t.Error("Info failed") |
| } |
| } |
| |
| // Test that the header has the correct format. |
| func TestHeader(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| defer func(previous func() time.Time) { timeNow = previous }(timeNow) |
| timeNow = func() time.Time { |
| return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local) |
| } |
| pid = 1234 |
| Info("test") |
| var line int |
| format := "I0102 15:04:05.067890 1234 glog_test.go:%d] test\n" |
| n, err := fmt.Sscanf(contents(infoLog), format, &line) |
| if n != 1 || err != nil { |
| t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog)) |
| } |
| // Scanf treats multiple spaces as equivalent to a single space, |
| // so check for correct space-padding also. |
| want := fmt.Sprintf(format, line) |
| if contents(infoLog) != want { |
| t.Errorf("log format error: got:\n\t%q\nwant:\t%q", contents(infoLog), want) |
| } |
| } |
| |
| // Test that an Error log goes to Warning and Info. |
| // Even in the Info log, the source character will be E, so the data should |
| // all be identical. |
| func TestError(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| Error("test") |
| if !contains(errorLog, "E", t) { |
| t.Errorf("Error has wrong character: %q", contents(errorLog)) |
| } |
| if !contains(errorLog, "test", t) { |
| t.Error("Error failed") |
| } |
| str := contents(errorLog) |
| if !contains(warningLog, str, t) { |
| t.Error("Warning failed") |
| } |
| if !contains(infoLog, str, t) { |
| t.Error("Info failed") |
| } |
| } |
| |
| // Test that a Warning log goes to Info. |
| // Even in the Info log, the source character will be W, so the data should |
| // all be identical. |
| func TestWarning(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| Warning("test") |
| if !contains(warningLog, "W", t) { |
| t.Errorf("Warning has wrong character: %q", contents(warningLog)) |
| } |
| if !contains(warningLog, "test", t) { |
| t.Error("Warning failed") |
| } |
| str := contents(warningLog) |
| if !contains(infoLog, str, t) { |
| t.Error("Info failed") |
| } |
| } |
| |
| // Test that a V log goes to Info. |
| func TestV(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| logging.verbosity.Set("2") |
| defer logging.verbosity.Set("0") |
| V(2).Info("test") |
| if !contains(infoLog, "I", t) { |
| t.Errorf("Info has wrong character: %q", contents(infoLog)) |
| } |
| if !contains(infoLog, "test", t) { |
| t.Error("Info failed") |
| } |
| } |
| |
| // Test that a vmodule enables a log in this file. |
| func TestVmoduleOn(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| logging.vmodule.Set("glog_test=2") |
| defer logging.vmodule.Set("") |
| if !V(1) { |
| t.Error("V not enabled for 1") |
| } |
| if !V(2) { |
| t.Error("V not enabled for 2") |
| } |
| if V(3) { |
| t.Error("V enabled for 3") |
| } |
| V(2).Info("test") |
| if !contains(infoLog, "I", t) { |
| t.Errorf("Info has wrong character: %q", contents(infoLog)) |
| } |
| if !contains(infoLog, "test", t) { |
| t.Error("Info failed") |
| } |
| } |
| |
| // Test that a vmodule of another file does not enable a log in this file. |
| func TestVmoduleOff(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| logging.vmodule.Set("notthisfile=2") |
| defer logging.vmodule.Set("") |
| for i := 1; i <= 3; i++ { |
| if V(Level(i)) { |
| t.Errorf("V enabled for %d", i) |
| } |
| } |
| V(2).Info("test") |
| if contents(infoLog) != "" { |
| t.Error("V logged incorrectly") |
| } |
| } |
| |
| // vGlobs are patterns that match/don't match this file at V=2. |
| var vGlobs = map[string]bool{ |
| // Easy to test the numeric match here. |
| "glog_test=1": false, // If -vmodule sets V to 1, V(2) will fail. |
| "glog_test=2": true, |
| "glog_test=3": true, // If -vmodule sets V to 1, V(3) will succeed. |
| // These all use 2 and check the patterns. All are true. |
| "*=2": true, |
| "?l*=2": true, |
| "????_*=2": true, |
| "??[mno]?_*t=2": true, |
| // These all use 2 and check the patterns. All are false. |
| "*x=2": false, |
| "m*=2": false, |
| "??_*=2": false, |
| "?[abc]?_*t=2": false, |
| } |
| |
| // Test that vmodule globbing works as advertised. |
| func testVmoduleGlob(pat string, match bool, t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| defer logging.vmodule.Set("") |
| logging.vmodule.Set(pat) |
| if V(2) != Verbose(match) { |
| t.Errorf("incorrect match for %q: got %t expected %t", pat, V(2), match) |
| } |
| } |
| |
| // Test that a vmodule globbing works as advertised. |
| func TestVmoduleGlob(t *testing.T) { |
| for glob, match := range vGlobs { |
| testVmoduleGlob(glob, match, t) |
| } |
| } |
| |
| func TestRollover(t *testing.T) { |
| setFlags() |
| var err error |
| defer func(previous func(error)) { logExitFunc = previous }(logExitFunc) |
| logExitFunc = func(e error) { |
| err = e |
| } |
| defer func(previous uint64) { MaxSize = previous }(MaxSize) |
| MaxSize = 512 |
| |
| Info("x") // Be sure we have a file. |
| info, ok := logging.file[infoLog].(*syncBuffer) |
| if !ok { |
| t.Fatal("info wasn't created") |
| } |
| if err != nil { |
| t.Fatalf("info has initial error: %v", err) |
| } |
| fname0 := info.file.Name() |
| Info(strings.Repeat("x", int(MaxSize))) // force a rollover |
| if err != nil { |
| t.Fatalf("info has error after big write: %v", err) |
| } |
| |
| // Make sure the next log file gets a file name with a different |
| // time stamp. |
| // |
| // TODO: determine whether we need to support subsecond log |
| // rotation. C++ does not appear to handle this case (nor does it |
| // handle Daylight Savings Time properly). |
| time.Sleep(1 * time.Second) |
| |
| Info("x") // create a new file |
| if err != nil { |
| t.Fatalf("error after rotation: %v", err) |
| } |
| fname1 := info.file.Name() |
| if fname0 == fname1 { |
| t.Errorf("info.f.Name did not change: %v", fname0) |
| } |
| if info.nbytes >= MaxSize { |
| t.Errorf("file size was not reset: %d", info.nbytes) |
| } |
| } |
| |
| func TestLogBacktraceAt(t *testing.T) { |
| setFlags() |
| defer logging.swap(logging.newBuffers()) |
| // The peculiar style of this code simplifies line counting and maintenance of the |
| // tracing block below. |
| var infoLine string |
| setTraceLocation := func(file string, line int, ok bool, delta int) { |
| if !ok { |
| t.Fatal("could not get file:line") |
| } |
| _, file = filepath.Split(file) |
| infoLine = fmt.Sprintf("%s:%d", file, line+delta) |
| err := logging.traceLocation.Set(infoLine) |
| if err != nil { |
| t.Fatal("error setting log_backtrace_at: ", err) |
| } |
| } |
| { |
| // Start of tracing block. These lines know about each other's relative position. |
| _, file, line, ok := runtime.Caller(0) |
| setTraceLocation(file, line, ok, +2) // Two lines between Caller and Info calls. |
| Info("we want a stack trace here") |
| } |
| numAppearances := strings.Count(contents(infoLog), infoLine) |
| if numAppearances < 2 { |
| // Need 2 appearances, one in the log header and one in the trace: |
| // log_test.go:281: I0511 16:36:06.952398 02238 log_test.go:280] we want a stack trace here |
| // ... |
| // github.com/glog/glog_test.go:280 (0x41ba91) |
| // ... |
| // We could be more precise but that would require knowing the details |
| // of the traceback format, which may not be dependable. |
| t.Fatal("got no trace back; log is ", contents(infoLog)) |
| } |
| } |
| |
| func BenchmarkHeader(b *testing.B) { |
| for i := 0; i < b.N; i++ { |
| buf, _, _ := logging.header(infoLog, 0) |
| logging.putBuffer(buf) |
| } |
| } |