From 4e95cecfb999425e40b0c071b9768b1654167fe2 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 14:29:04 +0200 Subject: ethlog: improve dispatch concurrency This also fixes a deadlock in the tests. --- ethlog/loggers.go | 111 ++++++++++++++++++++++++++++-------------------------- 1 file changed, 57 insertions(+), 54 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index b2760534b..34561853a 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -29,20 +29,6 @@ func newPrintfLogMessage(level LogLevel, tag string, format string, v ...interfa return &logMessage{level, true, fmt.Sprintf("[%s] %s", tag, fmt.Sprintf(format, v...))} } -func (msg *logMessage) send(logger LogSystem) { - if msg.format { - logger.Printf(msg.msg) - } else { - logger.Println(msg.msg) - } -} - -var logMessages chan (*logMessage) -var logSystems []LogSystem -var quit chan chan error -var drained chan bool -var mutex = sync.Mutex{} - type LogLevel uint8 const ( @@ -54,56 +40,80 @@ const ( DebugDetailLevel ) -func dispatch(msg *logMessage) { - for _, logSystem := range logSystems { - if logSystem.GetLogLevel() >= msg.LogLevel { - msg.send(logSystem) - } - } +var ( + mutex sync.RWMutex // protects logSystems + logSystems []LogSystem + + logMessages = make(chan *logMessage) + drainWaitReq = make(chan chan struct{}) +) + +func init() { + go dispatchLoop() } -// log messages are dispatched to log writers -func start() { +func dispatchLoop() { + var drainWait []chan struct{} + dispatchDone := make(chan struct{}) + pending := 0 for { select { - case status := <-quit: - status <- nil - return case msg := <-logMessages: - dispatch(msg) - default: - drained <- true // this blocks until a message is sent to the queue + go dispatch(msg, dispatchDone) + pending++ + case waiter := <-drainWaitReq: + if pending == 0 { + close(waiter) + } else { + drainWait = append(drainWait, waiter) + } + case <-dispatchDone: + pending-- + if pending == 0 { + for _, c := range drainWait { + close(c) + } + drainWait = nil + } } } } +func dispatch(msg *logMessage, done chan<- struct{}) { + mutex.RLock() + for _, sys := range logSystems { + if sys.GetLogLevel() >= msg.LogLevel { + if msg.format { + sys.Printf(msg.msg) + } else { + sys.Println(msg.msg) + } + } + } + mutex.RUnlock() + done <- struct{}{} +} + +// send delivers a message to all installed log +// systems. it doesn't wait for the message to be +// written. func send(msg *logMessage) { logMessages <- msg - select { - case <-drained: - default: - } } +// Reset removes all registered log systems. func Reset() { mutex.Lock() - defer mutex.Unlock() - if logSystems != nil { - status := make(chan error) - quit <- status - select { - case <-drained: - default: - } - <-status - } + logSystems = nil + mutex.Unlock() } -// waits until log messages are drained (dispatched to log writers) +// Flush waits until all current log messages have been dispatched to +// the active log systems. func Flush() { - if logSystems != nil { - <-drained - } + waiter := make(chan struct{}) + drainWaitReq <- waiter + <-waiter } type Logger struct { @@ -115,16 +125,9 @@ func NewLogger(tag string) *Logger { } func AddLogSystem(logSystem LogSystem) { - var mutex = &sync.Mutex{} mutex.Lock() - defer mutex.Unlock() - if logSystems == nil { - logMessages = make(chan *logMessage, 10) - quit = make(chan chan error, 1) - drained = make(chan bool, 1) - go start() - } logSystems = append(logSystems, logSystem) + mutex.Unlock() } func (logger *Logger) sendln(level LogLevel, v ...interface{}) { -- cgit v1.2.3 From dac128a029ee8d80d4ebdad64b24506c03d55e63 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 14:31:33 +0200 Subject: ethlog: fix test compilation error --- ethlog/loggers_test.go | 1 - 1 file changed, 1 deletion(-) (limited to 'ethlog') diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index a9b1463e7..2b0d1fb1d 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -54,7 +54,6 @@ func TestLoggerPrintln(t *testing.T) { 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) } -- cgit v1.2.3 From 3b1296077b2f814bf4bf478aea63503d18ece86f Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 14:33:58 +0200 Subject: ethlog: Reset before each test --- ethlog/loggers_test.go | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index 2b0d1fb1d..fbfb2c99b 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -29,6 +29,8 @@ func (t *TestLogSystem) GetLogLevel() LogLevel { } func TestLoggerFlush(t *testing.T) { + Reset() + logger := NewLogger("TEST") testLogSystem := &TestLogSystem{level: WarnLevel} AddLogSystem(testLogSystem) @@ -36,7 +38,6 @@ func TestLoggerFlush(t *testing.T) { 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) @@ -44,6 +45,8 @@ func TestLoggerFlush(t *testing.T) { } func TestLoggerPrintln(t *testing.T) { + Reset() + logger := NewLogger("TEST") testLogSystem := &TestLogSystem{level: WarnLevel} AddLogSystem(testLogSystem) @@ -52,7 +55,6 @@ func TestLoggerPrintln(t *testing.T) { logger.Infoln("info") logger.Debugln("debug") Flush() - Reset() output := testLogSystem.Output if output != "[TEST] error\n[TEST] warn\n" { t.Error("Expected logger output '[TEST] error\\n[TEST] warn\\n', got ", output) @@ -60,6 +62,8 @@ func TestLoggerPrintln(t *testing.T) { } func TestLoggerPrintf(t *testing.T) { + Reset() + logger := NewLogger("TEST") testLogSystem := &TestLogSystem{level: WarnLevel} AddLogSystem(testLogSystem) @@ -68,7 +72,6 @@ func TestLoggerPrintf(t *testing.T) { 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) @@ -76,6 +79,8 @@ func TestLoggerPrintf(t *testing.T) { } func TestMultipleLogSystems(t *testing.T) { + Reset() + logger := NewLogger("TEST") testLogSystem0 := &TestLogSystem{level: ErrorLevel} testLogSystem1 := &TestLogSystem{level: WarnLevel} @@ -84,7 +89,6 @@ func TestMultipleLogSystems(t *testing.T) { logger.Errorln("error") logger.Warnln("warn") Flush() - Reset() output0 := testLogSystem0.Output output1 := testLogSystem1.Output if output0 != "[TEST] error\n" { @@ -96,6 +100,8 @@ func TestMultipleLogSystems(t *testing.T) { } func TestFileLogSystem(t *testing.T) { + Reset() + logger := NewLogger("TEST") filename := "test.log" file, _ := os.OpenFile(filename, os.O_RDWR|os.O_CREATE, os.ModePerm) @@ -114,6 +120,8 @@ func TestFileLogSystem(t *testing.T) { } func TestNoLogSystem(t *testing.T) { + Reset() + logger := NewLogger("TEST") logger.Warnln("warn") Flush() -- cgit v1.2.3 From d5a7ba1626b9c7bbc5733a44fbda2ed50070c1b9 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 14:35:16 +0200 Subject: ethlog: add test that adds log systems concurrently --- ethlog/loggers_test.go | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) (limited to 'ethlog') diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index fbfb2c99b..4c62a0dbd 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -3,8 +3,10 @@ package ethlog import ( "fmt" "io/ioutil" + "math/rand" "os" "testing" + "time" ) type TestLogSystem struct { @@ -126,3 +128,30 @@ func TestNoLogSystem(t *testing.T) { 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.Infof("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(&TestLogSystem{level: InfoLevel}) + } + close(stop) +} -- cgit v1.2.3 From 45d1052229f5390d76e912f15e17240a0eddc7b9 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 14:35:54 +0200 Subject: ethlog: fix StdLogSystem data race on level --- ethlog/loggers.go | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index 34561853a..edf77bda1 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -6,6 +6,7 @@ import ( "log" "os" "sync" + "sync/atomic" ) type LogSystem interface { @@ -198,7 +199,7 @@ func (logger *Logger) Fatalf(format string, v ...interface{}) { type StdLogSystem struct { logger *log.Logger - level LogLevel + level uint32 } func (t *StdLogSystem) Println(v ...interface{}) { @@ -210,14 +211,14 @@ func (t *StdLogSystem) Printf(format string, v ...interface{}) { } func (t *StdLogSystem) SetLogLevel(i LogLevel) { - t.level = i + atomic.StoreUint32(&t.level, uint32(i)) } func (t *StdLogSystem) GetLogLevel() LogLevel { - return t.level + return LogLevel(atomic.LoadUint32(&t.level)) } func NewStdLogSystem(writer io.Writer, flags int, level LogLevel) *StdLogSystem { logger := log.New(writer, "", flags) - return &StdLogSystem{logger, level} + return &StdLogSystem{logger, uint32(level)} } -- cgit v1.2.3 From ec132749aab8f4b26181bfc2c4b3190aa104fdb5 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 19:05:43 +0200 Subject: ethlog: improve TestLogSystem It's now safe for concurrent access. Output checking looks better. --- ethlog/loggers_test.go | 65 +++++++++++++++++++++++++++++--------------------- 1 file changed, 38 insertions(+), 27 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index 4c62a0dbd..c1a7de997 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -5,29 +5,50 @@ import ( "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) Println(v ...interface{}) { + ls.mutex.Lock() + ls.output += fmt.Sprintln(v...) + ls.mutex.Unlock() } -func (t *TestLogSystem) Printf(format string, v ...interface{}) { - t.Output += fmt.Sprintf(format, v...) +func (ls *TestLogSystem) Printf(format string, v ...interface{}) { + ls.mutex.Lock() + ls.output += fmt.Sprintf(format, v...) + ls.mutex.Unlock() } -func (t *TestLogSystem) SetLogLevel(i LogLevel) { - t.level = i +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) + } } -func (t *TestLogSystem) GetLogLevel() LogLevel { - return t.level } func TestLoggerFlush(t *testing.T) { @@ -57,10 +78,8 @@ func TestLoggerPrintln(t *testing.T) { logger.Infoln("info") logger.Debugln("debug") Flush() - output := testLogSystem.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) { @@ -69,15 +88,12 @@ func TestLoggerPrintf(t *testing.T) { logger := NewLogger("TEST") testLogSystem := &TestLogSystem{level: WarnLevel} AddLogSystem(testLogSystem) - logger.Errorf("error to %v\n", *testLogSystem) + logger.Errorf("error to %v\n", []int{1, 2, 3}) logger.Warnf("warn") logger.Infof("info") logger.Debugf("debug") Flush() - 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") } func TestMultipleLogSystems(t *testing.T) { @@ -91,14 +107,9 @@ func TestMultipleLogSystems(t *testing.T) { logger.Errorln("error") logger.Warnln("warn") Flush() - 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) { @@ -140,7 +151,7 @@ func TestConcurrentAddSystem(t *testing.T) { case <-stop: return default: - logger.Infof("foo") + logger.Infoln("foo") Flush() } } -- cgit v1.2.3 From 793baf060a0e918b5d5ca72a425c99751b93ab41 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 19:07:19 +0200 Subject: ethlog: don't buffer output in TestConcurrentAddSystem --- ethlog/loggers_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'ethlog') diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index c1a7de997..ffc30e21f 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -162,7 +162,7 @@ func TestConcurrentAddSystem(t *testing.T) { stopTime := time.Now().Add(100 * time.Millisecond) for time.Now().Before(stopTime) { time.Sleep(time.Duration(rand.Intn(20)) * time.Millisecond) - AddLogSystem(&TestLogSystem{level: InfoLevel}) + AddLogSystem(NewStdLogSystem(ioutil.Discard, 0, InfoLevel)) } close(stop) } -- cgit v1.2.3 From a6265cb49a0fd5641e53ed8cc8505bb91cb88976 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 19:07:54 +0200 Subject: ethlog: verify that Flush is blocking in TestLoggerFlush --- ethlog/loggers_test.go | 30 ++++++++++++++++++++++++------ 1 file changed, 24 insertions(+), 6 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index ffc30e21f..0466a3d59 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -49,22 +49,40 @@ func (ls *TestLogSystem) CheckOutput(t *testing.T, expected string) { } } +type blockedLogSystem struct { + LogSystem + unblock chan struct{} +} + +func (ls blockedLogSystem) Println(v ...interface{}) { + <-ls.unblock + ls.LogSystem.Println(v...) +} + +func (ls blockedLogSystem) Printf(fmt string, v ...interface{}) { + <-ls.unblock + ls.LogSystem.Printf(fmt, v...) } 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() - 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) { -- cgit v1.2.3 From e0f93c74c54f04e8da18ee0f0eee58e322ddc89b Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Tue, 14 Oct 2014 19:35:10 +0200 Subject: ethlog: add Godoc documentation, remove README --- ethlog/README.md | 62 --------------------------------------- ethlog/loggers.go | 87 ++++++++++++++++++++++++++++++++++++++++++++----------- 2 files changed, 70 insertions(+), 79 deletions(-) delete mode 100644 ethlog/README.md (limited to 'ethlog') diff --git a/ethlog/README.md b/ethlog/README.md deleted file mode 100644 index d9b69e106..000000000 --- a/ethlog/README.md +++ /dev/null @@ -1,62 +0,0 @@ -## Features - -- packages use tagged logger sending log messages to shared (process-wide) logging engine -- log writers (interface ethlog.LogSystem) can be added to the logging engine by wrappers/guis/clients -- shared logging engine dispatching to multiple log systems -- log level can be set separately per log system -- async logging thread: logging IO does not block main thread -- log messages are synchronously stringified to avoid incorrectly logging of changed states -- log level enum: ethlog.LogLevel: Silence, ErrorLevel, WarnLevel, InfoLevel, DebugLevel, DebugDetailLevel - -## Usage - -In an ethereum component package: - - import "github.com/ethereum/eth-go/ethlog" - - // package-wide logger using tag - var logger = ethlog.NewLogger("TAG") - -Logger provides named Printf and Println style methods for all loglevels - - logger.Infoln("this is info") # > [TAG] This is info - logger.Infof("this %v is info", object) # > [TAG] This object is info - -Ethereum wrappers should register log systems conforming to ethlog.LogSystem - - import "github.com/ethereum/eth-go/ethlog" - - type CustomLogWriter struct { - logLevel ethlog.LogLevel - } - - func (t *TestLogSystem) SetLogLevel(i LogLevel) { - t.level = i - } - - func (t *TestLogSystem) GetLogLevel() LogLevel { - return t.level - } - - func (c *CustomLogWriter) Printf(format string, v...interface{}) { - //.... - } - - func (c *CustomLogWriter) Println(v...interface{}) { - //.... - } - - ethlog.AddLogWriter(&CustomLogWriter{}) - -ethlog also provides constructors for that wrap io.Writers into a standard logger with a settable level: - - filename := "test.log" - file, _ := os.OpenFile(filename, os.O_RDWR|os.O_CREATE, os.ModePerm) - fileLogSystem := NewStdLogSystem(file, 0, WarnLevel) - AddLogSystem(fileLogSystem) - stdOutLogSystem := NewStdLogSystem(os.Stdout, 0, WarnLevel) - AddLogSystem(stdOutLogSystem) - - - - diff --git a/ethlog/loggers.go b/ethlog/loggers.go index edf77bda1..d1a4c5863 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -1,3 +1,36 @@ +/* +Package ethlog implements a multi-output leveled logger. + +Features + +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 asynchrounous and does not block the main thread. Message +formatting is performed by the caller goroutine to avoid incorrect +logging of mutable state. + +Usage + +The Logger type provides named Printf and Println style methods for +all loglevels. Each ethereum component should have its own logger with +a unique prefix. + + logger.Infoln("this is info") # > [TAG] This is info + logger.Infof("this %v is info", object) # > [TAG] This object is info + +ethlog also provides constructors for that wrap io.Writers into a +standard logger with a settable level: + + filename := "test.log" + file, _ := os.OpenFile(filename, os.O_RDWR|os.O_CREATE, os.ModePerm) + fileLogSystem := NewStdLogSystem(file, 0, WarnLevel) + AddLogSystem(fileLogSystem) + stdOutLogSystem := NewStdLogSystem(os.Stdout, 0, WarnLevel) + AddLogSystem(stdOutLogSystem) + +*/ package ethlog import ( @@ -9,6 +42,8 @@ import ( "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) @@ -33,6 +68,7 @@ func newPrintfLogMessage(level LogLevel, tag string, format string, v ...interfa type LogLevel uint8 const ( + // Standard log levels Silence LogLevel = iota ErrorLevel WarnLevel @@ -102,7 +138,7 @@ func send(msg *logMessage) { logMessages <- msg } -// Reset removes all registered log systems. +// Reset removes all active log systems. func Reset() { mutex.Lock() logSystems = nil @@ -117,6 +153,15 @@ func Flush() { <-waiter } +// AddLogSystem starts printing messages to the given LogSystem. +func AddLogSystem(logSystem LogSystem) { + mutex.Lock() + logSystems = append(logSystems, logSystem) + mutex.Unlock() +} + +// A Logger prints messages prefixed by a given tag. +// You should create one with a unique tag for each high-level component. type Logger struct { tag string } @@ -125,12 +170,6 @@ func NewLogger(tag string) *Logger { return &Logger{tag} } -func AddLogSystem(logSystem LogSystem) { - mutex.Lock() - logSystems = append(logSystems, logSystem) - mutex.Unlock() -} - func (logger *Logger) sendln(level LogLevel, v ...interface{}) { if logMessages != nil { msg := newPrintlnLogMessage(level, logger.tag, v...) @@ -145,80 +184,94 @@ func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { } } +// 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) } -type StdLogSystem struct { +// 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) Println(v ...interface{}) { +func (t *stdLogSystem) Println(v ...interface{}) { t.logger.Println(v...) } -func (t *StdLogSystem) Printf(format string, v ...interface{}) { +func (t *stdLogSystem) Printf(format string, v ...interface{}) { t.logger.Printf(format, v...) } -func (t *StdLogSystem) SetLogLevel(i LogLevel) { +func (t *stdLogSystem) SetLogLevel(i LogLevel) { atomic.StoreUint32(&t.level, uint32(i)) } -func (t *StdLogSystem) GetLogLevel() LogLevel { +func (t *stdLogSystem) GetLogLevel() LogLevel { return LogLevel(atomic.LoadUint32(&t.level)) } - -func NewStdLogSystem(writer io.Writer, flags int, level LogLevel) *StdLogSystem { - logger := log.New(writer, "", flags) - return &StdLogSystem{logger, uint32(level)} -} -- cgit v1.2.3 From 0165c1833017963a280f135a5733974a9fc3ec0b Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Wed, 15 Oct 2014 11:15:59 +0200 Subject: ethlog: use Godoc for code examples in documentation This ensures that examples will actually compile. --- ethlog/example_test.go | 21 +++++++++++++++++++++ ethlog/loggers.go | 36 ++++++++---------------------------- 2 files changed, 29 insertions(+), 28 deletions(-) create mode 100644 ethlog/example_test.go (limited to 'ethlog') diff --git a/ethlog/example_test.go b/ethlog/example_test.go new file mode 100644 index 000000000..2532f36c1 --- /dev/null +++ b/ethlog/example_test.go @@ -0,0 +1,21 @@ +package ethlog + +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/ethlog/loggers.go b/ethlog/loggers.go index d1a4c5863..b8a7b0455 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -1,35 +1,14 @@ /* Package ethlog implements a multi-output leveled logger. -Features +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. -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 asynchrounous and does not block the main thread. Message +Logging is asynchrounous and does not block the caller. Message formatting is performed by the caller goroutine to avoid incorrect logging of mutable state. - -Usage - -The Logger type provides named Printf and Println style methods for -all loglevels. Each ethereum component should have its own logger with -a unique prefix. - - logger.Infoln("this is info") # > [TAG] This is info - logger.Infof("this %v is info", object) # > [TAG] This object is info - -ethlog also provides constructors for that wrap io.Writers into a -standard logger with a settable level: - - filename := "test.log" - file, _ := os.OpenFile(filename, os.O_RDWR|os.O_CREATE, os.ModePerm) - fileLogSystem := NewStdLogSystem(file, 0, WarnLevel) - AddLogSystem(fileLogSystem) - stdOutLogSystem := NewStdLogSystem(os.Stdout, 0, WarnLevel) - AddLogSystem(stdOutLogSystem) - */ package ethlog @@ -160,8 +139,9 @@ func AddLogSystem(logSystem LogSystem) { mutex.Unlock() } -// A Logger prints messages prefixed by a given tag. -// You should create one with a unique tag for each high-level component. +// 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 } -- cgit v1.2.3 From 50f5ba5b0cfdf02cd87a9070676bd3c21c217296 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Thu, 16 Oct 2014 10:48:33 +0200 Subject: ethlog: add test for '%' in log message This test fails because the log message is formatted twice. --- ethlog/loggers_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index 0466a3d59..23f649312 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -107,11 +107,11 @@ func TestLoggerPrintf(t *testing.T) { testLogSystem := &TestLogSystem{level: WarnLevel} AddLogSystem(testLogSystem) logger.Errorf("error to %v\n", []int{1, 2, 3}) - logger.Warnf("warn") + 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") + testLogSystem.CheckOutput(t, "[TEST] error to [1 2 3]\n[TEST] warn %d 5") } func TestMultipleLogSystems(t *testing.T) { -- cgit v1.2.3 From c090a77f1c9bc890e67a00fb47a1c23c8769799d Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Thu, 16 Oct 2014 10:50:51 +0200 Subject: ethlog: simplify LogSystem interface Messages are formatted by generic part, so the log system doesn't need to provide formatting. This fixes the test from the previous commit. As a small bonus, log systems now have access to the level of the message. This could be used to provide colored logging in the future. --- ethlog/loggers.go | 57 ++++++++++++-------------------------------------- ethlog/loggers_test.go | 20 ++++-------------- 2 files changed, 17 insertions(+), 60 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index b8a7b0455..f5ec4d402 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -26,22 +26,12 @@ import ( type LogSystem interface { GetLogLevel() LogLevel SetLogLevel(i LogLevel) - Println(v ...interface{}) - Printf(format string, v ...interface{}) + LogPrint(LogLevel, string) } -type logMessage struct { - LogLevel LogLevel - format bool - msg string -} - -func newPrintlnLogMessage(level LogLevel, tag string, v ...interface{}) *logMessage { - return &logMessage{level, false, fmt.Sprintf("[%s] %s", tag, fmt.Sprint(v...))} -} - -func newPrintfLogMessage(level LogLevel, tag string, format string, v ...interface{}) *logMessage { - return &logMessage{level, true, fmt.Sprintf("[%s] %s", tag, fmt.Sprintf(format, v...))} +type message struct { + level LogLevel + msg string } type LogLevel uint8 @@ -60,7 +50,7 @@ var ( mutex sync.RWMutex // protects logSystems logSystems []LogSystem - logMessages = make(chan *logMessage) + logMessages = make(chan message) drainWaitReq = make(chan chan struct{}) ) @@ -95,28 +85,17 @@ func dispatchLoop() { } } -func dispatch(msg *logMessage, done chan<- struct{}) { +func dispatch(msg message, done chan<- struct{}) { mutex.RLock() for _, sys := range logSystems { - if sys.GetLogLevel() >= msg.LogLevel { - if msg.format { - sys.Printf(msg.msg) - } else { - sys.Println(msg.msg) - } + if sys.GetLogLevel() >= msg.level { + sys.LogPrint(msg.level, msg.msg) } } mutex.RUnlock() done <- struct{}{} } -// send delivers a message to all installed log -// systems. it doesn't wait for the message to be -// written. -func send(msg *logMessage) { - logMessages <- msg -} - // Reset removes all active log systems. func Reset() { mutex.Lock() @@ -147,21 +126,15 @@ type Logger struct { } func NewLogger(tag string) *Logger { - return &Logger{tag} + return &Logger{"[" + tag + "] "} } func (logger *Logger) sendln(level LogLevel, v ...interface{}) { - if logMessages != nil { - msg := newPrintlnLogMessage(level, logger.tag, v...) - send(msg) - } + logMessages <- message{level, logger.tag + fmt.Sprintln(v...)} } func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { - if logMessages != nil { - msg := newPrintfLogMessage(level, logger.tag, format, v...) - send(msg) - } + logMessages <- message{level, logger.tag + fmt.Sprintf(format, v...)} } // Errorln writes a message with ErrorLevel. @@ -240,12 +213,8 @@ type stdLogSystem struct { level uint32 } -func (t *stdLogSystem) Println(v ...interface{}) { - t.logger.Println(v...) -} - -func (t *stdLogSystem) Printf(format string, v ...interface{}) { - t.logger.Printf(format, v...) +func (t *stdLogSystem) LogPrint(level LogLevel, msg string) { + t.logger.Print(msg) } func (t *stdLogSystem) SetLogLevel(i LogLevel) { diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index 23f649312..cf92e3cc6 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -1,7 +1,6 @@ package ethlog import ( - "fmt" "io/ioutil" "math/rand" "os" @@ -16,15 +15,9 @@ type TestLogSystem struct { level LogLevel } -func (ls *TestLogSystem) Println(v ...interface{}) { +func (ls *TestLogSystem) LogPrint(level LogLevel, msg string) { ls.mutex.Lock() - ls.output += fmt.Sprintln(v...) - ls.mutex.Unlock() -} - -func (ls *TestLogSystem) Printf(format string, v ...interface{}) { - ls.mutex.Lock() - ls.output += fmt.Sprintf(format, v...) + ls.output += msg ls.mutex.Unlock() } @@ -54,14 +47,9 @@ type blockedLogSystem struct { unblock chan struct{} } -func (ls blockedLogSystem) Println(v ...interface{}) { - <-ls.unblock - ls.LogSystem.Println(v...) -} - -func (ls blockedLogSystem) Printf(fmt string, v ...interface{}) { +func (ls blockedLogSystem) LogPrint(level LogLevel, msg string) { <-ls.unblock - ls.LogSystem.Printf(fmt, v...) + ls.LogSystem.LogPrint(level, msg) } func TestLoggerFlush(t *testing.T) { -- cgit v1.2.3 From fd9b03a431a9b8bb28a5b681f97e0b2d18ef7a3e Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Thu, 16 Oct 2014 11:50:10 +0200 Subject: ethlog: fix concurrency Rather than spawning a new goroutine for each message, run each log system in a dedicated goroutine. Ensure that logging is still asynchronous by using a per-system buffer (currently 500 messages). If it overflows all logging will hang, but that's better than spawning indefinitely many goroutines. --- ethlog/loggers.go | 98 ++++++++++++++++++++++++++++++++++--------------------- 1 file changed, 60 insertions(+), 38 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index f5ec4d402..732d6a970 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -47,75 +47,97 @@ const ( ) var ( - mutex sync.RWMutex // protects logSystems - logSystems []LogSystem - - logMessages = make(chan message) - drainWaitReq = make(chan chan struct{}) + 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 drainWait []chan struct{} - dispatchDone := make(chan struct{}) - pending := 0 + 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 := <-logMessages: - go dispatch(msg, dispatchDone) - pending++ - case waiter := <-drainWaitReq: - if pending == 0 { - close(waiter) - } else { - drainWait = append(drainWait, waiter) + 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) } - case <-dispatchDone: - pending-- - if pending == 0 { - for _, c := range drainWait { - close(c) - } - drainWait = nil + systemIn = nil + systemWG.Wait() + for _, sys := range systems { + bootSystem(sys) } + close(waiter) } } } -func dispatch(msg message, done chan<- struct{}) { - mutex.RLock() - for _, sys := range logSystems { +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) } } - mutex.RUnlock() - done <- struct{}{} + wg.Done() } // Reset removes all active log systems. +// It blocks until all current messages have been delivered. func Reset() { - mutex.Lock() - logSystems = nil - mutex.Unlock() + 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{}) - drainWaitReq <- waiter + flushC <- waiter <-waiter } // AddLogSystem starts printing messages to the given LogSystem. -func AddLogSystem(logSystem LogSystem) { - mutex.Lock() - logSystems = append(logSystems, logSystem) - mutex.Unlock() +func AddLogSystem(sys LogSystem) { + addSystemC <- sys } // A Logger prints messages prefixed by a given tag. It provides named @@ -130,11 +152,11 @@ func NewLogger(tag string) *Logger { } func (logger *Logger) sendln(level LogLevel, v ...interface{}) { - logMessages <- message{level, logger.tag + fmt.Sprintln(v...)} + logMessageC <- message{level, logger.tag + fmt.Sprintln(v...)} } func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { - logMessages <- message{level, logger.tag + fmt.Sprintf(format, v...)} + logMessageC <- message{level, logger.tag + fmt.Sprintf(format, v...)} } // Errorln writes a message with ErrorLevel. -- cgit v1.2.3 From 35f339e9423bb3f3b5130e954e4a03937971b0ac Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Thu, 16 Oct 2014 12:11:17 +0200 Subject: ethlog: fix typo in documentation --- ethlog/loggers.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index 732d6a970..986bb1759 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -6,7 +6,7 @@ Other packages use tagged logger to send log messages to shared multiple log systems. The log level can be set separately per log system. -Logging is asynchrounous and does not block the caller. Message +Logging is asynchronous and does not block the caller. Message formatting is performed by the caller goroutine to avoid incorrect logging of mutable state. */ -- cgit v1.2.3