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

@@ -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, m := NewMock(t)
-	l.SetLogLevel(5)
 
 	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.")
 }

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 <file>:<line>: <level> <log message>
+	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 '<file>:<line>: '
+	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) {
+func NewMock(t *testing.T) (*logger, *WriterMap) {
-	wMap := writerMap{
+	wMap := &WriterMap{
-		Debug: &mockWriter{make([]byte, 0)},
+		t: t,
-		Info:  &mockWriter{make([]byte, 0)},
+		m: map[LogLevel]*mockWriter{
-		Warn:  &mockWriter{make([]byte, 0)},
+			Debug: &mockWriter{make([]byte, 0)},
-		Error: &mockWriter{make([]byte, 0)},
+			Info:  &mockWriter{make([]byte, 0)},
-		Fatal: &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) {
+// When you expect something to be logged but don't care so much what level at.
-	for lv, w := range m {
+func (wm *WriterMap) Expect(exp string) {
-		if len(w.written) > 0 {
+	found := false
-			t.Errorf("%d bytes logged at level %s, expected none:",
+	for lv, w := range wm.m {
-				len(w.written), logString[lv])
+		if s := w.getLine(); s != "" && !found {
-			t.Errorf("\t%s", w.written)
+			// 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 {
+	if _, ok := wm.m[lv]; !ok {
-		w = m[Debug]
+		w = wm.m[Debug]
 	} else {
-		w = m[lv]
+		w = wm.m[lv]
 	}
-	// 20 bytes covers the date and time in
+	s := w.getLine()
-	// 2011/10/22 10:22:57 log_test.go:<line no>: <level> <log message>
+	exp = strings.Join([]string{LogString(lv), exp}, " ")
-	if len(w.written) <= 20 {
+	if s == "" {
-		t.Errorf("Not enough bytes logged at level %s:", LogString(lv))
+		wm.t.Errorf("Nothing logged at level %s:", LogString(lv))
-		t.Errorf("exp: %s\ngot: %s", exp, w.written)
+		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))
+		wm.t.Errorf("Log message at level %s differed.", LogString(lv))
-		t.Errorf("exp: %s\ngot: %s", exp, s)
+		wm.t.Errorf("exp: %s\ngot: %s", exp, s)
-		t.Errorf("orig: %s", w.written)
 	}
-	w.reset()
+	wm.ExpectNothing()
-	// Calling checkNothingWritten here both tests that w.reset() works
-	// and verifies that nothing was written at any other levels.
-	m.CheckNothingWritten(t)
 }
-