Merge pull request #59 from fjl/feature/raceless-ethlog

Improve package ethlog

1 files changed, 92 insertions, 39 deletions

diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go
index a9b1463e7..cf92e3cc6 100644
--- a/ethlog/loggers_test.go
+++ b/ethlog/loggers_test.go
@@ -1,49 +1,81 @@
 package ethlog
 
 import (
-	"fmt"
 	"io/ioutil"
+	"math/rand"
 	"os"
+	"sync"
 	"testing"
+	"time"
 )
 
 type TestLogSystem struct {
-	Output string
+	mutex  sync.Mutex
+	output string
 	level  LogLevel
 }
 
-func (t *TestLogSystem) Println(v ...interface{}) {
-	t.Output += fmt.Sprintln(v...)
+func (ls *TestLogSystem) LogPrint(level LogLevel, msg string) {
+	ls.mutex.Lock()
+	ls.output += msg
+	ls.mutex.Unlock()
 }
 
-func (t *TestLogSystem) Printf(format string, v ...interface{}) {
-	t.Output += fmt.Sprintf(format, v...)
+func (ls *TestLogSystem) SetLogLevel(i LogLevel) {
+	ls.mutex.Lock()
+	ls.level = i
+	ls.mutex.Unlock()
 }
 
-func (t *TestLogSystem) SetLogLevel(i LogLevel) {
-	t.level = i
+func (ls *TestLogSystem) GetLogLevel() LogLevel {
+	ls.mutex.Lock()
+	defer ls.mutex.Unlock()
+	return ls.level
 }
 
-func (t *TestLogSystem) GetLogLevel() LogLevel {
-	return t.level
+func (ls *TestLogSystem) CheckOutput(t *testing.T, expected string) {
+	ls.mutex.Lock()
+	output := ls.output
+	ls.mutex.Unlock()
+	if output != expected {
+		t.Errorf("log output mismatch:\n   got: %q\n  want: %q\n", output, expected)
+	}
+}
+
+type blockedLogSystem struct {
+	LogSystem
+	unblock chan struct{}
+}
+
+func (ls blockedLogSystem) LogPrint(level LogLevel, msg string) {
+	<-ls.unblock
+	ls.LogSystem.LogPrint(level, msg)
 }
 
 func TestLoggerFlush(t *testing.T) {
+	Reset()
+
 	logger := NewLogger("TEST")
-	testLogSystem := &TestLogSystem{level: WarnLevel}
-	AddLogSystem(testLogSystem)
+	ls := blockedLogSystem{&TestLogSystem{level: WarnLevel}, make(chan struct{})}
+	AddLogSystem(ls)
 	for i := 0; i < 5; i++ {
+		// these writes shouldn't hang even though ls is blocked
 		logger.Errorf(".")
 	}
-	Flush()
-	Reset()
-	output := testLogSystem.Output
-	if output != "[TEST] .[TEST] .[TEST] .[TEST] .[TEST] ." {
-		t.Error("Expected complete logger output '[TEST] .[TEST] .[TEST] .[TEST] .[TEST] .', got ", output)
+
+	beforeFlush := time.Now()
+	time.AfterFunc(80*time.Millisecond, func() { close(ls.unblock) })
+	Flush() // this should hang for approx. 80ms
+	if blockd := time.Now().Sub(beforeFlush); blockd < 80*time.Millisecond {
+		t.Errorf("Flush didn't block long enough, blocked for %v, should've been >= 80ms", blockd)
 	}
+
+	ls.LogSystem.(*TestLogSystem).CheckOutput(t, "[TEST] .[TEST] .[TEST] .[TEST] .[TEST] .")
 }
 
 func TestLoggerPrintln(t *testing.T) {
+	Reset()
+
 	logger := NewLogger("TEST")
 	testLogSystem := &TestLogSystem{level: WarnLevel}
 	AddLogSystem(testLogSystem)
@@ -52,31 +84,27 @@ func TestLoggerPrintln(t *testing.T) {
 	logger.Infoln("info")
 	logger.Debugln("debug")
 	Flush()
-	Reset()
-	output := testLogSystem.Output
-	fmt.Println(quote(output))
-	if output != "[TEST] error\n[TEST] warn\n" {
-		t.Error("Expected logger output '[TEST] error\\n[TEST] warn\\n', got ", output)
-	}
+
+	testLogSystem.CheckOutput(t, "[TEST] error\n[TEST] warn\n")
 }
 
 func TestLoggerPrintf(t *testing.T) {
+	Reset()
+
 	logger := NewLogger("TEST")
 	testLogSystem := &TestLogSystem{level: WarnLevel}
 	AddLogSystem(testLogSystem)
-	logger.Errorf("error to %v\n", *testLogSystem)
-	logger.Warnf("warn")
+	logger.Errorf("error to %v\n", []int{1, 2, 3})
+	logger.Warnf("warn %%d %d", 5)
 	logger.Infof("info")
 	logger.Debugf("debug")
 	Flush()
-	Reset()
-	output := testLogSystem.Output
-	if output != "[TEST] error to { 2}\n[TEST] warn" {
-		t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", output)
-	}
+	testLogSystem.CheckOutput(t, "[TEST] error to [1 2 3]\n[TEST] warn %d 5")
 }
 
 func TestMultipleLogSystems(t *testing.T) {
+	Reset()
+
 	logger := NewLogger("TEST")
 	testLogSystem0 := &TestLogSystem{level: ErrorLevel}
 	testLogSystem1 := &TestLogSystem{level: WarnLevel}
@@ -85,18 +113,14 @@ func TestMultipleLogSystems(t *testing.T) {
 	logger.Errorln("error")
 	logger.Warnln("warn")
 	Flush()
-	Reset()
-	output0 := testLogSystem0.Output
-	output1 := testLogSystem1.Output
-	if output0 != "[TEST] error\n" {
-		t.Error("Expected logger 0 output '[TEST] error\\n', got ", output0)
-	}
-	if output1 != "[TEST] error\n[TEST] warn\n" {
-		t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", output1)
-	}
+
+	testLogSystem0.CheckOutput(t, "[TEST] error\n")
+	testLogSystem1.CheckOutput(t, "[TEST] error\n[TEST] warn\n")
 }
 
 func TestFileLogSystem(t *testing.T) {
+	Reset()
+
 	logger := NewLogger("TEST")
 	filename := "test.log"
 	file, _ := os.OpenFile(filename, os.O_RDWR|os.O_CREATE, os.ModePerm)
@@ -115,7 +139,36 @@ func TestFileLogSystem(t *testing.T) {
 }
 
 func TestNoLogSystem(t *testing.T) {
+	Reset()
+
 	logger := NewLogger("TEST")
 	logger.Warnln("warn")
 	Flush()
 }
+
+func TestConcurrentAddSystem(t *testing.T) {
+	rand.Seed(time.Now().Unix())
+	Reset()
+
+	logger := NewLogger("TEST")
+	stop := make(chan struct{})
+	writer := func() {
+		select {
+		case <-stop:
+			return
+		default:
+			logger.Infoln("foo")
+			Flush()
+		}
+	}
+
+	go writer()
+	go writer()
+
+	stopTime := time.Now().Add(100 * time.Millisecond)
+	for time.Now().Before(stopTime) {
+		time.Sleep(time.Duration(rand.Intn(20)) * time.Millisecond)
+		AddLogSystem(NewStdLogSystem(ioutil.Discard, 0, InfoLevel))
+	}
+	close(stop)
+}