diff --git a/.gitignore b/.gitignore index f37225baa..62f28681c 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,2 @@ -*.swp -*.swo vendor +.glide diff --git a/Makefile b/Makefile index cd1a57346..8e43dd11a 100644 --- a/Makefile +++ b/Makefile @@ -1,10 +1,10 @@ -.PHONY: all test install get_vendor_deps ensure_tools +.PHONY: all test get_vendor_deps ensure_tools GOTOOLS = \ github.com/Masterminds/glide REPO:=github.com/tendermint/tmlibs -all: install test +all: test test: go test `glide novendor` @@ -16,5 +16,3 @@ get_vendor_deps: ensure_tools ensure_tools: go get $(GOTOOLS) - - diff --git a/common/service.go b/common/service.go index 6a274a798..71fc03cb9 100644 --- a/common/service.go +++ b/common/service.go @@ -3,7 +3,7 @@ package common import ( "sync/atomic" - "github.com/tendermint/log15" + "github.com/tendermint/tmlibs/log" ) type Service interface { @@ -19,6 +19,8 @@ type Service interface { IsRunning() bool String() string + + SetLogger(log.Logger) } /* @@ -64,7 +66,7 @@ Typical usage: } */ type BaseService struct { - log log15.Logger + Logger log.Logger name string started uint32 // atomic stopped uint32 // atomic @@ -74,27 +76,31 @@ type BaseService struct { impl Service } -func NewBaseService(log log15.Logger, name string, impl Service) *BaseService { +func NewBaseService(logger log.Logger, name string, impl Service) *BaseService { + if logger == nil { + logger = log.NewNopLogger() + } + return &BaseService{ - log: log, - name: name, - Quit: make(chan struct{}), - impl: impl, + Logger: logger, + name: name, + Quit: make(chan struct{}), + impl: impl, } } +func (bs *BaseService) SetLogger(l log.Logger) { + bs.Logger = l +} + // Implements Servce func (bs *BaseService) Start() (bool, error) { if atomic.CompareAndSwapUint32(&bs.started, 0, 1) { if atomic.LoadUint32(&bs.stopped) == 1 { - if bs.log != nil { - bs.log.Warn(Fmt("Not starting %v -- already stopped", bs.name), "impl", bs.impl) - } + bs.Logger.Error(Fmt("Not starting %v -- already stopped", bs.name), "impl", bs.impl) return false, nil } else { - if bs.log != nil { - bs.log.Info(Fmt("Starting %v", bs.name), "impl", bs.impl) - } + bs.Logger.Info(Fmt("Starting %v", bs.name), "impl", bs.impl) } err := bs.impl.OnStart() if err != nil { @@ -104,9 +110,7 @@ func (bs *BaseService) Start() (bool, error) { } return true, err } else { - if bs.log != nil { - bs.log.Debug(Fmt("Not starting %v -- already started", bs.name), "impl", bs.impl) - } + bs.Logger.Debug(Fmt("Not starting %v -- already started", bs.name), "impl", bs.impl) return false, nil } } @@ -119,16 +123,12 @@ func (bs *BaseService) OnStart() error { return nil } // Implements Service func (bs *BaseService) Stop() bool { if atomic.CompareAndSwapUint32(&bs.stopped, 0, 1) { - if bs.log != nil { - bs.log.Info(Fmt("Stopping %v", bs.name), "impl", bs.impl) - } + bs.Logger.Info(Fmt("Stopping %v", bs.name), "impl", bs.impl) bs.impl.OnStop() close(bs.Quit) return true } else { - if bs.log != nil { - bs.log.Debug(Fmt("Stopping %v (ignoring: already stopped)", bs.name), "impl", bs.impl) - } + bs.Logger.Debug(Fmt("Stopping %v (ignoring: already stopped)", bs.name), "impl", bs.impl) return false } } @@ -147,9 +147,7 @@ func (bs *BaseService) Reset() (bool, error) { bs.Quit = make(chan struct{}) return true, bs.impl.OnReset() } else { - if bs.log != nil { - bs.log.Debug(Fmt("Can't reset %v. Not stopped", bs.name), "impl", bs.impl) - } + bs.Logger.Debug(Fmt("Can't reset %v. Not stopped", bs.name), "impl", bs.impl) return false, nil } // never happens @@ -182,11 +180,11 @@ type QuitService struct { BaseService } -func NewQuitService(log log15.Logger, name string, impl Service) *QuitService { - if log != nil { - log.Warn("QuitService is deprecated, use BaseService instead") +func NewQuitService(logger log.Logger, name string, impl Service) *QuitService { + if logger != nil { + logger.Info("QuitService is deprecated, use BaseService instead") } return &QuitService{ - BaseService: *NewBaseService(log, name, impl), + BaseService: *NewBaseService(logger, name, impl), } } diff --git a/events/events.go b/events/events.go index 487d120b3..12aa07813 100644 --- a/events/events.go +++ b/events/events.go @@ -45,7 +45,7 @@ type eventSwitch struct { func NewEventSwitch() EventSwitch { evsw := &eventSwitch{} - evsw.BaseService = *NewBaseService(log, "EventSwitch", evsw) + evsw.BaseService = *NewBaseService(nil, "EventSwitch", evsw) return evsw } diff --git a/events/log.go b/events/log.go deleted file mode 100644 index adb6bab09..000000000 --- a/events/log.go +++ /dev/null @@ -1,7 +0,0 @@ -package events - -import ( - "github.com/tendermint/tmlibs/logger" -) - -var log = logger.New("module", "events") diff --git a/glide.lock b/glide.lock index b7d4fb8ff..b30f538a3 100644 --- a/glide.lock +++ b/glide.lock @@ -1,5 +1,5 @@ -hash: a28817fffc1bfbba980a957b7782a84ea574fb73d5dfb01730f7e304c9dee630 -updated: 2017-05-03T10:27:41.060683376+02:00 +hash: 69359a39dbb6957c9f09167520317ad72d4bfa75f37a614b347e2510768c8a42 +updated: 2017-05-05T17:46:34.975369143Z imports: - name: github.com/fsnotify/fsnotify version: 4da3e2cfbabc9f751898f250b49f2439785783a1 @@ -12,11 +12,11 @@ imports: - name: github.com/go-logfmt/logfmt version: 390ab7935ee28ec6b286364bba9b4dd6410cb3d5 - name: github.com/go-stack/stack - version: 100eb0c0a9c5b306ca2fb4f165df21d80ada4b82 + version: 7a2f19628aabfe68f0766b59e74d6315f8347d22 - name: github.com/golang/snappy version: 553a641470496b2327abcac10b36396bd98e45c9 - name: github.com/hashicorp/hcl - version: 630949a3c5fa3c613328e1b8256052cbc2327c9b + version: a4b07c25de5ff55ad3b8936cea69a79a3d95a855 subpackages: - hcl/ast - hcl/parser @@ -35,17 +35,17 @@ imports: - name: github.com/magiconair/properties version: 51463bfca2576e06c62a8504b5c0f06d61312647 - name: github.com/mattn/go-colorable - version: d228849504861217f796da67fae4f6e347643f15 + version: ded68f7a9561c023e790de24279db7ebf473ea80 - name: github.com/mattn/go-isatty - version: 30a891c33c7cde7b02a981314b4228ec99380cca + version: fc9e8d8ef48496124e79ae0df75490096eccf6fe - name: github.com/mitchellh/mapstructure - version: 53818660ed4955e899c0bcafa97299a388bd7c8e + version: cc8532a8e9a55ea36402aa21efdf403a60d34096 - name: github.com/pelletier/go-buffruneio version: c37440a7cf42ac63b919c752ca73a85067e05992 - name: github.com/pelletier/go-toml - version: 13d49d4606eb801b8f01ae542b4afc4c6ee3d84a + version: 97253b98df84f9eef872866d079e74b8265150f1 - name: github.com/pkg/errors - version: bfd5150e4e41705ded2129ec33379de1cb90b513 + version: c605e284fe17294bda444b34710735b29d1a9d90 - name: github.com/spf13/afero version: 9be650865eab0c12963d8753212f4f9c66cdcf12 subpackages: @@ -53,15 +53,15 @@ imports: - name: github.com/spf13/cast version: acbeb36b902d72a7a4c18e8f3241075e7ab763e4 - name: github.com/spf13/cobra - version: fcd0c5a1df88f5d6784cb4feead962c3f3d0b66c + version: db6b9a8b3f3f400c8ecb4a4d7d02245b8facad66 - name: github.com/spf13/jwalterweatherman version: fa7ca7e836cf3a8bb4ebf799f472c12d7e903d66 - name: github.com/spf13/pflag - version: 9ff6c6923cfffbcd502984b8e0c80539a94968b7 + version: 80fe0fb4eba54167e2ccae1c6c950e72abf61b73 - name: github.com/spf13/viper - version: 5d46e70da8c0b6f812e0b170b7a985753b5c63cb + version: 0967fc9aceab2ce9da34061253ac10fb99bba5b2 - name: github.com/syndtr/goleveldb - version: 23851d93a2292dcc56e71a18ec9e0624d84a0f65 + version: 8c81ea47d4c41a385645e133e15510fc6a2a74b4 subpackages: - leveldb - leveldb/cache @@ -76,24 +76,24 @@ imports: - leveldb/table - leveldb/util - name: github.com/tendermint/go-wire - version: 334005c236d19c632fb5f073f9de3b0fab6a522b + version: b53add0b622662731985485f3a19be7f684660b8 subpackages: - data - data/base58 - name: github.com/tendermint/log15 - version: ae0f3d6450da9eac7074b439c8e1c3cabf0d5ce6 + version: f91285dece9f4875421b481da3e613d83d44f29b subpackages: - term - name: golang.org/x/crypto - version: 7c6cc321c680f03b9ef0764448e780704f486b51 + version: 5a033cc77e57eca05bdb50522851d29e03569cbe subpackages: - ripemd160 - name: golang.org/x/sys - version: d75a52659825e75fff6158388dddc6a5b04f9ba5 + version: 9ccfe848b9db8435a24c424abbc07a921adf1df5 subpackages: - unix - name: golang.org/x/text - version: f4b4367115ec2de254587813edaa901bc1c723a8 + version: 470f45bf29f4147d6fbd7dfd0a02a848e49f5bf4 subpackages: - transform - unicode/norm @@ -101,7 +101,7 @@ imports: version: cd8b52f8269e0feb286dfeef29f8fe4d5b397e0b testImports: - name: github.com/davecgh/go-spew - version: 6d212800a42e8ab5c146b8ace3490ee17e5225f9 + version: 04cdfd42973bb9c8589fd6a731800cf222fde1a9 subpackages: - spew - name: github.com/pmezard/go-difflib @@ -109,7 +109,7 @@ testImports: subpackages: - difflib - name: github.com/stretchr/testify - version: 69483b4bd14f5845b5a1e55bca19e954e827f1d0 + version: 4d4bfba8f1d1027c4fdbe371823030df51419987 subpackages: - assert - require diff --git a/glide.yaml b/glide.yaml index f9e8f29b1..d8bdd5872 100644 --- a/glide.yaml +++ b/glide.yaml @@ -1,19 +1,28 @@ package: github.com/tendermint/tmlibs import: +- package: github.com/go-kit/kit + subpackages: + - log + - log/level + - log/term +- package: github.com/go-logfmt/logfmt - package: github.com/jmhodges/levigo +- package: github.com/pkg/errors +- package: github.com/spf13/cobra +- package: github.com/spf13/viper - package: github.com/syndtr/goleveldb subpackages: - leveldb - leveldb/errors - leveldb/opt - package: github.com/tendermint/go-wire + subpackages: + - data + - data/base58 - package: github.com/tendermint/log15 - package: golang.org/x/crypto subpackages: - ripemd160 -- package: github.com/go-logfmt/logfmt -- package: github.com/spf13/cobra -- package: github.com/spf13/viper testImport: - package: github.com/stretchr/testify version: ^1.1.4 diff --git a/log/filter.go b/log/filter.go new file mode 100644 index 000000000..102e2d900 --- /dev/null +++ b/log/filter.go @@ -0,0 +1,97 @@ +package log + +// NewFilter wraps next and implements filtering. See the commentary on the +// Option functions for a detailed description of how to configure levels. If +// no options are provided, all leveled log events created with Debug, Info or +// Error helper methods are squelched. +func NewFilter(next Logger, options ...Option) Logger { + l := &filter{ + next: next, + } + for _, option := range options { + option(l) + } + return l +} + +type filter struct { + next Logger + allowed level + errNotAllowed error +} + +func (l *filter) Info(msg string, keyvals ...interface{}) error { + levelAllowed := l.allowed&levelInfo != 0 + if !levelAllowed { + return l.errNotAllowed + } + return l.next.Info(msg, keyvals...) +} + +func (l *filter) Debug(msg string, keyvals ...interface{}) error { + levelAllowed := l.allowed&levelDebug != 0 + if !levelAllowed { + return l.errNotAllowed + } + return l.next.Debug(msg, keyvals...) +} + +func (l *filter) Error(msg string, keyvals ...interface{}) error { + levelAllowed := l.allowed&levelError != 0 + if !levelAllowed { + return l.errNotAllowed + } + return l.next.Error(msg, keyvals...) +} + +func (l *filter) With(keyvals ...interface{}) Logger { + return l.next.With(keyvals...) +} + +// Option sets a parameter for the filter. +type Option func(*filter) + +// AllowAll is an alias for AllowDebug. +func AllowAll() Option { + return AllowDebug() +} + +// AllowDebug allows error, info and debug level log events to pass. +func AllowDebug() Option { + return allowed(levelError | levelInfo | levelDebug) +} + +// AllowInfo allows error and info level log events to pass. +func AllowInfo() Option { + return allowed(levelError | levelInfo) +} + +// AllowError allows only error level log events to pass. +func AllowError() Option { + return allowed(levelError) +} + +// AllowNone allows no leveled log events to pass. +func AllowNone() Option { + return allowed(0) +} + +func allowed(allowed level) Option { + return func(l *filter) { l.allowed = allowed } +} + +// ErrNotAllowed sets the error to return from Log when it squelches a log +// event disallowed by the configured Allow[Level] option. By default, +// ErrNotAllowed is nil; in this case the log event is squelched with no +// error. +func ErrNotAllowed(err error) Option { + return func(l *filter) { l.errNotAllowed = err } +} + +type level byte + +const ( + levelDebug level = 1 << iota + levelInfo + levelError +) diff --git a/log/filter_test.go b/log/filter_test.go new file mode 100644 index 000000000..5e1fb167e --- /dev/null +++ b/log/filter_test.go @@ -0,0 +1,103 @@ +package log_test + +import ( + "bytes" + "errors" + "strings" + "testing" + + "github.com/tendermint/tmlibs/log" +) + +func TestVariousLevels(t *testing.T) { + testCases := []struct { + name string + allowed log.Option + want string + }{ + { + "AllowAll", + log.AllowAll(), + strings.Join([]string{ + `{"_msg":"here","level":"debug","this is":"debug log"}`, + `{"_msg":"here","level":"info","this is":"info log"}`, + `{"_msg":"here","level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "AllowDebug", + log.AllowDebug(), + strings.Join([]string{ + `{"_msg":"here","level":"debug","this is":"debug log"}`, + `{"_msg":"here","level":"info","this is":"info log"}`, + `{"_msg":"here","level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "AllowInfo", + log.AllowInfo(), + strings.Join([]string{ + `{"_msg":"here","level":"info","this is":"info log"}`, + `{"_msg":"here","level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "AllowError", + log.AllowError(), + strings.Join([]string{ + `{"_msg":"here","level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "AllowNone", + log.AllowNone(), + ``, + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + logger := log.NewFilter(log.NewTMJSONLogger(&buf), tc.allowed) + + logger.Debug("here", "this is", "debug log") + logger.Info("here", "this is", "info log") + logger.Error("here", "this is", "error log") + + if want, have := tc.want, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant:\n%s\nhave:\n%s", want, have) + } + }) + } +} + +func TestErrNotAllowed(t *testing.T) { + myError := errors.New("squelched!") + opts := []log.Option{ + log.AllowError(), + log.ErrNotAllowed(myError), + } + logger := log.NewFilter(log.NewNopLogger(), opts...) + + if want, have := myError, logger.Info("foo", "bar", "baz"); want != have { + t.Errorf("want %#+v, have %#+v", want, have) + } + + if want, have := error(nil), logger.Error("foo", "bar", "baz"); want != have { + t.Errorf("want %#+v, have %#+v", want, have) + } +} + +func TestLevelContext(t *testing.T) { + var buf bytes.Buffer + + var logger log.Logger + logger = log.NewTMJSONLogger(&buf) + logger = log.NewFilter(logger, log.AllowAll()) + logger = logger.With("context", "value") + + logger.Info("foo", "bar", "baz") + if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"info"}`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } +} diff --git a/log/logger.go b/log/logger.go new file mode 100644 index 000000000..be273f484 --- /dev/null +++ b/log/logger.go @@ -0,0 +1,30 @@ +package log + +import ( + "io" + + kitlog "github.com/go-kit/kit/log" +) + +// Logger is what any Tendermint library should take. +type Logger interface { + Debug(msg string, keyvals ...interface{}) error + Info(msg string, keyvals ...interface{}) error + Error(msg string, keyvals ...interface{}) error + + With(keyvals ...interface{}) Logger +} + +// NewSyncWriter returns a new writer that is safe for concurrent use by +// multiple goroutines. Writes to the returned writer are passed on to w. If +// another write is already in progress, the calling goroutine blocks until +// the writer is available. +// +// If w implements the following interface, so does the returned writer. +// +// interface { +// Fd() uintptr +// } +func NewSyncWriter(w io.Writer) io.Writer { + return kitlog.NewSyncWriter(w) +} diff --git a/log/nop_logger.go b/log/nop_logger.go new file mode 100644 index 000000000..306a8405f --- /dev/null +++ b/log/nop_logger.go @@ -0,0 +1,25 @@ +package log + +type nopLogger struct{} + +// Interface assertions +var _ Logger = (*nopLogger)(nil) + +// NewNopLogger returns a logger that doesn't do anything. +func NewNopLogger() Logger { return &nopLogger{} } + +func (nopLogger) Info(string, ...interface{}) error { + return nil +} + +func (nopLogger) Debug(string, ...interface{}) error { + return nil +} + +func (nopLogger) Error(string, ...interface{}) error { + return nil +} + +func (l *nopLogger) With(...interface{}) Logger { + return l +} diff --git a/log/nop_logger_test.go b/log/nop_logger_test.go new file mode 100644 index 000000000..d2009fdf0 --- /dev/null +++ b/log/nop_logger_test.go @@ -0,0 +1,18 @@ +package log_test + +import ( + "testing" + + "github.com/tendermint/tmlibs/log" +) + +func TestNopLogger(t *testing.T) { + t.Parallel() + logger := log.NewNopLogger() + if err := logger.Info("Hello", "abc", 123); err != nil { + t.Error(err) + } + if err := logger.With("def", "ghi").Debug(""); err != nil { + t.Error(err) + } +} diff --git a/log/testing_logger.go b/log/testing_logger.go new file mode 100644 index 000000000..319136337 --- /dev/null +++ b/log/testing_logger.go @@ -0,0 +1,31 @@ +package log + +import ( + "os" + "testing" +) + +var ( + // reuse the same logger across all tests + _testingLogger Logger +) + +// TestingLogger returns a TMLogger which writes to STDOUT if testing being run +// with the verbose (-v) flag, NopLogger otherwise. +// +// Note that the call to TestingLogger() must be made +// inside a test (not in the init func) because +// verbose flag only set at the time of testing. +func TestingLogger() Logger { + if _testingLogger != nil { + return _testingLogger + } + + if testing.Verbose() { + _testingLogger = NewTMLogger(NewSyncWriter(os.Stdout)) + } else { + _testingLogger = NewNopLogger() + } + + return _testingLogger +} diff --git a/log/tm_json_logger.go b/log/tm_json_logger.go new file mode 100644 index 000000000..a71ac1034 --- /dev/null +++ b/log/tm_json_logger.go @@ -0,0 +1,15 @@ +package log + +import ( + "io" + + kitlog "github.com/go-kit/kit/log" +) + +// NewTMJSONLogger returns a Logger that encodes keyvals to the Writer as a +// single JSON object. Each log event produces no more than one call to +// w.Write. The passed Writer must be safe for concurrent use by multiple +// goroutines if the returned Logger will be used concurrently. +func NewTMJSONLogger(w io.Writer) Logger { + return &tmLogger{kitlog.NewJSONLogger(w)} +} diff --git a/log/tm_logger.go b/log/tm_logger.go new file mode 100644 index 000000000..a6a6f6d39 --- /dev/null +++ b/log/tm_logger.go @@ -0,0 +1,67 @@ +package log + +import ( + "fmt" + "io" + + kitlog "github.com/go-kit/kit/log" + kitlevel "github.com/go-kit/kit/log/level" + "github.com/go-kit/kit/log/term" +) + +const ( + msgKey = "_msg" // "_" prefixed to avoid collisions +) + +type tmLogger struct { + srcLogger kitlog.Logger +} + +// Interface assertions +var _ Logger = (*tmLogger)(nil) + +// NewTMTermLogger returns a logger that encodes msg and keyvals to the Writer +// using go-kit's log as an underlying logger and our custom formatter. Note +// that underlying logger could be swapped with something else. +func NewTMLogger(w io.Writer) Logger { + // Color by level value + colorFn := func(keyvals ...interface{}) term.FgBgColor { + if keyvals[0] != kitlevel.Key() { + panic(fmt.Sprintf("expected level key to be first, got %v", keyvals[0])) + } + switch keyvals[1].(kitlevel.Value).String() { + case "debug": + return term.FgBgColor{Fg: term.DarkGray} + case "error": + return term.FgBgColor{Fg: term.Red} + default: + return term.FgBgColor{} + } + } + + return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)} +} + +// Info logs a message at level Info. +func (l *tmLogger) Info(msg string, keyvals ...interface{}) error { + lWithLevel := kitlevel.Info(l.srcLogger) + return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...) +} + +// Debug logs a message at level Debug. +func (l *tmLogger) Debug(msg string, keyvals ...interface{}) error { + lWithLevel := kitlevel.Debug(l.srcLogger) + return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...) +} + +// Error logs a message at level Error. +func (l *tmLogger) Error(msg string, keyvals ...interface{}) error { + lWithLevel := kitlevel.Error(l.srcLogger) + return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...) +} + +// With returns a new contextual logger with keyvals prepended to those passed +// to calls to Info, Debug or Error. +func (l *tmLogger) With(keyvals ...interface{}) Logger { + return &tmLogger{kitlog.With(l.srcLogger, keyvals...)} +} diff --git a/log/tm_logger_test.go b/log/tm_logger_test.go new file mode 100644 index 000000000..15c940ce8 --- /dev/null +++ b/log/tm_logger_test.go @@ -0,0 +1,41 @@ +package log_test + +import ( + "io/ioutil" + "testing" + + "github.com/tendermint/tmlibs/log" +) + +func TestTMLogger(t *testing.T) { + t.Parallel() + logger := log.NewTMLogger(ioutil.Discard) + if err := logger.Info("Hello", "abc", 123); err != nil { + t.Error(err) + } + if err := logger.With("def", "ghi").Debug(""); err != nil { + t.Error(err) + } +} + +func BenchmarkTMLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewTMLogger(ioutil.Discard), baseInfoMessage) +} + +func BenchmarkTMLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewTMLogger(ioutil.Discard), withInfoMessage) +} + +func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { + lc := logger.With("common_key", "common_value") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + f(lc) + } +} + +var ( + baseInfoMessage = func(logger log.Logger) { logger.Info("foo_message", "foo_key", "foo_value") } + withInfoMessage = func(logger log.Logger) { logger.With("a", "b").Info("c", "d", "f") } +) diff --git a/log/tmfmt_logger.go b/log/tmfmt_logger.go new file mode 100644 index 000000000..4e36de898 --- /dev/null +++ b/log/tmfmt_logger.go @@ -0,0 +1,116 @@ +package log + +import ( + "bytes" + "fmt" + "io" + "sync" + "time" + + kitlog "github.com/go-kit/kit/log" + kitlevel "github.com/go-kit/kit/log/level" + "github.com/go-logfmt/logfmt" +) + +type tmfmtEncoder struct { + *logfmt.Encoder + buf bytes.Buffer +} + +func (l *tmfmtEncoder) Reset() { + l.Encoder.Reset() + l.buf.Reset() +} + +var tmfmtEncoderPool = sync.Pool{ + New: func() interface{} { + var enc tmfmtEncoder + enc.Encoder = logfmt.NewEncoder(&enc.buf) + return &enc + }, +} + +type tmfmtLogger struct { + w io.Writer +} + +// NewTMFmtLogger returns a logger that encodes keyvals to the Writer in +// Tendermint custom format. +// +// Each log event produces no more than one call to w.Write. +// The passed Writer must be safe for concurrent use by multiple goroutines if +// the returned Logger will be used concurrently. +func NewTMFmtLogger(w io.Writer) kitlog.Logger { + return &tmfmtLogger{w} +} + +func (l tmfmtLogger) Log(keyvals ...interface{}) error { + enc := tmfmtEncoderPool.Get().(*tmfmtEncoder) + enc.Reset() + defer tmfmtEncoderPool.Put(enc) + + lvl := "none" + msg := "unknown" + lvlIndex := -1 + msgIndex := -1 + + for i := 0; i < len(keyvals)-1; i += 2 { + // Extract level + if keyvals[i] == kitlevel.Key() { + lvlIndex = i + switch keyvals[i+1].(type) { + case string: + lvl = keyvals[i+1].(string) + case kitlevel.Value: + lvl = keyvals[i+1].(kitlevel.Value).String() + default: + panic(fmt.Sprintf("level value of unknown type %T", keyvals[i+1])) + } + continue + } + + // and message + if keyvals[i] == msgKey { + msgIndex = i + msg = keyvals[i+1].(string) + continue + } + + if lvlIndex > 0 && msgIndex > 0 { // found all we're looking for + break + } + } + + // Form a custom Tendermint line + // + // Example: + // D[05-02|11:06:44.322] Stopping AddrBook (ignoring: already stopped) + // + // Description: + // D - first character of the level, uppercase (ASCII only) + // [05-02|11:06:44.322] - our time format (see https://golang.org/src/time/format.go) + // Stopping ... - message + enc.buf.WriteString(fmt.Sprintf("%c[%s] %-44s", lvl[0]-32, time.Now().UTC().Format("01-02|15:04:05.000"), msg)) + + for i := 0; i < len(keyvals)-1; i += 2 { + if i == lvlIndex || i == msgIndex { + continue + } + if err := enc.EncodeKeyval(keyvals[i], keyvals[i+1]); err != nil { + return err + } + } + + // Add newline to the end of the buffer + if err := enc.EndRecord(); err != nil { + return err + } + + // The Logger interface requires implementations to be safe for concurrent + // use by multiple goroutines. For this implementation that means making + // only one call to l.w.Write() for each call to Log. + if _, err := l.w.Write(enc.buf.Bytes()); err != nil { + return err + } + return nil +} diff --git a/log/tmfmt_logger_test.go b/log/tmfmt_logger_test.go new file mode 100644 index 000000000..c5ec41274 --- /dev/null +++ b/log/tmfmt_logger_test.go @@ -0,0 +1,110 @@ +package log_test + +import ( + "bytes" + "errors" + "io/ioutil" + "math" + "regexp" + "testing" + + kitlog "github.com/go-kit/kit/log" + "github.com/stretchr/testify/assert" + "github.com/tendermint/tmlibs/log" +) + +func TestTMFmtLogger(t *testing.T) { + t.Parallel() + buf := &bytes.Buffer{} + logger := log.NewTMFmtLogger(buf) + + if err := logger.Log("hello", "world"); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ hello=world\n$`), buf.String()) + + buf.Reset() + if err := logger.Log("a", 1, "err", errors.New("error")); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ a=1 err=error\n$`), buf.String()) + + buf.Reset() + err := logger.Log("std_map", map[int]int{1: 2}, "my_map", mymap{0: 0}) + assert.NotNil(t, err) + + buf.Reset() + if err := logger.Log("level", "error"); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`E\[.+\] unknown \s+\n$`), buf.String()) + + buf.Reset() + if err := logger.Log("_msg", "Hello"); err != nil { + t.Fatal(err) + } + assert.Regexp(t, regexp.MustCompile(`N\[.+\] Hello \s+\n$`), buf.String()) +} + +func BenchmarkTMFmtLoggerSimple(b *testing.B) { + benchmarkRunnerKitlog(b, log.NewTMFmtLogger(ioutil.Discard), baseMessage) +} + +func BenchmarkTMFmtLoggerContextual(b *testing.B) { + benchmarkRunnerKitlog(b, log.NewTMFmtLogger(ioutil.Discard), withMessage) +} + +func TestTMFmtLoggerConcurrency(t *testing.T) { + t.Parallel() + testConcurrency(t, log.NewTMFmtLogger(ioutil.Discard), 10000) +} + +func benchmarkRunnerKitlog(b *testing.B, logger kitlog.Logger, f func(kitlog.Logger)) { + lc := kitlog.With(logger, "common_key", "common_value") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + f(lc) + } +} + +var ( + baseMessage = func(logger kitlog.Logger) { logger.Log("foo_key", "foo_value") } + withMessage = func(logger kitlog.Logger) { kitlog.With(logger, "a", "b").Log("d", "f") } +) + +// These test are designed to be run with the race detector. + +func testConcurrency(t *testing.T, logger kitlog.Logger, total int) { + n := int(math.Sqrt(float64(total))) + share := total / n + + errC := make(chan error, n) + + for i := 0; i < n; i++ { + go func() { + errC <- spam(logger, share) + }() + } + + for i := 0; i < n; i++ { + err := <-errC + if err != nil { + t.Fatalf("concurrent logging error: %v", err) + } + } +} + +func spam(logger kitlog.Logger, count int) error { + for i := 0; i < count; i++ { + err := logger.Log("key", i) + if err != nil { + return err + } + } + return nil +} + +type mymap map[int]int + +func (m mymap) String() string { return "special_behavior" } diff --git a/logger/log.go b/logger/log.go index 84f71c34f..2f4faef6b 100644 --- a/logger/log.go +++ b/logger/log.go @@ -1,10 +1,11 @@ +// DEPRECATED! Use newer log package. package logger import ( "os" - . "github.com/tendermint/tmlibs/common" "github.com/tendermint/log15" + . "github.com/tendermint/tmlibs/common" ) var mainHandler log15.Handler @@ -40,14 +41,14 @@ func MainHandler() log15.Handler { return mainHandler } -func BypassHandler() log15.Handler { - return bypassHandler -} - func New(ctx ...interface{}) log15.Logger { return NewMain(ctx...) } +func BypassHandler() log15.Handler { + return bypassHandler +} + func NewMain(ctx ...interface{}) log15.Logger { return log15.Root().New(ctx...) }