From 588a3168ac21008eb4b37c2ee5ae3dd9d779fc1b Mon Sep 17 00:00:00 2001 From: Alex Bramley Date: Sat, 5 Nov 2011 05:56:45 +0000 Subject: [PATCH] More logging yak-shaving: * Change Mock API to match mockNetConn Expect* calls. * Make logging.NewMock take and store *testing.T. * Add a level-agnostic Expect(). * Make writerMap an externally accessible type. * Adjust tests to take this shaving into account. --- logging/log_test.go | 32 ++++++------ logging/mock.go | 119 +++++++++++++++++++++++++++++--------------- 2 files changed, 96 insertions(+), 55 deletions(-) diff --git a/logging/log_test.go b/logging/log_test.go index bc44995..c02e3ad 100644 --- a/logging/log_test.go +++ b/logging/log_test.go @@ -7,54 +7,54 @@ import ( // Note: the below is deliberately PLACED AT THE TOP OF THIS FILE because // it is fragile. It ensures the right file:line is logged. Sorry! func TestLogCorrectLineNumbers(t *testing.T) { - l, m := NewMock() + l, m := NewMock(t) l.Log(Error, "Error!") - if s := string(m[Error].written); s[20:] != "log_test.go:11: ERROR Error!\n" { + // This breaks the mock encapsulation a little, but meh. + if s := string(m.m[Error].written); s[20:] != "log_test.go:11: ERROR Error!\n" { t.Errorf("Error incorrectly logged (check line numbers!)") } } func TestStandardLogging(t *testing.T) { - l, m := NewMock() + l, m := NewMock(t) l.SetLogLevel(Error) l.Log(4, "Nothing should be logged yet") - m.CheckNothingWritten(t) + m.ExpectNothing() l.Log(Debug, "or yet...") - m.CheckNothingWritten(t) + m.ExpectNothing() l.Log(Info, "or yet...") - m.CheckNothingWritten(t) + m.ExpectNothing() l.Log(Warn, "or yet!") - m.CheckNothingWritten(t) + m.ExpectNothing() l.Log(Error, "Error!") - m.CheckWrittenAtLevel(t, Error, "Error!") + m.Expect("Error!") } func TestAllLoggingLevels(t *testing.T) { - l, m := NewMock() - l.SetLogLevel(5) + l, m := NewMock(t) l.Log(4, "Log to level 4.") - m.CheckWrittenAtLevel(t, 4, "Log to level 4.") + m.ExpectAt(4, "Log to level 4.") l.Debug("Log to debug.") - m.CheckWrittenAtLevel(t, Debug, "Log to debug.") + m.ExpectAt(Debug, "Log to debug.") l.Info("Log to info.") - m.CheckWrittenAtLevel(t, Info, "Log to info.") + m.ExpectAt(Info, "Log to info.") l.Warn("Log to warning.") - m.CheckWrittenAtLevel(t, Warn, "Log to warning.") + m.ExpectAt(Warn, "Log to warning.") l.Error("Log to error.") - m.CheckWrittenAtLevel(t, Error, "Log to error.") + m.ExpectAt(Error, "Log to error.") // recover to track the panic caused by Fatal. defer func() { recover() }() l.Fatal("Log to fatal.") - m.CheckWrittenAtLevel(t, Fatal, "Log to fatal.") + m.ExpectAt(Fatal, "Log to fatal.") } diff --git a/logging/mock.go b/logging/mock.go index c126251..9e95304 100644 --- a/logging/mock.go +++ b/logging/mock.go @@ -8,6 +8,9 @@ import ( // These are provided to ease testing code that uses the logging pkg +// TODO(fluffle): Assumes at most one logging line will be written +// between calls to Expect*. Change to be Expect(exp []string)? + type mockWriter struct { written []byte } @@ -17,70 +20,108 @@ func (w *mockWriter) Write(p []byte) (n int, err os.Error) { return len(p), nil } +func (w *mockWriter) getLine() string { + // 20 bytes covers the date and time in + // 2011/10/22 10:22:57 :: + if len(w.written) < 20 { + return "" + } + s := string(w.written) + idx := strings.Index(s, "\n") + s = s[20:idx] + w.written = w.written[idx+1:] + // consume ':: ' + idx = strings.Index(s, ":") + 1 + idx += strings.Index(s[idx:], ":") + 2 + return s[idx:] +} + func (w *mockWriter) reset() { w.written = w.written[:0] } -type writerMap map[LogLevel]*mockWriter +type WriterMap struct { + t *testing.T + m map[LogLevel]*mockWriter +} // This doesn't create a mock Logger but a Logger that writes to mock outputs -func NewMock() (*logger, writerMap) { - wMap := writerMap{ - Debug: &mockWriter{make([]byte, 0)}, - Info: &mockWriter{make([]byte, 0)}, - Warn: &mockWriter{make([]byte, 0)}, - Error: &mockWriter{make([]byte, 0)}, - Fatal: &mockWriter{make([]byte, 0)}, +func NewMock(t *testing.T) (*logger, *WriterMap) { + wMap := &WriterMap{ + t: t, + m: map[LogLevel]*mockWriter{ + Debug: &mockWriter{make([]byte, 0)}, + Info: &mockWriter{make([]byte, 0)}, + Warn: &mockWriter{make([]byte, 0)}, + Error: &mockWriter{make([]byte, 0)}, + Fatal: &mockWriter{make([]byte, 0)}, + }, } logMap := make(LogMap) - for lv, w := range wMap { + for lv, w := range wMap.m { logMap[lv] = makeLogger(w) } // Set the default log level high enough that everything will get logged return New(logMap, (1 << 31) - 1, false), wMap } -func (m writerMap) CheckNothingWritten(t *testing.T) { - for lv, w := range m { - if len(w.written) > 0 { - t.Errorf("%d bytes logged at level %s, expected none:", - len(w.written), logString[lv]) - t.Errorf("\t%s", w.written) +// When you expect something to be logged but don't care so much what level at. +func (wm *WriterMap) Expect(exp string) { + found := false + for lv, w := range wm.m { + if s := w.getLine(); s != "" && !found { + // Since we don't know what log level we're expecting, compare + // exp against the log line with the level stripped. + idx := strings.Index(s, " ") + 1 + if s[idx:] == exp { + found = true + } else { + wm.t.Errorf("Unexpected log message encountered at level %s:", + LogString(lv)) + wm.t.Errorf("exp: %s\ngot: %s", exp, s[idx:]) + } + } + } + wm.ExpectNothing() + if !found { + wm.t.Errorf("Expected log message not encountered:") + wm.t.Errorf("exp: %s", exp) + } +} + + +// When you expect nothing to be logged +func (wm *WriterMap) ExpectNothing() { + for lv, w := range wm.m { + if s := w.getLine(); s != "" { + wm.t.Errorf("Unexpected log message at level %s:", + LogString(lv)) + wm.t.Errorf("%s", s) w.reset() } } } -func (m writerMap) CheckWrittenAtLevel(t *testing.T, lv LogLevel, exp string) { +// When you expect something to be logged at a specific level. +func (wm *WriterMap) ExpectAt(lv LogLevel, exp string) { var w *mockWriter - if _, ok := m[lv]; !ok { - w = m[Debug] + if _, ok := wm.m[lv]; !ok { + w = wm.m[Debug] } else { - w = m[lv] + w = wm.m[lv] } - // 20 bytes covers the date and time in - // 2011/10/22 10:22:57 log_test.go:: - if len(w.written) <= 20 { - t.Errorf("Not enough bytes logged at level %s:", LogString(lv)) - t.Errorf("exp: %s\ngot: %s", exp, w.written) + s := w.getLine() + exp = strings.Join([]string{LogString(lv), exp}, " ") + if s == "" { + wm.t.Errorf("Nothing logged at level %s:", LogString(lv)) + wm.t.Errorf("exp: %s", exp) // Check nothing was written to a different log level here, too. - m.CheckNothingWritten(t) + wm.ExpectNothing() return } - s := string(w.written[20:]) - // consume the log line file:line: and the level prefix - idx := strings.Index(s, ":") + 1 - idx += strings.Index(s[idx:], ":") + len(LogString(lv)) + 3 - // s will end in "\n", so -1 to chop that off too - s = s[idx:len(s)-1] if s != exp { - t.Errorf("Log message at level %s differed.", LogString(lv)) - t.Errorf("exp: %s\ngot: %s", exp, s) - t.Errorf("orig: %s", w.written) + wm.t.Errorf("Log message at level %s differed.", LogString(lv)) + wm.t.Errorf("exp: %s\ngot: %s", exp, s) } - w.reset() - // Calling checkNothingWritten here both tests that w.reset() works - // and verifies that nothing was written at any other levels. - m.CheckNothingWritten(t) + wm.ExpectNothing() } -