From b1c247231b11f313ca0eedff75ea563926d23f68 Mon Sep 17 00:00:00 2001 From: obscuren Date: Fri, 31 Oct 2014 12:56:05 +0100 Subject: ethlog => logger --- logger/example_test.go | 21 +++++ logger/loggers.go | 248 +++++++++++++++++++++++++++++++++++++++++++++++++ logger/loggers_test.go | 174 ++++++++++++++++++++++++++++++++++ 3 files changed, 443 insertions(+) create mode 100644 logger/example_test.go create mode 100644 logger/loggers.go create mode 100644 logger/loggers_test.go (limited to 'logger') 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) +} -- cgit