mirror of
https://github.com/tendermint/tendermint.git
synced 2026-09-29 19:25:56 +00:00
Zach Ramsay
@@ -0,0 +1,158 @@
|
||||
package log
|
||||
|
||||
import "fmt"
|
||||
|
||||
type level byte
|
||||
|
||||
const (
|
||||
levelDebug level = 1 << iota
|
||||
levelInfo
|
||||
levelError
|
||||
)
|
||||
|
||||
type filter struct {
|
||||
next Logger
|
||||
allowed level // XOR'd levels for default case
|
||||
allowedKeyvals map[keyval]level // When key-value match, use this level
|
||||
}
|
||||
|
||||
type keyval struct {
|
||||
key interface{}
|
||||
value interface{}
|
||||
}
|
||||
|
||||
// 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,
|
||||
allowedKeyvals: make(map[keyval]level),
|
||||
}
|
||||
for _, option := range options {
|
||||
option(l)
|
||||
}
|
||||
return l
|
||||
}
|
||||
|
||||
func (l *filter) Info(msg string, keyvals ...interface{}) {
|
||||
levelAllowed := l.allowed&levelInfo != 0
|
||||
if !levelAllowed {
|
||||
return
|
||||
}
|
||||
l.next.Info(msg, keyvals...)
|
||||
}
|
||||
|
||||
func (l *filter) Debug(msg string, keyvals ...interface{}) {
|
||||
levelAllowed := l.allowed&levelDebug != 0
|
||||
if !levelAllowed {
|
||||
return
|
||||
}
|
||||
l.next.Debug(msg, keyvals...)
|
||||
}
|
||||
|
||||
func (l *filter) Error(msg string, keyvals ...interface{}) {
|
||||
levelAllowed := l.allowed&levelError != 0
|
||||
if !levelAllowed {
|
||||
return
|
||||
}
|
||||
l.next.Error(msg, keyvals...)
|
||||
}
|
||||
|
||||
// With implements Logger by constructing a new filter with a keyvals appended
|
||||
// to the logger.
|
||||
//
|
||||
// If custom level was set for a keyval pair using one of the
|
||||
// Allow*With methods, it is used as the logger's level.
|
||||
//
|
||||
// Examples:
|
||||
// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"))
|
||||
// logger.With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto"
|
||||
//
|
||||
// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"), log.AllowNoneWith("user", "Sam"))
|
||||
// logger.With("module", "crypto", "user", "Sam").Info("Hello") # returns nil
|
||||
//
|
||||
// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"), log.AllowNoneWith("user", "Sam"))
|
||||
// logger.With("user", "Sam").With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto user=Sam"
|
||||
func (l *filter) With(keyvals ...interface{}) Logger {
|
||||
for i := len(keyvals) - 2; i >= 0; i -= 2 {
|
||||
for kv, allowed := range l.allowedKeyvals {
|
||||
if keyvals[i] == kv.key && keyvals[i+1] == kv.value {
|
||||
return &filter{next: l.next.With(keyvals...), allowed: allowed, allowedKeyvals: l.allowedKeyvals}
|
||||
}
|
||||
}
|
||||
}
|
||||
return &filter{next: l.next.With(keyvals...), allowed: l.allowed, allowedKeyvals: l.allowedKeyvals}
|
||||
}
|
||||
|
||||
//--------------------------------------------------------------------------------
|
||||
|
||||
// Option sets a parameter for the filter.
|
||||
type Option func(*filter)
|
||||
|
||||
// AllowLevel returns an option for the given level or error if no option exist
|
||||
// for such level.
|
||||
func AllowLevel(lvl string) (Option, error) {
|
||||
switch lvl {
|
||||
case "debug":
|
||||
return AllowDebug(), nil
|
||||
case "info":
|
||||
return AllowInfo(), nil
|
||||
case "error":
|
||||
return AllowError(), nil
|
||||
case "none":
|
||||
return AllowNone(), nil
|
||||
default:
|
||||
return nil, fmt.Errorf("Expected either \"info\", \"debug\", \"error\" or \"none\" level, given %s", lvl)
|
||||
}
|
||||
}
|
||||
|
||||
// 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 }
|
||||
}
|
||||
|
||||
// AllowDebugWith allows error, info and debug level log events to pass for a specific key value pair.
|
||||
func AllowDebugWith(key interface{}, value interface{}) Option {
|
||||
return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo | levelDebug }
|
||||
}
|
||||
|
||||
// AllowInfoWith allows error and info level log events to pass for a specific key value pair.
|
||||
func AllowInfoWith(key interface{}, value interface{}) Option {
|
||||
return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo }
|
||||
}
|
||||
|
||||
// AllowErrorWith allows only error level log events to pass for a specific key value pair.
|
||||
func AllowErrorWith(key interface{}, value interface{}) Option {
|
||||
return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError }
|
||||
}
|
||||
|
||||
// AllowNoneWith allows no leveled log events to pass for a specific key value pair.
|
||||
func AllowNoneWith(key interface{}, value interface{}) Option {
|
||||
return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = 0 }
|
||||
}
|
||||
@@ -0,0 +1,118 @@
|
||||
package log_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/tendermint/tendermint/libs/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 TestLevelContext(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
|
||||
logger := log.NewTMJSONLogger(&buf)
|
||||
logger = log.NewFilter(logger, log.AllowError())
|
||||
logger = logger.With("context", "value")
|
||||
|
||||
logger.Error("foo", "bar", "baz")
|
||||
if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"error"}`, strings.TrimSpace(buf.String()); want != have {
|
||||
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
|
||||
}
|
||||
|
||||
buf.Reset()
|
||||
logger.Info("foo", "bar", "baz")
|
||||
if want, have := ``, strings.TrimSpace(buf.String()); want != have {
|
||||
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
|
||||
}
|
||||
}
|
||||
|
||||
func TestVariousAllowWith(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
|
||||
logger := log.NewTMJSONLogger(&buf)
|
||||
|
||||
logger1 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"))
|
||||
logger1.With("context", "value").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)
|
||||
}
|
||||
|
||||
buf.Reset()
|
||||
|
||||
logger2 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"), log.AllowNoneWith("user", "Sam"))
|
||||
logger2.With("context", "value", "user", "Sam").Info("foo", "bar", "baz")
|
||||
if want, have := ``, strings.TrimSpace(buf.String()); want != have {
|
||||
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
|
||||
}
|
||||
|
||||
buf.Reset()
|
||||
|
||||
logger3 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"), log.AllowNoneWith("user", "Sam"))
|
||||
logger3.With("user", "Sam").With("context", "value").Info("foo", "bar", "baz")
|
||||
if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"info","user":"Sam"}`, strings.TrimSpace(buf.String()); want != have {
|
||||
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
|
||||
}
|
||||
}
|
||||
@@ -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{})
|
||||
Info(msg string, keyvals ...interface{})
|
||||
Error(msg string, keyvals ...interface{})
|
||||
|
||||
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)
|
||||
}
|
||||
@@ -0,0 +1,17 @@
|
||||
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{}) {}
|
||||
func (nopLogger) Debug(string, ...interface{}) {}
|
||||
func (nopLogger) Error(string, ...interface{}) {}
|
||||
|
||||
func (l *nopLogger) With(...interface{}) Logger {
|
||||
return l
|
||||
}
|
||||
@@ -0,0 +1,49 @@
|
||||
package log
|
||||
|
||||
import (
|
||||
"os"
|
||||
"testing"
|
||||
|
||||
"github.com/go-kit/kit/log/term"
|
||||
)
|
||||
|
||||
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
|
||||
}
|
||||
|
||||
// TestingLoggerWithColorFn allow you to provide your own color function. See
|
||||
// TestingLogger for documentation.
|
||||
func TestingLoggerWithColorFn(colorFn func(keyvals ...interface{}) term.FgBgColor) Logger {
|
||||
if _testingLogger != nil {
|
||||
return _testingLogger
|
||||
}
|
||||
|
||||
if testing.Verbose() {
|
||||
_testingLogger = NewTMLoggerWithColorFn(NewSyncWriter(os.Stdout), colorFn)
|
||||
} else {
|
||||
_testingLogger = NewNopLogger()
|
||||
}
|
||||
|
||||
return _testingLogger
|
||||
}
|
||||
@@ -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)}
|
||||
}
|
||||
@@ -0,0 +1,83 @@
|
||||
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
|
||||
moduleKey = "module"
|
||||
)
|
||||
|
||||
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)}
|
||||
}
|
||||
|
||||
// NewTMLoggerWithColorFn allows you to provide your own color function. See
|
||||
// NewTMLogger for documentation.
|
||||
func NewTMLoggerWithColorFn(w io.Writer, colorFn func(keyvals ...interface{}) term.FgBgColor) Logger {
|
||||
return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)}
|
||||
}
|
||||
|
||||
// Info logs a message at level Info.
|
||||
func (l *tmLogger) Info(msg string, keyvals ...interface{}) {
|
||||
lWithLevel := kitlevel.Info(l.srcLogger)
|
||||
if err := kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...); err != nil {
|
||||
errLogger := kitlevel.Error(l.srcLogger)
|
||||
kitlog.With(errLogger, msgKey, msg).Log("err", err)
|
||||
}
|
||||
}
|
||||
|
||||
// Debug logs a message at level Debug.
|
||||
func (l *tmLogger) Debug(msg string, keyvals ...interface{}) {
|
||||
lWithLevel := kitlevel.Debug(l.srcLogger)
|
||||
if err := kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...); err != nil {
|
||||
errLogger := kitlevel.Error(l.srcLogger)
|
||||
kitlog.With(errLogger, msgKey, msg).Log("err", err)
|
||||
}
|
||||
}
|
||||
|
||||
// Error logs a message at level Error.
|
||||
func (l *tmLogger) Error(msg string, keyvals ...interface{}) {
|
||||
lWithLevel := kitlevel.Error(l.srcLogger)
|
||||
lWithMsg := kitlog.With(lWithLevel, msgKey, msg)
|
||||
if err := lWithMsg.Log(keyvals...); err != nil {
|
||||
lWithMsg.Log("err", err)
|
||||
}
|
||||
}
|
||||
|
||||
// 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...)}
|
||||
}
|
||||
@@ -0,0 +1,44 @@
|
||||
package log_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"io/ioutil"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/go-logfmt/logfmt"
|
||||
"github.com/tendermint/tendermint/libs/log"
|
||||
)
|
||||
|
||||
func TestLoggerLogsItsErrors(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
|
||||
logger := log.NewTMLogger(&buf)
|
||||
logger.Info("foo", "baz baz", "bar")
|
||||
msg := strings.TrimSpace(buf.String())
|
||||
if !strings.Contains(msg, logfmt.ErrInvalidKey.Error()) {
|
||||
t.Errorf("Expected logger msg to contain ErrInvalidKey, got %s", msg)
|
||||
}
|
||||
}
|
||||
|
||||
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") }
|
||||
)
|
||||
@@ -0,0 +1,127 @@
|
||||
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. Note complex types (structs, maps, slices)
|
||||
// formatted as "%+v".
|
||||
//
|
||||
// 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)
|
||||
|
||||
const unknown = "unknown"
|
||||
lvl := "none"
|
||||
msg := unknown
|
||||
module := unknown
|
||||
|
||||
// indexes of keys to skip while encoding later
|
||||
excludeIndexes := make([]int, 0)
|
||||
|
||||
for i := 0; i < len(keyvals)-1; i += 2 {
|
||||
// Extract level
|
||||
if keyvals[i] == kitlevel.Key() {
|
||||
excludeIndexes = append(excludeIndexes, 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]))
|
||||
}
|
||||
// and message
|
||||
} else if keyvals[i] == msgKey {
|
||||
excludeIndexes = append(excludeIndexes, i)
|
||||
msg = keyvals[i+1].(string)
|
||||
// and module (could be multiple keyvals; if such case last keyvalue wins)
|
||||
} else if keyvals[i] == moduleKey {
|
||||
excludeIndexes = append(excludeIndexes, i)
|
||||
module = keyvals[i+1].(string)
|
||||
}
|
||||
}
|
||||
|
||||
// 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))
|
||||
|
||||
if module != unknown {
|
||||
enc.buf.WriteString("module=" + module + " ")
|
||||
}
|
||||
|
||||
KeyvalueLoop:
|
||||
for i := 0; i < len(keyvals)-1; i += 2 {
|
||||
for _, j := range excludeIndexes {
|
||||
if i == j {
|
||||
continue KeyvalueLoop
|
||||
}
|
||||
}
|
||||
|
||||
err := enc.EncodeKeyval(keyvals[i], keyvals[i+1])
|
||||
if err == logfmt.ErrUnsupportedValueType {
|
||||
enc.EncodeKeyval(keyvals[i], fmt.Sprintf("%+v", keyvals[i+1]))
|
||||
} else if 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
|
||||
}
|
||||
@@ -0,0 +1,118 @@
|
||||
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/tendermint/libs/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()
|
||||
if err := logger.Log("std_map", map[int]int{1: 2}, "my_map", mymap{0: 0}); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ std_map=map\[1:2\] my_map=special_behavior\n$`), buf.String())
|
||||
|
||||
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())
|
||||
|
||||
buf.Reset()
|
||||
if err := logger.Log("module", "main", "module", "crypto", "module", "wire"); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+module=wire\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" }
|
||||
@@ -0,0 +1,76 @@
|
||||
package log
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
|
||||
"github.com/pkg/errors"
|
||||
)
|
||||
|
||||
// NewTracingLogger enables tracing by wrapping all errors (if they
|
||||
// implement stackTracer interface) in tracedError.
|
||||
//
|
||||
// All errors returned by https://github.com/pkg/errors implement stackTracer
|
||||
// interface.
|
||||
//
|
||||
// For debugging purposes only as it doubles the amount of allocations.
|
||||
func NewTracingLogger(next Logger) Logger {
|
||||
return &tracingLogger{
|
||||
next: next,
|
||||
}
|
||||
}
|
||||
|
||||
type stackTracer interface {
|
||||
error
|
||||
StackTrace() errors.StackTrace
|
||||
}
|
||||
|
||||
type tracingLogger struct {
|
||||
next Logger
|
||||
}
|
||||
|
||||
func (l *tracingLogger) Info(msg string, keyvals ...interface{}) {
|
||||
l.next.Info(msg, formatErrors(keyvals)...)
|
||||
}
|
||||
|
||||
func (l *tracingLogger) Debug(msg string, keyvals ...interface{}) {
|
||||
l.next.Debug(msg, formatErrors(keyvals)...)
|
||||
}
|
||||
|
||||
func (l *tracingLogger) Error(msg string, keyvals ...interface{}) {
|
||||
l.next.Error(msg, formatErrors(keyvals)...)
|
||||
}
|
||||
|
||||
func (l *tracingLogger) With(keyvals ...interface{}) Logger {
|
||||
return &tracingLogger{next: l.next.With(formatErrors(keyvals)...)}
|
||||
}
|
||||
|
||||
func formatErrors(keyvals []interface{}) []interface{} {
|
||||
newKeyvals := make([]interface{}, len(keyvals))
|
||||
copy(newKeyvals, keyvals)
|
||||
for i := 0; i < len(newKeyvals)-1; i += 2 {
|
||||
if err, ok := newKeyvals[i+1].(stackTracer); ok {
|
||||
newKeyvals[i+1] = tracedError{err}
|
||||
}
|
||||
}
|
||||
return newKeyvals
|
||||
}
|
||||
|
||||
// tracedError wraps a stackTracer and just makes the Error() result
|
||||
// always return a full stack trace.
|
||||
type tracedError struct {
|
||||
wrapped stackTracer
|
||||
}
|
||||
|
||||
var _ stackTracer = tracedError{}
|
||||
|
||||
func (t tracedError) StackTrace() errors.StackTrace {
|
||||
return t.wrapped.StackTrace()
|
||||
}
|
||||
|
||||
func (t tracedError) Cause() error {
|
||||
return t.wrapped
|
||||
}
|
||||
|
||||
func (t tracedError) Error() string {
|
||||
return fmt.Sprintf("%+v", t.wrapped)
|
||||
}
|
||||
@@ -0,0 +1,41 @@
|
||||
package log_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
stderr "errors"
|
||||
"fmt"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/pkg/errors"
|
||||
"github.com/tendermint/tendermint/libs/log"
|
||||
)
|
||||
|
||||
func TestTracingLogger(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
|
||||
logger := log.NewTMJSONLogger(&buf)
|
||||
|
||||
logger1 := log.NewTracingLogger(logger)
|
||||
err1 := errors.New("Courage is grace under pressure.")
|
||||
err2 := errors.New("It does not matter how slowly you go, so long as you do not stop.")
|
||||
logger1.With("err1", err1).Info("foo", "err2", err2)
|
||||
have := strings.Replace(strings.Replace(strings.TrimSpace(buf.String()), "\\n", "", -1), "\\t", "", -1)
|
||||
if want := strings.Replace(strings.Replace(`{"_msg":"foo","err1":"`+fmt.Sprintf("%+v", err1)+`","err2":"`+fmt.Sprintf("%+v", err2)+`","level":"info"}`, "\t", "", -1), "\n", "", -1); want != have {
|
||||
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
|
||||
}
|
||||
|
||||
buf.Reset()
|
||||
|
||||
logger.With("err1", stderr.New("Opportunities don't happen. You create them.")).Info("foo", "err2", stderr.New("Once you choose hope, anything's possible."))
|
||||
if want, have := `{"_msg":"foo","err1":"Opportunities don't happen. You create them.","err2":"Once you choose hope, anything's possible.","level":"info"}`, strings.TrimSpace(buf.String()); want != have {
|
||||
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
|
||||
}
|
||||
|
||||
buf.Reset()
|
||||
|
||||
logger.With("user", "Sam").With("context", "value").Info("foo", "bar", "baz")
|
||||
if want, have := `{"_msg":"foo","bar":"baz","context":"value","level":"info","user":"Sam"}`, strings.TrimSpace(buf.String()); want != have {
|
||||
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user