libs/log: format []byte as hexidecimal string (uppercased) (#5960)

Closes: #5806 

Co-authored-by: Lanie Hei <heixx011@umn.edu>

libs/log/tm_logger.go

@@ -21,7 +21,7 @@ type tmLogger struct {
 // Interface assertions
 var _ Logger = (*tmLogger)(nil)
 
-// NewTMTermLogger returns a logger that encodes msg and keyvals to the Writer
+// NewTMLogger 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 {
@@ -52,6 +52,7 @@ func NewTMLoggerWithColorFn(w io.Writer, colorFn func(keyvals ...interface{}) te
 // 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) //nolint:errcheck // no need to check error again
@@ -61,6 +62,7 @@ func (l *tmLogger) Info(msg string, keyvals ...interface{}) {
 // 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) //nolint:errcheck // no need to check error again
@@ -70,6 +72,7 @@ func (l *tmLogger) Debug(msg string, keyvals ...interface{}) {
 // 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) //nolint:errcheck // no need to check error again

libs/log/tm_logger_test.go

@@ -20,6 +20,75 @@ func TestLoggerLogsItsErrors(t *testing.T) {
 	}
 }
 
+func TestInfo(t *testing.T) {
+	var bufInfo bytes.Buffer
+
+	l := log.NewTMLogger(&bufInfo)
+	l.Info("Client initialized with old header (trusted is more recent)",
+		"old", 42,
+		"trustedHeight", "forty two",
+		"trustedHash", []byte("test me"))
+
+	msg := strings.TrimSpace(bufInfo.String())
+
+	// Remove the timestamp information to allow
+	// us to test against the expected message.
+	receivedmsg := strings.Split(msg, "] ")[1]
+
+	const expectedmsg = `Client initialized with old header
+	(trusted is more recent) old=42 trustedHeight="forty two"
+	trustedHash=74657374206D65`
+	if strings.EqualFold(receivedmsg, expectedmsg) {
+		t.Fatalf("received %s, expected %s", receivedmsg, expectedmsg)
+	}
+}
+
+func TestDebug(t *testing.T) {
+	var bufDebug bytes.Buffer
+
+	ld := log.NewTMLogger(&bufDebug)
+	ld.Debug("Client initialized with old header (trusted is more recent)",
+		"old", 42,
+		"trustedHeight", "forty two",
+		"trustedHash", []byte("test me"))
+
+	msg := strings.TrimSpace(bufDebug.String())
+
+	// Remove the timestamp information to allow
+	// us to test against the expected message.
+	receivedmsg := strings.Split(msg, "] ")[1]
+
+	const expectedmsg = `Client initialized with old header
+	(trusted is more recent) old=42 trustedHeight="forty two"
+	trustedHash=74657374206D65`
+	if strings.EqualFold(receivedmsg, expectedmsg) {
+		t.Fatalf("received %s, expected %s", receivedmsg, expectedmsg)
+	}
+}
+
+func TestError(t *testing.T) {
+	var bufErr bytes.Buffer
+
+	le := log.NewTMLogger(&bufErr)
+	le.Error("Client initialized with old header (trusted is more recent)",
+		"old", 42,
+		"trustedHeight", "forty two",
+		"trustedHash", []byte("test me"))
+
+	msg := strings.TrimSpace(bufErr.String())
+
+	// Remove the timestamp information to allow
+	// us to test against the expected message.
+	receivedmsg := strings.Split(msg, "] ")[1]
+
+	const expectedmsg = `Client initialized with old header
+	(trusted is more recent) old=42 trustedHeight="forty two"
+	trustedHash=74657374206D65`
+	if strings.EqualFold(receivedmsg, expectedmsg) {
+		t.Fatalf("received %s, expected %s", receivedmsg, expectedmsg)
+	}
+}
+
 func BenchmarkTMLoggerSimple(b *testing.B) {
 	benchmarkRunner(b, log.NewTMLogger(ioutil.Discard), baseInfoMessage)
 }

libs/log/tmfmt_logger.go

@@ -2,8 +2,10 @@ package log
 
 import (
 	"bytes"
+	"encoding/hex"
 	"fmt"
 	"io"
+	"strings"
 	"sync"
 	"time"
 
@@ -80,6 +82,11 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error {
 			excludeIndexes = append(excludeIndexes, i)
 			module = keyvals[i+1].(string)
 		}
+
+		// Print []byte as a hexadecimal string (uppercased)
+		if b, ok := keyvals[i+1].([]byte); ok {
+			keyvals[i+1] = strings.ToUpper(hex.EncodeToString(b))
+		}
 	}
 
 	// Form a custom Tendermint line

libs/log/tmfmt_logger_test.go

@@ -53,6 +53,12 @@ func TestTMFmtLogger(t *testing.T) {
 		t.Fatal(err)
 	}
 	assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+module=wire\s+\n$`), buf.String())
+
+	buf.Reset()
+	if err := logger.Log("hash", []byte("test me")); err != nil {
+		t.Fatal(err)
+	}
+	assert.Regexp(t, regexp.MustCompile(`N\[.+\] unknown \s+ hash=74657374206D65\n$`), buf.String())
 }
 
 func BenchmarkTMFmtLoggerSimple(b *testing.B) {