From 8e9cc3697944c3e568186a5c23ac729f6eb4a1f4 Mon Sep 17 00:00:00 2001 From: zelig Date: Mon, 23 Jun 2014 12:49:04 +0100 Subject: refactor logging. Details: - 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 - README.md - loggers_test --- ethlog/README.md | 58 ++++++++++++++++ ethlog/loggers.go | 179 +++++++++++++++++++++++++++++++++++++++++++++++++ ethlog/loggers_test.go | 115 +++++++++++++++++++++++++++++++ 3 files changed, 352 insertions(+) create mode 100644 ethlog/README.md create mode 100644 ethlog/loggers.go create mode 100644 ethlog/loggers_test.go (limited to 'ethlog') diff --git a/ethlog/README.md b/ethlog/README.md new file mode 100644 index 000000000..f8818d98e --- /dev/null +++ b/ethlog/README.md @@ -0,0 +1,58 @@ +## 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 + +## Usage + +In an ethereum component package: + + import "github.com/ethereum/eth-go/ethlog" + + // package-wide logger using tag + var logger = ethlog.NewLogger("TAG") + + logger.Infoln("this is info") # > [TAG] This 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 new file mode 100644 index 000000000..e656ffbe5 --- /dev/null +++ b/ethlog/loggers.go @@ -0,0 +1,179 @@ +package ethlog + +import ( + "fmt" + "sync" + "log" + "io" + "os" +) + +type LogSystem interface { + GetLogLevel() LogLevel + SetLogLevel(i LogLevel) + Println(v ...interface{}) + Printf(format string, v ...interface{}) +} + +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...))} +} + +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 drained = true + +type LogLevel uint8 + +const ( + Silence LogLevel = iota + ErrorLevel + WarnLevel + InfoLevel + DebugLevel +) + +// log messages are dispatched to log writers +func start() { + for { + select { + case msg := <- logMessages: + for _, logSystem := range logSystems { + if logSystem.GetLogLevel() >= msg.LogLevel { + msg.send(logSystem) + } + } + default: + drained = true + } + } +} + +// waits until log messages are drained (dispatched to log writers) +func Flush() { + for !drained {} +} + +type Logger struct { + tag string +} + +func NewLogger(tag string) *Logger { + return &Logger{tag} +} + +func AddLogSystem(logSystem LogSystem) { + var mutex = &sync.Mutex{} + mutex.Lock() + defer mutex.Unlock() + if logSystems == nil { + logMessages = make(chan *logMessage) + go start() + } + logSystems = append(logSystems, logSystem) +} + +func (logger *Logger) sendln(level LogLevel, v...interface{}) { + if logMessages != nil { + msg := newPrintlnLogMessage(level, logger.tag, v...) + drained = false + logMessages <- msg + } +} + +func (logger *Logger) sendf(level LogLevel, format string, v...interface{}) { + if logMessages != nil { + msg := newPrintfLogMessage(level, logger.tag, format, v...) + drained = false + logMessages <- msg + } +} + +func (logger *Logger) Errorln(v...interface{}) { + logger.sendln(ErrorLevel, v...) +} + +func (logger *Logger) Warnln(v...interface{}) { + logger.sendln(WarnLevel, v...) +} + +func (logger *Logger) Infoln(v...interface{}) { + logger.sendln(InfoLevel, v...) +} + +func (logger *Logger) Debugln(v...interface{}) { + logger.sendln(DebugLevel, v...) +} + +func (logger *Logger) Errorf(format string, v...interface{}) { + logger.sendf(ErrorLevel, format, v...) +} + +func (logger *Logger) Warnf(format string, v...interface{}) { + logger.sendf(WarnLevel, format, v...) +} + +func (logger *Logger) Infof(format string, v...interface{}) { + logger.sendf(InfoLevel, format, v...) +} + +func (logger *Logger) Debugf(format string, v...interface{}) { + logger.sendf(DebugLevel, format, v...) +} + +func (logger *Logger) Fatalln (v...interface{}) { + logger.sendln(ErrorLevel, v...) + Flush() + os.Exit(0) +} + +func (logger *Logger) Fatalf (format string, v...interface{}) { + logger.sendf(ErrorLevel, format, v...) + Flush() + os.Exit(0) +} + +type StdLogSystem struct { + logger *log.Logger + level LogLevel +} + +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) SetLogLevel(i LogLevel) { + t.level = i +} + +func (t *StdLogSystem) GetLogLevel() LogLevel { + return t.level +} + +func NewStdLogSystem(writer io.Writer, flags int, level LogLevel) *StdLogSystem { + logger := log.New(writer, "", flags) + return &StdLogSystem{logger, level} +} + diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go new file mode 100644 index 000000000..c33082012 --- /dev/null +++ b/ethlog/loggers_test.go @@ -0,0 +1,115 @@ +package ethlog + +import ( + "testing" + "fmt" + "io/ioutil" + "os" +) + +type TestLogSystem struct { + Output string + level LogLevel +} + +func (t *TestLogSystem) Println(v ...interface{}) { + t.Output += fmt.Sprintln(v...) +} + +func (t *TestLogSystem) Printf(format string, v ...interface{}) { + t.Output += fmt.Sprintf(format, v...) +} + +func (t *TestLogSystem) SetLogLevel(i LogLevel) { + t.level = i +} + +func (t *TestLogSystem) GetLogLevel() LogLevel { + return t.level +} + +func quote(s string) string { + return fmt.Sprintf("'%s'", s) +} + +func TestLoggerPrintln(t *testing.T) { + logger := NewLogger("TEST") + testLogSystem := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem) + logger.Errorln("error") + logger.Warnln("warn") + logger.Infoln("info") + logger.Debugln("debug") + Flush() + 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 ", quote(testLogSystem.Output)) + } +} + +func TestLoggerPrintf(t *testing.T) { + logger := NewLogger("TEST") + testLogSystem := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem) + logger.Errorf("error to %v\n", *testLogSystem) + logger.Warnf("warn") + logger.Infof("info") + logger.Debugf("debug") + Flush() + output := testLogSystem.Output + fmt.Println(quote(output)) + if output != "[TEST] error to { 2}\n[TEST] warn" { + t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", quote(testLogSystem.Output)) + } +} + +func TestMultipleLogSystems(t *testing.T) { + logger := NewLogger("TEST") + testLogSystem0 := &TestLogSystem{level: ErrorLevel} + testLogSystem1 := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem0) + AddLogSystem(testLogSystem1) + 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 ", quote(testLogSystem0.Output)) + } + if output1 != "[TEST] error\n[TEST] warn\n" { + t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", quote(testLogSystem1.Output)) + } +} + +func TestFileLogSystem(t *testing.T) { + 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) + fmt.Println(quote(output)) + 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 ", quote(output)) + } else { + os.Remove(filename) + } +} + +func TestNoLogSystem(t *testing.T) { + logger := NewLogger("TEST") + logger.Warnln("warn") + Flush() +} + + + + + + -- cgit v1.2.3 From e75f7ae3301bb66ca6d4e9c099c6a14bbe2be418 Mon Sep 17 00:00:00 2001 From: zelig Date: Wed, 25 Jun 2014 16:37:38 +0100 Subject: implement DebugDetail loglevel and named print methods --- ethlog/loggers.go | 9 +++++++++ 1 file changed, 9 insertions(+) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index e656ffbe5..be42c9fb7 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -49,6 +49,7 @@ const ( WarnLevel InfoLevel DebugLevel + DebugDetailLevel ) // log messages are dispatched to log writers @@ -123,6 +124,10 @@ func (logger *Logger) Debugln(v...interface{}) { logger.sendln(DebugLevel, v...) } +func (logger *Logger) DebugDetailln(v...interface{}) { + logger.sendln(DebugDetailLevel, v...) +} + func (logger *Logger) Errorf(format string, v...interface{}) { logger.sendf(ErrorLevel, format, v...) } @@ -139,6 +144,10 @@ func (logger *Logger) Debugf(format string, v...interface{}) { logger.sendf(DebugLevel, format, v...) } +func (logger *Logger) DebugDetailf(format string, v...interface{}) { + logger.sendf(DebugDetailLevel, format, v...) +} + func (logger *Logger) Fatalln (v...interface{}) { logger.sendln(ErrorLevel, v...) Flush() -- cgit v1.2.3 From 6465e4c3fd21e7002e5870069c51755bd2c66df5 Mon Sep 17 00:00:00 2001 From: zelig Date: Wed, 25 Jun 2014 16:38:42 +0100 Subject: update doc: list levels and show usage of named print methods --- ethlog/README.md | 4 ++++ 1 file changed, 4 insertions(+) (limited to 'ethlog') diff --git a/ethlog/README.md b/ethlog/README.md index f8818d98e..d9b69e106 100644 --- a/ethlog/README.md +++ b/ethlog/README.md @@ -6,6 +6,7 @@ - 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 @@ -16,7 +17,10 @@ In an ethereum component package: // 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 -- cgit v1.2.3 From 853053a3b204ddf4ae935e70e0aa5b5d8994493e Mon Sep 17 00:00:00 2001 From: zelig Date: Thu, 26 Jun 2014 18:45:57 +0100 Subject: go fmt --- ethlog/loggers.go | 202 ++++++++++++++++++++++++------------------------- ethlog/loggers_test.go | 150 ++++++++++++++++++------------------ 2 files changed, 173 insertions(+), 179 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index be42c9fb7..9ebe59096 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -1,188 +1,188 @@ package ethlog import ( - "fmt" - "sync" - "log" - "io" - "os" + "fmt" + "io" + "log" + "os" + "sync" ) type LogSystem interface { - GetLogLevel() LogLevel - SetLogLevel(i LogLevel) - Println(v ...interface{}) - Printf(format string, v ...interface{}) + GetLogLevel() LogLevel + SetLogLevel(i LogLevel) + Println(v ...interface{}) + Printf(format string, v ...interface{}) } type logMessage struct { - LogLevel LogLevel - format bool - msg string + 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 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...))} +func newPrintfLogMessage(level LogLevel, tag string, format string, v ...interface{}) *logMessage { + 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) - } + if msg.format { + logger.Printf(msg.msg) + } else { + logger.Println(msg.msg) + } } -var logMessages chan(*logMessage) -var logSystems []LogSystem +var logMessages chan (*logMessage) +var logSystems []LogSystem var drained = true type LogLevel uint8 const ( - Silence LogLevel = iota - ErrorLevel - WarnLevel - InfoLevel - DebugLevel - DebugDetailLevel + Silence LogLevel = iota + ErrorLevel + WarnLevel + InfoLevel + DebugLevel + DebugDetailLevel ) // log messages are dispatched to log writers func start() { - for { - select { - case msg := <- logMessages: - for _, logSystem := range logSystems { - if logSystem.GetLogLevel() >= msg.LogLevel { - msg.send(logSystem) - } - } - default: - drained = true - } - } + for { + select { + case msg := <-logMessages: + for _, logSystem := range logSystems { + if logSystem.GetLogLevel() >= msg.LogLevel { + msg.send(logSystem) + } + } + default: + drained = true + } + } } // waits until log messages are drained (dispatched to log writers) func Flush() { - for !drained {} + for !drained { + } } type Logger struct { - tag string + tag string } func NewLogger(tag string) *Logger { - return &Logger{tag} + return &Logger{tag} } func AddLogSystem(logSystem LogSystem) { - var mutex = &sync.Mutex{} - mutex.Lock() - defer mutex.Unlock() - if logSystems == nil { - logMessages = make(chan *logMessage) - go start() - } - logSystems = append(logSystems, logSystem) + var mutex = &sync.Mutex{} + mutex.Lock() + defer mutex.Unlock() + if logSystems == nil { + logMessages = make(chan *logMessage) + go start() + } + logSystems = append(logSystems, logSystem) } -func (logger *Logger) sendln(level LogLevel, v...interface{}) { - if logMessages != nil { - msg := newPrintlnLogMessage(level, logger.tag, v...) - drained = false - logMessages <- msg - } +func (logger *Logger) sendln(level LogLevel, v ...interface{}) { + if logMessages != nil { + msg := newPrintlnLogMessage(level, logger.tag, v...) + drained = false + logMessages <- msg + } } -func (logger *Logger) sendf(level LogLevel, format string, v...interface{}) { - if logMessages != nil { - msg := newPrintfLogMessage(level, logger.tag, format, v...) - drained = false - logMessages <- msg - } +func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { + if logMessages != nil { + msg := newPrintfLogMessage(level, logger.tag, format, v...) + drained = false + logMessages <- msg + } } -func (logger *Logger) Errorln(v...interface{}) { - logger.sendln(ErrorLevel, v...) +func (logger *Logger) Errorln(v ...interface{}) { + logger.sendln(ErrorLevel, v...) } -func (logger *Logger) Warnln(v...interface{}) { - logger.sendln(WarnLevel, v...) +func (logger *Logger) Warnln(v ...interface{}) { + logger.sendln(WarnLevel, v...) } -func (logger *Logger) Infoln(v...interface{}) { - logger.sendln(InfoLevel, v...) +func (logger *Logger) Infoln(v ...interface{}) { + logger.sendln(InfoLevel, v...) } -func (logger *Logger) Debugln(v...interface{}) { - logger.sendln(DebugLevel, v...) +func (logger *Logger) Debugln(v ...interface{}) { + logger.sendln(DebugLevel, v...) } -func (logger *Logger) DebugDetailln(v...interface{}) { - logger.sendln(DebugDetailLevel, v...) +func (logger *Logger) DebugDetailln(v ...interface{}) { + logger.sendln(DebugDetailLevel, v...) } -func (logger *Logger) Errorf(format string, v...interface{}) { - logger.sendf(ErrorLevel, format, v...) +func (logger *Logger) Errorf(format string, v ...interface{}) { + logger.sendf(ErrorLevel, format, v...) } -func (logger *Logger) Warnf(format string, v...interface{}) { - logger.sendf(WarnLevel, format, v...) +func (logger *Logger) Warnf(format string, v ...interface{}) { + logger.sendf(WarnLevel, format, v...) } -func (logger *Logger) Infof(format string, v...interface{}) { - logger.sendf(InfoLevel, format, v...) +func (logger *Logger) Infof(format string, v ...interface{}) { + logger.sendf(InfoLevel, format, v...) } -func (logger *Logger) Debugf(format string, v...interface{}) { - logger.sendf(DebugLevel, format, v...) +func (logger *Logger) Debugf(format string, v ...interface{}) { + logger.sendf(DebugLevel, format, v...) } -func (logger *Logger) DebugDetailf(format string, v...interface{}) { - logger.sendf(DebugDetailLevel, format, v...) +func (logger *Logger) DebugDetailf(format string, v ...interface{}) { + logger.sendf(DebugDetailLevel, format, v...) } -func (logger *Logger) Fatalln (v...interface{}) { - logger.sendln(ErrorLevel, v...) - Flush() - os.Exit(0) +func (logger *Logger) Fatalln(v ...interface{}) { + logger.sendln(ErrorLevel, v...) + Flush() + os.Exit(0) } -func (logger *Logger) Fatalf (format string, v...interface{}) { - logger.sendf(ErrorLevel, format, v...) - Flush() - os.Exit(0) +func (logger *Logger) Fatalf(format string, v ...interface{}) { + logger.sendf(ErrorLevel, format, v...) + Flush() + os.Exit(0) } type StdLogSystem struct { - logger *log.Logger - level LogLevel + logger *log.Logger + level LogLevel } func (t *StdLogSystem) Println(v ...interface{}) { - t.logger.Println(v...) + t.logger.Println(v...) } func (t *StdLogSystem) Printf(format string, v ...interface{}) { - t.logger.Printf(format, v...) + t.logger.Printf(format, v...) } func (t *StdLogSystem) SetLogLevel(i LogLevel) { - t.level = i + t.level = i } func (t *StdLogSystem) GetLogLevel() LogLevel { - return t.level + return t.level } func NewStdLogSystem(writer io.Writer, flags int, level LogLevel) *StdLogSystem { - logger := log.New(writer, "", flags) - return &StdLogSystem{logger, level} + logger := log.New(writer, "", flags) + return &StdLogSystem{logger, level} } - diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index c33082012..89f416681 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -1,115 +1,109 @@ package ethlog import ( - "testing" - "fmt" - "io/ioutil" - "os" + "fmt" + "io/ioutil" + "os" + "testing" ) type TestLogSystem struct { - Output string - level LogLevel + Output string + level LogLevel } func (t *TestLogSystem) Println(v ...interface{}) { - t.Output += fmt.Sprintln(v...) + t.Output += fmt.Sprintln(v...) } func (t *TestLogSystem) Printf(format string, v ...interface{}) { - t.Output += fmt.Sprintf(format, v...) + t.Output += fmt.Sprintf(format, v...) } func (t *TestLogSystem) SetLogLevel(i LogLevel) { - t.level = i + t.level = i } func (t *TestLogSystem) GetLogLevel() LogLevel { - return t.level + return t.level } func quote(s string) string { - return fmt.Sprintf("'%s'", s) + return fmt.Sprintf("'%s'", s) } func TestLoggerPrintln(t *testing.T) { - logger := NewLogger("TEST") - testLogSystem := &TestLogSystem{level: WarnLevel} - AddLogSystem(testLogSystem) - logger.Errorln("error") - logger.Warnln("warn") - logger.Infoln("info") - logger.Debugln("debug") - Flush() - 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 ", quote(testLogSystem.Output)) - } + logger := NewLogger("TEST") + testLogSystem := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem) + logger.Errorln("error") + logger.Warnln("warn") + logger.Infoln("info") + logger.Debugln("debug") + Flush() + 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 ", quote(testLogSystem.Output)) + } } func TestLoggerPrintf(t *testing.T) { - logger := NewLogger("TEST") - testLogSystem := &TestLogSystem{level: WarnLevel} - AddLogSystem(testLogSystem) - logger.Errorf("error to %v\n", *testLogSystem) - logger.Warnf("warn") - logger.Infof("info") - logger.Debugf("debug") - Flush() - output := testLogSystem.Output - fmt.Println(quote(output)) - if output != "[TEST] error to { 2}\n[TEST] warn" { - t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", quote(testLogSystem.Output)) - } + logger := NewLogger("TEST") + testLogSystem := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem) + logger.Errorf("error to %v\n", *testLogSystem) + logger.Warnf("warn") + logger.Infof("info") + logger.Debugf("debug") + Flush() + output := testLogSystem.Output + fmt.Println(quote(output)) + if output != "[TEST] error to { 2}\n[TEST] warn" { + t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", quote(testLogSystem.Output)) + } } func TestMultipleLogSystems(t *testing.T) { - logger := NewLogger("TEST") - testLogSystem0 := &TestLogSystem{level: ErrorLevel} - testLogSystem1 := &TestLogSystem{level: WarnLevel} - AddLogSystem(testLogSystem0) - AddLogSystem(testLogSystem1) - 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 ", quote(testLogSystem0.Output)) - } - if output1 != "[TEST] error\n[TEST] warn\n" { - t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", quote(testLogSystem1.Output)) - } + logger := NewLogger("TEST") + testLogSystem0 := &TestLogSystem{level: ErrorLevel} + testLogSystem1 := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem0) + AddLogSystem(testLogSystem1) + 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 ", quote(testLogSystem0.Output)) + } + if output1 != "[TEST] error\n[TEST] warn\n" { + t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", quote(testLogSystem1.Output)) + } } func TestFileLogSystem(t *testing.T) { - 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) - fmt.Println(quote(output)) - 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 ", quote(output)) - } else { - os.Remove(filename) - } + 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) + fmt.Println(quote(output)) + 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 ", quote(output)) + } else { + os.Remove(filename) + } } func TestNoLogSystem(t *testing.T) { - logger := NewLogger("TEST") - logger.Warnln("warn") - Flush() + logger := NewLogger("TEST") + logger.Warnln("warn") + Flush() } - - - - - - -- cgit v1.2.3 From 329887df993aefc8799cf64ed20cf1dcc8cfb6ed Mon Sep 17 00:00:00 2001 From: obscuren Date: Sat, 5 Jul 2014 13:24:26 +0200 Subject: Fixed crazy looping --- ethlog/loggers.go | 20 ++++++++++++++------ 1 file changed, 14 insertions(+), 6 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index 9ebe59096..219c78240 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -39,7 +39,7 @@ func (msg *logMessage) send(logger LogSystem) { var logMessages chan (*logMessage) var logSystems []LogSystem -var drained = true +var quit chan bool type LogLevel uint8 @@ -54,6 +54,7 @@ const ( // log messages are dispatched to log writers func start() { +out: for { select { case msg := <-logMessages: @@ -62,15 +63,23 @@ func start() { msg.send(logSystem) } } - default: - drained = true + case <-quit: + break out } } } // waits until log messages are drained (dispatched to log writers) func Flush() { - for !drained { + quit <- true + +done: + for { + select { + case <-logMessages: + default: + break done + } } } @@ -88,6 +97,7 @@ func AddLogSystem(logSystem LogSystem) { defer mutex.Unlock() if logSystems == nil { logMessages = make(chan *logMessage) + quit = make(chan bool) go start() } logSystems = append(logSystems, logSystem) @@ -96,7 +106,6 @@ func AddLogSystem(logSystem LogSystem) { func (logger *Logger) sendln(level LogLevel, v ...interface{}) { if logMessages != nil { msg := newPrintlnLogMessage(level, logger.tag, v...) - drained = false logMessages <- msg } } @@ -104,7 +113,6 @@ func (logger *Logger) sendln(level LogLevel, v ...interface{}) { func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { if logMessages != nil { msg := newPrintfLogMessage(level, logger.tag, format, v...) - drained = false logMessages <- msg } } -- cgit v1.2.3 From d4300c406c5f98d35857b6e53b0427be5f45e3b2 Mon Sep 17 00:00:00 2001 From: zelig Date: Sat, 5 Jul 2014 18:36:22 +0100 Subject: logger fix - introduce quit, drained, shutdown channels - mainLoop falls through reading message channel to drained state, and waits is blocked in default branch until any message is sent - Flush() waits for <-drained - Stop() pushes quit and nodges mainloop out of blocking drained state - package-global mutex - Reset() - clear tests --- ethlog/loggers.go | 57 ++++++++++++++++++++++++++++++++++---------------- ethlog/loggers_test.go | 23 ++++++++++---------- 2 files changed, 50 insertions(+), 30 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index 219c78240..d7707cf9e 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -40,6 +40,9 @@ func (msg *logMessage) send(logger LogSystem) { var logMessages chan (*logMessage) var logSystems []LogSystem var quit chan bool +var drained chan bool +var shutdown chan bool +var mutex = sync.Mutex{} type LogLevel uint8 @@ -57,29 +60,41 @@ func start() { out: for { select { + case <-quit: + break out case msg := <-logMessages: for _, logSystem := range logSystems { if logSystem.GetLogLevel() >= msg.LogLevel { msg.send(logSystem) } } - case <-quit: - break out + case drained <- true: + default: + drained <- true // this blocks until a message is sent to the queu } } + close(shutdown) } -// waits until log messages are drained (dispatched to log writers) -func Flush() { - quit <- true - -done: - for { +func Reset() { + mutex.Lock() + defer mutex.Unlock() + if logSystems != nil { + quit <- true select { - case <-logMessages: - default: - break done + case <-drained: } + <-shutdown + } + logSystems = nil +} + +// waits until log messages are drained (dispatched to log writers) +func Flush() { + mutex.Lock() + defer mutex.Unlock() + if logSystems != nil { + <-drained } } @@ -92,28 +107,34 @@ 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) quit = make(chan bool) + drained = make(chan bool, 1) + shutdown = make(chan bool, 1) go start() } logSystems = append(logSystems, logSystem) } +func send(msg *logMessage) { + select { + case <-drained: + } + logMessages <- msg +} + func (logger *Logger) sendln(level LogLevel, v ...interface{}) { - if logMessages != nil { - msg := newPrintlnLogMessage(level, logger.tag, v...) - logMessages <- msg + if logSystems != nil { + send(newPrintlnLogMessage(level, logger.tag, v...)) } } func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { - if logMessages != nil { - msg := newPrintfLogMessage(level, logger.tag, format, v...) - logMessages <- msg + if logSystems != nil { + send(newPrintfLogMessage(level, logger.tag, format, v...)) } } diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index 89f416681..9fff471c1 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -28,10 +28,6 @@ func (t *TestLogSystem) GetLogLevel() LogLevel { return t.level } -func quote(s string) string { - return fmt.Sprintf("'%s'", s) -} - func TestLoggerPrintln(t *testing.T) { logger := NewLogger("TEST") testLogSystem := &TestLogSystem{level: WarnLevel} @@ -41,10 +37,10 @@ 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 ", quote(testLogSystem.Output)) + t.Error("Expected logger output '[TEST] error\\n[TEST] warn\\n', got ", testLogSystem.Output) } } @@ -57,10 +53,10 @@ func TestLoggerPrintf(t *testing.T) { logger.Infof("info") logger.Debugf("debug") Flush() + Reset() output := testLogSystem.Output - fmt.Println(quote(output)) if output != "[TEST] error to { 2}\n[TEST] warn" { - t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", quote(testLogSystem.Output)) + t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", testLogSystem.Output) } } @@ -73,13 +69,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 ", quote(testLogSystem0.Output)) + t.Error("Expected logger 0 output '[TEST] error\\n', got ", testLogSystem0.Output) } if output1 != "[TEST] error\n[TEST] warn\n" { - t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", quote(testLogSystem1.Output)) + t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", testLogSystem1.Output) } } @@ -92,11 +89,11 @@ func TestFileLogSystem(t *testing.T) { logger.Errorf("error to %s\n", filename) logger.Warnln("warn") Flush() + Reset() contents, _ := ioutil.ReadFile(filename) output := string(contents) - fmt.Println(quote(output)) 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 ", quote(output)) + t.Error("Expected contents of file 'test.log': '[TEST] error to test.log\\n[TEST] warn\\n', got ", output) } else { os.Remove(filename) } @@ -105,5 +102,7 @@ func TestFileLogSystem(t *testing.T) { func TestNoLogSystem(t *testing.T) { logger := NewLogger("TEST") logger.Warnln("warn") + fmt.Println("1") Flush() + Reset() } -- cgit v1.2.3 From 6fe9b4ab5e839be96eb1c4a619bc14fab622d8d1 Mon Sep 17 00:00:00 2001 From: Jeffrey Wilcke Date: Mon, 7 Jul 2014 10:59:16 +0200 Subject: Revert "ethreact - Feature/ethutil refactor" --- ethlog/loggers.go | 57 ++++++++++++++++---------------------------------- ethlog/loggers_test.go | 23 ++++++++++---------- 2 files changed, 30 insertions(+), 50 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index d7707cf9e..219c78240 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -40,9 +40,6 @@ func (msg *logMessage) send(logger LogSystem) { var logMessages chan (*logMessage) var logSystems []LogSystem var quit chan bool -var drained chan bool -var shutdown chan bool -var mutex = sync.Mutex{} type LogLevel uint8 @@ -60,41 +57,29 @@ func start() { out: for { select { - case <-quit: - break out case msg := <-logMessages: for _, logSystem := range logSystems { if logSystem.GetLogLevel() >= msg.LogLevel { msg.send(logSystem) } } - case drained <- true: - default: - drained <- true // this blocks until a message is sent to the queu - } - } - close(shutdown) -} - -func Reset() { - mutex.Lock() - defer mutex.Unlock() - if logSystems != nil { - quit <- true - select { - case <-drained: + case <-quit: + break out } - <-shutdown } - logSystems = nil } // waits until log messages are drained (dispatched to log writers) func Flush() { - mutex.Lock() - defer mutex.Unlock() - if logSystems != nil { - <-drained + quit <- true + +done: + for { + select { + case <-logMessages: + default: + break done + } } } @@ -107,34 +92,28 @@ 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) quit = make(chan bool) - drained = make(chan bool, 1) - shutdown = make(chan bool, 1) go start() } logSystems = append(logSystems, logSystem) } -func send(msg *logMessage) { - select { - case <-drained: - } - logMessages <- msg -} - func (logger *Logger) sendln(level LogLevel, v ...interface{}) { - if logSystems != nil { - send(newPrintlnLogMessage(level, logger.tag, v...)) + if logMessages != nil { + msg := newPrintlnLogMessage(level, logger.tag, v...) + logMessages <- msg } } func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { - if logSystems != nil { - send(newPrintfLogMessage(level, logger.tag, format, v...)) + if logMessages != nil { + msg := newPrintfLogMessage(level, logger.tag, format, v...) + logMessages <- msg } } diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index 9fff471c1..89f416681 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -28,6 +28,10 @@ func (t *TestLogSystem) GetLogLevel() LogLevel { return t.level } +func quote(s string) string { + return fmt.Sprintf("'%s'", s) +} + func TestLoggerPrintln(t *testing.T) { logger := NewLogger("TEST") testLogSystem := &TestLogSystem{level: WarnLevel} @@ -37,10 +41,10 @@ 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 ", testLogSystem.Output) + t.Error("Expected logger output '[TEST] error\\n[TEST] warn\\n', got ", quote(testLogSystem.Output)) } } @@ -53,10 +57,10 @@ func TestLoggerPrintf(t *testing.T) { logger.Infof("info") logger.Debugf("debug") Flush() - Reset() output := testLogSystem.Output + fmt.Println(quote(output)) if output != "[TEST] error to { 2}\n[TEST] warn" { - t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", testLogSystem.Output) + t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", quote(testLogSystem.Output)) } } @@ -69,14 +73,13 @@ 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 ", testLogSystem0.Output) + t.Error("Expected logger 0 output '[TEST] error\\n', got ", quote(testLogSystem0.Output)) } if output1 != "[TEST] error\n[TEST] warn\n" { - t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", testLogSystem1.Output) + t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", quote(testLogSystem1.Output)) } } @@ -89,11 +92,11 @@ func TestFileLogSystem(t *testing.T) { logger.Errorf("error to %s\n", filename) logger.Warnln("warn") Flush() - Reset() contents, _ := ioutil.ReadFile(filename) output := string(contents) + fmt.Println(quote(output)) 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) + t.Error("Expected contents of file 'test.log': '[TEST] error to test.log\\n[TEST] warn\\n', got ", quote(output)) } else { os.Remove(filename) } @@ -102,7 +105,5 @@ func TestFileLogSystem(t *testing.T) { func TestNoLogSystem(t *testing.T) { logger := NewLogger("TEST") logger.Warnln("warn") - fmt.Println("1") Flush() - Reset() } -- cgit v1.2.3 From e4e704f48074161a175cc125c5fabdf94c095ca8 Mon Sep 17 00:00:00 2001 From: obscuren Date: Mon, 7 Jul 2014 16:05:59 +0200 Subject: Fix quit --- 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 219c78240..ec481edd8 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -97,7 +97,7 @@ func AddLogSystem(logSystem LogSystem) { defer mutex.Unlock() if logSystems == nil { logMessages = make(chan *logMessage) - quit = make(chan bool) + quit = make(chan bool, 1) go start() } logSystems = append(logSystems, logSystem) -- cgit v1.2.3 From 5c03adbdededd31cb73f64ced01e33154347e193 Mon Sep 17 00:00:00 2001 From: zelig Date: Mon, 14 Jul 2014 18:37:01 +0100 Subject: fix logger channel blocking --- ethlog/loggers.go | 55 +++++++++++++++++++++++++------------------------- ethlog/loggers_test.go | 15 ++++++++++++++ 2 files changed, 43 insertions(+), 27 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index d7707cf9e..4e950cadd 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -39,9 +39,8 @@ func (msg *logMessage) send(logger LogSystem) { var logMessages chan (*logMessage) var logSystems []LogSystem -var quit chan bool +var quit chan chan error var drained chan bool -var shutdown chan bool var mutex = sync.Mutex{} type LogLevel uint8 @@ -55,44 +54,54 @@ const ( DebugDetailLevel ) +func dispatch(msg *logMessage) { + for _, logSystem := range logSystems { + if logSystem.GetLogLevel() >= msg.LogLevel { + msg.send(logSystem) + } + } +} + // log messages are dispatched to log writers func start() { -out: for { select { - case <-quit: - break out + case status := <-quit: + status <- nil + return case msg := <-logMessages: - for _, logSystem := range logSystems { - if logSystem.GetLogLevel() >= msg.LogLevel { - msg.send(logSystem) - } - } - case drained <- true: + dispatch(msg) default: - drained <- true // this blocks until a message is sent to the queu + drained <- true // this blocks until a message is sent to the queue } } - close(shutdown) +} + +func send(msg *logMessage) { + logMessages <- msg + select { + case <-drained: + default: + } } func Reset() { mutex.Lock() defer mutex.Unlock() if logSystems != nil { - quit <- true + status := make(chan error) + quit <- status select { case <-drained: + default: } - <-shutdown + <-status } logSystems = nil } // waits until log messages are drained (dispatched to log writers) func Flush() { - mutex.Lock() - defer mutex.Unlock() if logSystems != nil { <-drained } @@ -110,22 +119,14 @@ func AddLogSystem(logSystem LogSystem) { mutex.Lock() defer mutex.Unlock() if logSystems == nil { - logMessages = make(chan *logMessage) - quit = make(chan bool) + logMessages = make(chan *logMessage, 5) + quit = make(chan chan error, 1) drained = make(chan bool, 1) - shutdown = make(chan bool, 1) go start() } logSystems = append(logSystems, logSystem) } -func send(msg *logMessage) { - select { - case <-drained: - } - logMessages <- msg -} - func (logger *Logger) sendln(level LogLevel, v ...interface{}) { if logSystems != nil { send(newPrintlnLogMessage(level, logger.tag, v...)) diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go index 9fff471c1..0e1c12e55 100644 --- a/ethlog/loggers_test.go +++ b/ethlog/loggers_test.go @@ -28,6 +28,21 @@ func (t *TestLogSystem) GetLogLevel() LogLevel { return t.level } +func TestLoggerFlush(t *testing.T) { + logger := NewLogger("TEST") + testLogSystem := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem) + for i := 0; i < 5; i++ { + 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) + } +} + func TestLoggerPrintln(t *testing.T) { logger := NewLogger("TEST") testLogSystem := &TestLogSystem{level: WarnLevel} -- cgit v1.2.3 From d1c89727dcf10c87bd1df68da9508cec047c56cf Mon Sep 17 00:00:00 2001 From: zelig Date: Mon, 14 Jul 2014 19:02:34 +0100 Subject: fix send overwritten by merge --- ethlog/loggers.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'ethlog') diff --git a/ethlog/loggers.go b/ethlog/loggers.go index f13186102..59021d169 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -130,14 +130,14 @@ func AddLogSystem(logSystem LogSystem) { func (logger *Logger) sendln(level LogLevel, v ...interface{}) { if logMessages != nil { msg := newPrintlnLogMessage(level, logger.tag, v...) - logMessages <- msg + send(msg) } } func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { if logMessages != nil { msg := newPrintfLogMessage(level, logger.tag, format, v...) - logMessages <- msg + send(msg) } } -- cgit v1.2.3 From 2762ec22d0693b406ead2f0c07b62e9b66d395e4 Mon Sep 17 00:00:00 2001 From: obscuren Date: Fri, 18 Jul 2014 13:50:15 +0200 Subject: Fixed miner and logger --- 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 ec481edd8..50de213b3 100644 --- a/ethlog/loggers.go +++ b/ethlog/loggers.go @@ -96,7 +96,7 @@ func AddLogSystem(logSystem LogSystem) { mutex.Lock() defer mutex.Unlock() if logSystems == nil { - logMessages = make(chan *logMessage) + logMessages = make(chan *logMessage, 10) quit = make(chan bool, 1) go start() } -- cgit v1.2.3 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