Browse Source

Merge pull request #7 from tendermint/log

Log
pull/1842/head
Ethan Buchman 8 years ago
committed by GitHub
parent
commit
d72136da0d
19 changed files with 722 additions and 71 deletions
  1. +1
    -2
      .gitignore
  2. +2
    -4
      Makefile
  3. +27
    -29
      common/service.go
  4. +1
    -1
      events/events.go
  5. +0
    -7
      events/log.go
  6. +20
    -20
      glide.lock
  7. +12
    -3
      glide.yaml
  8. +97
    -0
      log/filter.go
  9. +103
    -0
      log/filter_test.go
  10. +30
    -0
      log/logger.go
  11. +25
    -0
      log/nop_logger.go
  12. +18
    -0
      log/nop_logger_test.go
  13. +31
    -0
      log/testing_logger.go
  14. +15
    -0
      log/tm_json_logger.go
  15. +67
    -0
      log/tm_logger.go
  16. +41
    -0
      log/tm_logger_test.go
  17. +116
    -0
      log/tmfmt_logger.go
  18. +110
    -0
      log/tmfmt_logger_test.go
  19. +6
    -5
      logger/log.go

+ 1
- 2
.gitignore View File

@ -1,3 +1,2 @@
*.swp
*.swo
vendor
.glide

+ 2
- 4
Makefile View File

@ -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)

+ 27
- 29
common/service.go View File

@ -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),
}
}

+ 1
- 1
events/events.go View File

@ -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
}


+ 0
- 7
events/log.go View File

@ -1,7 +0,0 @@
package events
import (
"github.com/tendermint/tmlibs/logger"
)
var log = logger.New("module", "events")

+ 20
- 20
glide.lock View File

@ -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

+ 12
- 3
glide.yaml View File

@ -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


+ 97
- 0
log/filter.go View File

@ -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
)

+ 103
- 0
log/filter_test.go View File

@ -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)
}
}

+ 30
- 0
log/logger.go View File

@ -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)
}

+ 25
- 0
log/nop_logger.go View File

@ -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
}

+ 18
- 0
log/nop_logger_test.go View File

@ -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)
}
}

+ 31
- 0
log/testing_logger.go View File

@ -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
}

+ 15
- 0
log/tm_json_logger.go View File

@ -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)}
}

+ 67
- 0
log/tm_logger.go View File

@ -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...)}
}

+ 41
- 0
log/tm_logger_test.go View File

@ -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") }
)

+ 116
- 0
log/tmfmt_logger.go View File

@ -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
}

+ 110
- 0
log/tmfmt_logger_test.go View File

@ -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" }

+ 6
- 5
logger/log.go View File

@ -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...)
}


Loading…
Cancel
Save