From 56e74239d6b34df8f30ef046f0b0ff4ff0866a71 Mon Sep 17 00:00:00 2001 From: =Corey Hulen Date: Sun, 14 Jun 2015 23:53:32 -0800 Subject: first commit --- .../src/code.google.com/p/log4go/log4go_test.go | 534 +++++++++++++++++++++ 1 file changed, 534 insertions(+) create mode 100644 Godeps/_workspace/src/code.google.com/p/log4go/log4go_test.go (limited to 'Godeps/_workspace/src/code.google.com/p/log4go/log4go_test.go') diff --git a/Godeps/_workspace/src/code.google.com/p/log4go/log4go_test.go b/Godeps/_workspace/src/code.google.com/p/log4go/log4go_test.go new file mode 100644 index 000000000..90c629977 --- /dev/null +++ b/Godeps/_workspace/src/code.google.com/p/log4go/log4go_test.go @@ -0,0 +1,534 @@ +// Copyright (C) 2010, Kyle Lemons . All rights reserved. + +package log4go + +import ( + "crypto/md5" + "encoding/hex" + "fmt" + "io" + "io/ioutil" + "os" + "runtime" + "testing" + "time" +) + +const testLogFile = "_logtest.log" + +var now time.Time = time.Unix(0, 1234567890123456789).In(time.UTC) + +func newLogRecord(lvl level, src string, msg string) *LogRecord { + return &LogRecord{ + Level: lvl, + Source: src, + Created: now, + Message: msg, + } +} + +func TestELog(t *testing.T) { + fmt.Printf("Testing %s\n", L4G_VERSION) + lr := newLogRecord(CRITICAL, "source", "message") + if lr.Level != CRITICAL { + t.Errorf("Incorrect level: %d should be %d", lr.Level, CRITICAL) + } + if lr.Source != "source" { + t.Errorf("Incorrect source: %s should be %s", lr.Source, "source") + } + if lr.Message != "message" { + t.Errorf("Incorrect message: %s should be %s", lr.Source, "message") + } +} + +var formatTests = []struct { + Test string + Record *LogRecord + Formats map[string]string +}{ + { + Test: "Standard formats", + Record: &LogRecord{ + Level: ERROR, + Source: "source", + Message: "message", + Created: now, + }, + Formats: map[string]string{ + // TODO(kevlar): How can I do this so it'll work outside of PST? + FORMAT_DEFAULT: "[2009/02/13 23:31:30 UTC] [EROR] (source) message\n", + FORMAT_SHORT: "[23:31 02/13/09] [EROR] message\n", + FORMAT_ABBREV: "[EROR] message\n", + }, + }, +} + +func TestFormatLogRecord(t *testing.T) { + for _, test := range formatTests { + name := test.Test + for fmt, want := range test.Formats { + if got := FormatLogRecord(fmt, test.Record); got != want { + t.Errorf("%s - %s:", name, fmt) + t.Errorf(" got %q", got) + t.Errorf(" want %q", want) + } + } + } +} + +var logRecordWriteTests = []struct { + Test string + Record *LogRecord + Console string +}{ + { + Test: "Normal message", + Record: &LogRecord{ + Level: CRITICAL, + Source: "source", + Message: "message", + Created: now, + }, + Console: "[02/13/09 23:31:30] [CRIT] message\n", + }, +} + +func TestConsoleLogWriter(t *testing.T) { + console := make(ConsoleLogWriter) + + r, w := io.Pipe() + go console.run(w) + defer console.Close() + + buf := make([]byte, 1024) + + for _, test := range logRecordWriteTests { + name := test.Test + + console.LogWrite(test.Record) + n, _ := r.Read(buf) + + if got, want := string(buf[:n]), test.Console; got != want { + t.Errorf("%s: got %q", name, got) + t.Errorf("%s: want %q", name, want) + } + } +} + +func TestFileLogWriter(t *testing.T) { + defer func(buflen int) { + LogBufferLength = buflen + }(LogBufferLength) + LogBufferLength = 0 + + w := NewFileLogWriter(testLogFile, false) + if w == nil { + t.Fatalf("Invalid return: w should not be nil") + } + defer os.Remove(testLogFile) + + w.LogWrite(newLogRecord(CRITICAL, "source", "message")) + w.Close() + runtime.Gosched() + + if contents, err := ioutil.ReadFile(testLogFile); err != nil { + t.Errorf("read(%q): %s", testLogFile, err) + } else if len(contents) != 50 { + t.Errorf("malformed filelog: %q (%d bytes)", string(contents), len(contents)) + } +} + +func TestXMLLogWriter(t *testing.T) { + defer func(buflen int) { + LogBufferLength = buflen + }(LogBufferLength) + LogBufferLength = 0 + + w := NewXMLLogWriter(testLogFile, false) + if w == nil { + t.Fatalf("Invalid return: w should not be nil") + } + defer os.Remove(testLogFile) + + w.LogWrite(newLogRecord(CRITICAL, "source", "message")) + w.Close() + runtime.Gosched() + + if contents, err := ioutil.ReadFile(testLogFile); err != nil { + t.Errorf("read(%q): %s", testLogFile, err) + } else if len(contents) != 185 { + t.Errorf("malformed xmllog: %q (%d bytes)", string(contents), len(contents)) + } +} + +func TestLogger(t *testing.T) { + sl := NewDefaultLogger(WARNING) + if sl == nil { + t.Fatalf("NewDefaultLogger should never return nil") + } + if lw, exist := sl["stdout"]; lw == nil || exist != true { + t.Fatalf("NewDefaultLogger produced invalid logger (DNE or nil)") + } + if sl["stdout"].Level != WARNING { + t.Fatalf("NewDefaultLogger produced invalid logger (incorrect level)") + } + if len(sl) != 1 { + t.Fatalf("NewDefaultLogger produced invalid logger (incorrect map count)") + } + + //func (l *Logger) AddFilter(name string, level int, writer LogWriter) {} + l := make(Logger) + l.AddFilter("stdout", DEBUG, NewConsoleLogWriter()) + if lw, exist := l["stdout"]; lw == nil || exist != true { + t.Fatalf("AddFilter produced invalid logger (DNE or nil)") + } + if l["stdout"].Level != DEBUG { + t.Fatalf("AddFilter produced invalid logger (incorrect level)") + } + if len(l) != 1 { + t.Fatalf("AddFilter produced invalid logger (incorrect map count)") + } + + //func (l *Logger) Warn(format string, args ...interface{}) error {} + if err := l.Warn("%s %d %#v", "Warning:", 1, []int{}); err.Error() != "Warning: 1 []int{}" { + t.Errorf("Warn returned invalid error: %s", err) + } + + //func (l *Logger) Error(format string, args ...interface{}) error {} + if err := l.Error("%s %d %#v", "Error:", 10, []string{}); err.Error() != "Error: 10 []string{}" { + t.Errorf("Error returned invalid error: %s", err) + } + + //func (l *Logger) Critical(format string, args ...interface{}) error {} + if err := l.Critical("%s %d %#v", "Critical:", 100, []int64{}); err.Error() != "Critical: 100 []int64{}" { + t.Errorf("Critical returned invalid error: %s", err) + } + + // Already tested or basically untestable + //func (l *Logger) Log(level int, source, message string) {} + //func (l *Logger) Logf(level int, format string, args ...interface{}) {} + //func (l *Logger) intLogf(level int, format string, args ...interface{}) string {} + //func (l *Logger) Finest(format string, args ...interface{}) {} + //func (l *Logger) Fine(format string, args ...interface{}) {} + //func (l *Logger) Debug(format string, args ...interface{}) {} + //func (l *Logger) Trace(format string, args ...interface{}) {} + //func (l *Logger) Info(format string, args ...interface{}) {} +} + +func TestLogOutput(t *testing.T) { + const ( + expected = "fdf3e51e444da56b4cb400f30bc47424" + ) + + // Unbuffered output + defer func(buflen int) { + LogBufferLength = buflen + }(LogBufferLength) + LogBufferLength = 0 + + l := make(Logger) + + // Delete and open the output log without a timestamp (for a constant md5sum) + l.AddFilter("file", FINEST, NewFileLogWriter(testLogFile, false).SetFormat("[%L] %M")) + defer os.Remove(testLogFile) + + // Send some log messages + l.Log(CRITICAL, "testsrc1", fmt.Sprintf("This message is level %d", int(CRITICAL))) + l.Logf(ERROR, "This message is level %v", ERROR) + l.Logf(WARNING, "This message is level %s", WARNING) + l.Logc(INFO, func() string { return "This message is level INFO" }) + l.Trace("This message is level %d", int(TRACE)) + l.Debug("This message is level %s", DEBUG) + l.Fine(func() string { return fmt.Sprintf("This message is level %v", FINE) }) + l.Finest("This message is level %v", FINEST) + l.Finest(FINEST, "is also this message's level") + + l.Close() + + contents, err := ioutil.ReadFile(testLogFile) + if err != nil { + t.Fatalf("Could not read output log: %s", err) + } + + sum := md5.New() + sum.Write(contents) + if sumstr := hex.EncodeToString(sum.Sum(nil)); sumstr != expected { + t.Errorf("--- Log Contents:\n%s---", string(contents)) + t.Fatalf("Checksum does not match: %s (expecting %s)", sumstr, expected) + } +} + +func TestCountMallocs(t *testing.T) { + const N = 1 + var m runtime.MemStats + getMallocs := func() uint64 { + runtime.ReadMemStats(&m) + return m.Mallocs + } + + // Console logger + sl := NewDefaultLogger(INFO) + mallocs := 0 - getMallocs() + for i := 0; i < N; i++ { + sl.Log(WARNING, "here", "This is a WARNING message") + } + mallocs += getMallocs() + fmt.Printf("mallocs per sl.Log((WARNING, \"here\", \"This is a log message\"): %d\n", mallocs/N) + + // Console logger formatted + mallocs = 0 - getMallocs() + for i := 0; i < N; i++ { + sl.Logf(WARNING, "%s is a log message with level %d", "This", WARNING) + } + mallocs += getMallocs() + fmt.Printf("mallocs per sl.Logf(WARNING, \"%%s is a log message with level %%d\", \"This\", WARNING): %d\n", mallocs/N) + + // Console logger (not logged) + sl = NewDefaultLogger(INFO) + mallocs = 0 - getMallocs() + for i := 0; i < N; i++ { + sl.Log(DEBUG, "here", "This is a DEBUG log message") + } + mallocs += getMallocs() + fmt.Printf("mallocs per unlogged sl.Log((WARNING, \"here\", \"This is a log message\"): %d\n", mallocs/N) + + // Console logger formatted (not logged) + mallocs = 0 - getMallocs() + for i := 0; i < N; i++ { + sl.Logf(DEBUG, "%s is a log message with level %d", "This", DEBUG) + } + mallocs += getMallocs() + fmt.Printf("mallocs per unlogged sl.Logf(WARNING, \"%%s is a log message with level %%d\", \"This\", WARNING): %d\n", mallocs/N) +} + +func TestXMLConfig(t *testing.T) { + const ( + configfile = "example.xml" + ) + + fd, err := os.Create(configfile) + if err != nil { + t.Fatalf("Could not open %s for writing: %s", configfile, err) + } + + fmt.Fprintln(fd, "") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " stdout") + fmt.Fprintln(fd, " console") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " DEBUG") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " file") + fmt.Fprintln(fd, " file") + fmt.Fprintln(fd, " FINEST") + fmt.Fprintln(fd, " test.log") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " [%D %T] [%L] (%S) %M") + fmt.Fprintln(fd, " false ") + fmt.Fprintln(fd, " 0M ") + fmt.Fprintln(fd, " 0K ") + fmt.Fprintln(fd, " true ") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " xmllog") + fmt.Fprintln(fd, " xml") + fmt.Fprintln(fd, " TRACE") + fmt.Fprintln(fd, " trace.xml") + fmt.Fprintln(fd, " true ") + fmt.Fprintln(fd, " 100M ") + fmt.Fprintln(fd, " 6K ") + fmt.Fprintln(fd, " false ") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, " donotopen") + fmt.Fprintln(fd, " socket") + fmt.Fprintln(fd, " FINEST") + fmt.Fprintln(fd, " 192.168.1.255:12124 ") + fmt.Fprintln(fd, " udp ") + fmt.Fprintln(fd, " ") + fmt.Fprintln(fd, "") + fd.Close() + + log := make(Logger) + log.LoadConfiguration(configfile) + defer os.Remove("trace.xml") + defer os.Remove("test.log") + defer log.Close() + + // Make sure we got all loggers + if len(log) != 3 { + t.Fatalf("XMLConfig: Expected 3 filters, found %d", len(log)) + } + + // Make sure they're the right keys + if _, ok := log["stdout"]; !ok { + t.Errorf("XMLConfig: Expected stdout logger") + } + if _, ok := log["file"]; !ok { + t.Fatalf("XMLConfig: Expected file logger") + } + if _, ok := log["xmllog"]; !ok { + t.Fatalf("XMLConfig: Expected xmllog logger") + } + + // Make sure they're the right type + if _, ok := log["stdout"].LogWriter.(ConsoleLogWriter); !ok { + t.Fatalf("XMLConfig: Expected stdout to be ConsoleLogWriter, found %T", log["stdout"].LogWriter) + } + if _, ok := log["file"].LogWriter.(*FileLogWriter); !ok { + t.Fatalf("XMLConfig: Expected file to be *FileLogWriter, found %T", log["file"].LogWriter) + } + if _, ok := log["xmllog"].LogWriter.(*FileLogWriter); !ok { + t.Fatalf("XMLConfig: Expected xmllog to be *FileLogWriter, found %T", log["xmllog"].LogWriter) + } + + // Make sure levels are set + if lvl := log["stdout"].Level; lvl != DEBUG { + t.Errorf("XMLConfig: Expected stdout to be set to level %d, found %d", DEBUG, lvl) + } + if lvl := log["file"].Level; lvl != FINEST { + t.Errorf("XMLConfig: Expected file to be set to level %d, found %d", FINEST, lvl) + } + if lvl := log["xmllog"].Level; lvl != TRACE { + t.Errorf("XMLConfig: Expected xmllog to be set to level %d, found %d", TRACE, lvl) + } + + // Make sure the w is open and points to the right file + if fname := log["file"].LogWriter.(*FileLogWriter).file.Name(); fname != "test.log" { + t.Errorf("XMLConfig: Expected file to have opened %s, found %s", "test.log", fname) + } + + // Make sure the XLW is open and points to the right file + if fname := log["xmllog"].LogWriter.(*FileLogWriter).file.Name(); fname != "trace.xml" { + t.Errorf("XMLConfig: Expected xmllog to have opened %s, found %s", "trace.xml", fname) + } + + // Move XML log file + os.Rename(configfile, "examples/"+configfile) // Keep this so that an example with the documentation is available +} + +func BenchmarkFormatLogRecord(b *testing.B) { + const updateEvery = 1 + rec := &LogRecord{ + Level: CRITICAL, + Created: now, + Source: "source", + Message: "message", + } + for i := 0; i < b.N; i++ { + rec.Created = rec.Created.Add(1 * time.Second / updateEvery) + if i%2 == 0 { + FormatLogRecord(FORMAT_DEFAULT, rec) + } else { + FormatLogRecord(FORMAT_SHORT, rec) + } + } +} + +func BenchmarkConsoleLog(b *testing.B) { + /* This doesn't seem to work on OS X + sink, err := os.Open(os.DevNull) + if err != nil { + panic(err) + } + if err := syscall.Dup2(int(sink.Fd()), syscall.Stdout); err != nil { + panic(err) + } + */ + + stdout = ioutil.Discard + sl := NewDefaultLogger(INFO) + for i := 0; i < b.N; i++ { + sl.Log(WARNING, "here", "This is a log message") + } +} + +func BenchmarkConsoleNotLogged(b *testing.B) { + sl := NewDefaultLogger(INFO) + for i := 0; i < b.N; i++ { + sl.Log(DEBUG, "here", "This is a log message") + } +} + +func BenchmarkConsoleUtilLog(b *testing.B) { + sl := NewDefaultLogger(INFO) + for i := 0; i < b.N; i++ { + sl.Info("%s is a log message", "This") + } +} + +func BenchmarkConsoleUtilNotLog(b *testing.B) { + sl := NewDefaultLogger(INFO) + for i := 0; i < b.N; i++ { + sl.Debug("%s is a log message", "This") + } +} + +func BenchmarkFileLog(b *testing.B) { + sl := make(Logger) + b.StopTimer() + sl.AddFilter("file", INFO, NewFileLogWriter("benchlog.log", false)) + b.StartTimer() + for i := 0; i < b.N; i++ { + sl.Log(WARNING, "here", "This is a log message") + } + b.StopTimer() + os.Remove("benchlog.log") +} + +func BenchmarkFileNotLogged(b *testing.B) { + sl := make(Logger) + b.StopTimer() + sl.AddFilter("file", INFO, NewFileLogWriter("benchlog.log", false)) + b.StartTimer() + for i := 0; i < b.N; i++ { + sl.Log(DEBUG, "here", "This is a log message") + } + b.StopTimer() + os.Remove("benchlog.log") +} + +func BenchmarkFileUtilLog(b *testing.B) { + sl := make(Logger) + b.StopTimer() + sl.AddFilter("file", INFO, NewFileLogWriter("benchlog.log", false)) + b.StartTimer() + for i := 0; i < b.N; i++ { + sl.Info("%s is a log message", "This") + } + b.StopTimer() + os.Remove("benchlog.log") +} + +func BenchmarkFileUtilNotLog(b *testing.B) { + sl := make(Logger) + b.StopTimer() + sl.AddFilter("file", INFO, NewFileLogWriter("benchlog.log", false)) + b.StartTimer() + for i := 0; i < b.N; i++ { + sl.Debug("%s is a log message", "This") + } + b.StopTimer() + os.Remove("benchlog.log") +} + +// Benchmark results (darwin amd64 6g) +//elog.BenchmarkConsoleLog 100000 22819 ns/op +//elog.BenchmarkConsoleNotLogged 2000000 879 ns/op +//elog.BenchmarkConsoleUtilLog 50000 34380 ns/op +//elog.BenchmarkConsoleUtilNotLog 1000000 1339 ns/op +//elog.BenchmarkFileLog 100000 26497 ns/op +//elog.BenchmarkFileNotLogged 2000000 821 ns/op +//elog.BenchmarkFileUtilLog 50000 33945 ns/op +//elog.BenchmarkFileUtilNotLog 1000000 1258 ns/op -- cgit v1.2.3-1-g7c22