ethlog => logger

3 files changed, 443 insertions, 0 deletions

diff --git a/logger/example_test.go b/logger/example_test.go
new file mode 100644
index 000000000..c624252b8
--- /dev/null
+++ b/logger/example_test.go
@@ -0,0 +1,21 @@
+package logger
+
+import "os"
+
+func ExampleLogger() {
+	logger := NewLogger("TAG")
+	logger.Infoln("so awesome")            // prints [TAG] so awesome
+	logger.Infof("this %q is raw", "coin") // prints [TAG] this "coin" is raw
+}
+
+func ExampleLogSystem() {
+	filename := "test.log"
+	file, _ := os.OpenFile(filename, os.O_RDWR|os.O_CREATE, os.ModePerm)
+	fileLog := NewStdLogSystem(file, 0, WarnLevel)
+	AddLogSystem(fileLog)
+
+	stdoutLog := NewStdLogSystem(os.Stdout, 0, WarnLevel)
+	AddLogSystem(stdoutLog)
+
+	NewLogger("TAG").Warnln("reactor meltdown") // writes to both logs
+}
diff --git a/logger/loggers.go b/logger/loggers.go
new file mode 100644
index 000000000..1bf7bfa0e
--- /dev/null
+++ b/logger/loggers.go
@@ -0,0 +1,248 @@
+/*
+Package logger implements a multi-output leveled logger.
+
+Other packages use tagged logger to send log messages to shared
+(process-wide) logging engine. The shared logging engine dispatches to
+multiple log systems. The log level can be set separately per log
+system.
+
+Logging is asynchronous and does not block the caller. Message
+formatting is performed by the caller goroutine to avoid incorrect
+logging of mutable state.
+*/
+package logger
+
+import (
+	"fmt"
+	"io"
+	"log"
+	"os"
+	"sync"
+	"sync/atomic"
+)
+
+// LogSystem is implemented by log output devices.
+// All methods can be called concurrently from multiple goroutines.
+type LogSystem interface {
+	GetLogLevel() LogLevel
+	SetLogLevel(i LogLevel)
+	LogPrint(LogLevel, string)
+}
+
+type message struct {
+	level LogLevel
+	msg   string
+}
+
+type LogLevel uint8
+
+const (
+	// Standard log levels
+	Silence LogLevel = iota
+	ErrorLevel
+	WarnLevel
+	InfoLevel
+	DebugLevel
+	DebugDetailLevel
+)
+
+var (
+	logMessageC = make(chan message)
+	addSystemC  = make(chan LogSystem)
+	flushC      = make(chan chan struct{})
+	resetC      = make(chan chan struct{})
+)
+
+func init() {
+	go dispatchLoop()
+}
+
+// each system can buffer this many messages before
+// blocking incoming log messages.
+const sysBufferSize = 500
+
+func dispatchLoop() {
+	var (
+		systems  []LogSystem
+		systemIn []chan message
+		systemWG sync.WaitGroup
+	)
+	bootSystem := func(sys LogSystem) {
+		in := make(chan message, sysBufferSize)
+		systemIn = append(systemIn, in)
+		systemWG.Add(1)
+		go sysLoop(sys, in, &systemWG)
+	}
+
+	for {
+		select {
+		case msg := <-logMessageC:
+			for _, c := range systemIn {
+				c <- msg
+			}
+
+		case sys := <-addSystemC:
+			systems = append(systems, sys)
+			bootSystem(sys)
+
+		case waiter := <-resetC:
+			// reset means terminate all systems
+			for _, c := range systemIn {
+				close(c)
+			}
+			systems = nil
+			systemIn = nil
+			systemWG.Wait()
+			close(waiter)
+
+		case waiter := <-flushC:
+			// flush means reboot all systems
+			for _, c := range systemIn {
+				close(c)
+			}
+			systemIn = nil
+			systemWG.Wait()
+			for _, sys := range systems {
+				bootSystem(sys)
+			}
+			close(waiter)
+		}
+	}
+}
+
+func sysLoop(sys LogSystem, in <-chan message, wg *sync.WaitGroup) {
+	for msg := range in {
+		if sys.GetLogLevel() >= msg.level {
+			sys.LogPrint(msg.level, msg.msg)
+		}
+	}
+	wg.Done()
+}
+
+// Reset removes all active log systems.
+// It blocks until all current messages have been delivered.
+func Reset() {
+	waiter := make(chan struct{})
+	resetC <- waiter
+	<-waiter
+}
+
+// Flush waits until all current log messages have been dispatched to
+// the active log systems.
+func Flush() {
+	waiter := make(chan struct{})
+	flushC <- waiter
+	<-waiter
+}
+
+// AddLogSystem starts printing messages to the given LogSystem.
+func AddLogSystem(sys LogSystem) {
+	addSystemC <- sys
+}
+
+// A Logger prints messages prefixed by a given tag. It provides named
+// Printf and Println style methods for all loglevels. Each ethereum
+// component should have its own logger with a unique prefix.
+type Logger struct {
+	tag string
+}
+
+func NewLogger(tag string) *Logger {
+	return &Logger{"[" + tag + "] "}
+}
+
+func (logger *Logger) sendln(level LogLevel, v ...interface{}) {
+	logMessageC <- message{level, logger.tag + fmt.Sprintln(v...)}
+}
+
+func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) {
+	logMessageC <- message{level, logger.tag + fmt.Sprintf(format, v...)}
+}
+
+// Errorln writes a message with ErrorLevel.
+func (logger *Logger) Errorln(v ...interface{}) {
+	logger.sendln(ErrorLevel, v...)
+}
+
+// Warnln writes a message with WarnLevel.
+func (logger *Logger) Warnln(v ...interface{}) {
+	logger.sendln(WarnLevel, v...)
+}
+
+// Infoln writes a message with InfoLevel.
+func (logger *Logger) Infoln(v ...interface{}) {
+	logger.sendln(InfoLevel, v...)
+}
+
+// Debugln writes a message with DebugLevel.
+func (logger *Logger) Debugln(v ...interface{}) {
+	logger.sendln(DebugLevel, v...)
+}
+
+// DebugDetailln writes a message with DebugDetailLevel.
+func (logger *Logger) DebugDetailln(v ...interface{}) {
+	logger.sendln(DebugDetailLevel, v...)
+}
+
+// Errorf writes a message with ErrorLevel.
+func (logger *Logger) Errorf(format string, v ...interface{}) {
+	logger.sendf(ErrorLevel, format, v...)
+}
+
+// Warnf writes a message with WarnLevel.
+func (logger *Logger) Warnf(format string, v ...interface{}) {
+	logger.sendf(WarnLevel, format, v...)
+}
+
+// Infof writes a message with InfoLevel.
+func (logger *Logger) Infof(format string, v ...interface{}) {
+	logger.sendf(InfoLevel, format, v...)
+}
+
+// Debugf writes a message with DebugLevel.
+func (logger *Logger) Debugf(format string, v ...interface{}) {
+	logger.sendf(DebugLevel, format, v...)
+}
+
+// DebugDetailf writes a message with DebugDetailLevel.
+func (logger *Logger) DebugDetailf(format string, v ...interface{}) {
+	logger.sendf(DebugDetailLevel, format, v...)
+}
+
+// Fatalln writes a message with ErrorLevel and exits the program.
+func (logger *Logger) Fatalln(v ...interface{}) {
+	logger.sendln(ErrorLevel, v...)
+	Flush()
+	os.Exit(0)
+}
+
+// Fatalf writes a message with ErrorLevel and exits the program.
+func (logger *Logger) Fatalf(format string, v ...interface{}) {
+	logger.sendf(ErrorLevel, format, v...)
+	Flush()
+	os.Exit(0)
+}
+
+// NewStdLogSystem creates a LogSystem that prints to the given writer.
+// The flag values are defined package log.
+func NewStdLogSystem(writer io.Writer, flags int, level LogLevel) LogSystem {
+	logger := log.New(writer, "", flags)
+	return &stdLogSystem{logger, uint32(level)}
+}
+
+type stdLogSystem struct {
+	logger *log.Logger
+	level  uint32
+}
+
+func (t *stdLogSystem) LogPrint(level LogLevel, msg string) {
+	t.logger.Print(msg)
+}
+
+func (t *stdLogSystem) SetLogLevel(i LogLevel) {
+	atomic.StoreUint32(&t.level, uint32(i))
+}
+
+func (t *stdLogSystem) GetLogLevel() LogLevel {
+	return LogLevel(atomic.LoadUint32(&t.level))
+}
diff --git a/logger/loggers_test.go b/logger/loggers_test.go
new file mode 100644
index 000000000..adc4df016
--- /dev/null
+++ b/logger/loggers_test.go
@@ -0,0 +1,174 @@
+package logger
+
+import (
+	"io/ioutil"
+	"math/rand"
+	"os"
+	"sync"
+	"testing"
+	"time"
+)
+
+type TestLogSystem struct {
+	mutex  sync.Mutex
+	output string
+	level  LogLevel
+}
+
+func (ls *TestLogSystem) LogPrint(level LogLevel, msg string) {
+	ls.mutex.Lock()
+	ls.output += msg
+	ls.mutex.Unlock()
+}
+
+func (ls *TestLogSystem) SetLogLevel(i LogLevel) {
+	ls.mutex.Lock()
+	ls.level = i
+	ls.mutex.Unlock()
+}
+
+func (ls *TestLogSystem) GetLogLevel() LogLevel {
+	ls.mutex.Lock()
+	defer ls.mutex.Unlock()
+	return ls.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")
+	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(".")
+	}
+
+	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)
+	logger.Errorln("error")
+	logger.Warnln("warn")
+	logger.Infoln("info")
+	logger.Debugln("debug")
+	Flush()
+
+	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", []int{1, 2, 3})
+	logger.Warnf("warn %%d %d", 5)
+	logger.Infof("info")
+	logger.Debugf("debug")
+	Flush()
+	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}
+	AddLogSystem(testLogSystem0)
+	AddLogSystem(testLogSystem1)
+	logger.Errorln("error")
+	logger.Warnln("warn")
+	Flush()
+
+	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)
+	testLogSystem := NewStdLogSystem(file, 0, WarnLevel)
+	AddLogSystem(testLogSystem)
+	logger.Errorf("error to %s\n", filename)
+	logger.Warnln("warn")
+	Flush()
+	contents, _ := ioutil.ReadFile(filename)
+	output := string(contents)
+	if output != "[TEST] error to test.log\n[TEST] warn\n" {
+		t.Error("Expected contents of file 'test.log': '[TEST] error to test.log\\n[TEST] warn\\n', got ", output)
+	} else {
+		os.Remove(filename)
+	}
+}
+
+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)
+}