Merge pull request #21 from tendermint/feature/tracing-logger

[log] tracing logger

log/tm_logger.go

@@ -43,7 +43,7 @@ func NewTMLogger(w io.Writer) Logger {
 	return &tmLogger{term.NewLogger(w, NewTMFmtLogger, colorFn)}
 }
 
-// NewTMLoggerWithColorFn allow you to provide your own color function. See
+// 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)}

log/tracing_logger.go

@@ -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{}) error {
+	return l.next.Info(msg, formatErrors(keyvals)...)
+}
+
+func (l *tracingLogger) Debug(msg string, keyvals ...interface{}) error {
+	return l.next.Debug(msg, formatErrors(keyvals)...)
+}
+
+func (l *tracingLogger) Error(msg string, keyvals ...interface{}) error {
+	return 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)
+}

log/tracing_logger_test.go

@@ -0,0 +1,42 @@
+package log_test
+
+import (
+	"bytes"
+	stderr "errors"
+	"fmt"
+	"strings"
+	"testing"
+
+	"github.com/pkg/errors"
+	"github.com/tendermint/tmlibs/log"
+)
+
+func TestTracingLogger(t *testing.T) {
+	var buf bytes.Buffer
+
+	var logger log.Logger
+	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)
+	}
+}