Logger interface and tmLogger impl based on go-kit

log/logger.go

@@ -0,0 +1,27 @@
+package log
+
+import (
+	"fmt"
+
+	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 returns a new contextual logger with keyvals prepended to those passed
+// to calls to Info, Debug or Error.
+func With(logger Logger, keyvals ...interface{}) Logger {
+	switch logger.(type) {
+	case *tmLogger:
+		return &tmLogger{kitlog.With(logger.(*tmLogger).srcLogger, keyvals...)}
+	case *nopLogger:
+		return logger
+	default:
+		panic(fmt.Sprintf("Unexpected logger of type %T", logger))
+	}
+}

log/nop_logger.go

@@ -0,0 +1,18 @@
+package log
+
+type nopLogger struct{}
+
+// 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
+}

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 := log.With(logger, "def", "ghi").Debug(""); err != nil {
+		t.Error(err)
+	}
+}

log/tm_logger.go

@@ -0,0 +1,74 @@
+package log
+
+import (
+	"fmt"
+	"io"
+
+	kitlog "github.com/go-kit/kit/log"
+	"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
+}
+
+// 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] != level.Key() {
+			panic(fmt.Sprintf("expected level key to be first, got %v", keyvals[0]))
+		}
+		switch keyvals[1].(level.Value).String() {
+		case "debug":
+			return term.FgBgColor{Fg: term.DarkGray}
+		case "error":
+			return term.FgBgColor{Fg: term.Red}
+		default:
+			return term.FgBgColor{}
+		}
+	}
+
+	srcLogger := term.NewLogger(w, NewTmfmtLogger, colorFn)
+	srcLogger = level.NewFilter(srcLogger, level.AllowInfo())
+	return &tmLogger{srcLogger}
+}
+
+// WithLevel returns a copy of the logger with a level set to lvl.
+func (l *tmLogger) WithLevel(lvl string) Logger {
+	switch lvl {
+	case "info":
+		return &tmLogger{level.NewFilter(l.srcLogger, level.AllowInfo())}
+	case "debug":
+		return &tmLogger{level.NewFilter(l.srcLogger, level.AllowDebug())}
+	case "error":
+		return &tmLogger{level.NewFilter(l.srcLogger, level.AllowError())}
+	default:
+		panic(fmt.Sprintf("Unexpected level %v, expect either \"info\" or \"debug\" or \"error\"", lvl))
+	}
+}
+
+// Info logs a message at level Info.
+func (l *tmLogger) Info(msg string, keyvals ...interface{}) error {
+	lWithLevel := level.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 := level.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 := level.Error(l.srcLogger)
+	return kitlog.With(lWithLevel, msgKey, msg).Log(keyvals...)
+}

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 := log.With(logger, "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 := log.With(logger, "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) { log.With(logger, "a", "b").Info("c", "d", "f") }
+)

log/tmfmt_logger.go

@@ -0,0 +1,116 @@
+package log
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+	"sync"
+	"time"
+
+	kitlog "github.com/go-kit/kit/log"
+	"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] == level.Key() {
+			lvlIndex = i
+			switch keyvals[i+1].(type) {
+			case string:
+				lvl = keyvals[i+1].(string)
+			case level.Value:
+				lvl = keyvals[i+1].(level.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
+}

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