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

Closes: #5806

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

consensus/replay.go

@@ -254,7 +254,7 @@ func (h *Handshaker) Handshake(proxyApp proxy.AppConns) error {
 
 	h.logger.Info("ABCI Handshake App Info",
 		"height", blockHeight,
-		"hash", fmt.Sprintf("%X", appHash),
+		"hash", appHash,
 		"software-version", res.Version,
 		"protocol-version", res.AppVersion,
 	)
@@ -271,7 +271,7 @@ func (h *Handshaker) Handshake(proxyApp proxy.AppConns) error {
 	}
 
 	h.logger.Info("Completed ABCI Handshake - Tendermint and App are synced",
-		"appHeight", blockHeight, "appHash", fmt.Sprintf("%X", appHash))
+		"appHeight", blockHeight, "appHash", appHash)
 
 	// TODO: (on restart) replay mempool
 

libs/bytes/bytes.go

@@ -6,7 +6,7 @@ import (
 	"strings"
 )
 
-// The main purpose of HexBytes is to enable HEX-encoding for json/encoding.
+// HexBytes enables HEX-encoding for json/encoding.
 type HexBytes []byte
 
 // Marshal needed for protobuf compatibility
@@ -43,7 +43,7 @@ func (bz *HexBytes) UnmarshalJSON(data []byte) error {
 	return nil
 }
 
-// Allow it to fulfill various interfaces in light-client, etc...
+// Bytes fulfils various interfaces in light-client, etc...
 func (bz HexBytes) Bytes() []byte {
 	return bz
 }
@@ -52,6 +52,9 @@ func (bz HexBytes) String() string {
 	return strings.ToUpper(hex.EncodeToString(bz))
 }
 
+// Format writes either address of 0th element in a slice in base 16 notation,
+// with leading 0x (%p), or casts HexBytes to bytes and writes as hexadecimal
+// string to s.
 func (bz HexBytes) Format(s fmt.State, verb rune) {
 	switch verb {
 	case 'p':

libs/bytes/bytes_test.go

@@ -3,6 +3,7 @@ package bytes
 import (
 	"encoding/json"
 	"fmt"
+	"strconv"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
@@ -24,7 +25,6 @@ func TestMarshal(t *testing.T) {
 
 // Test that the hex encoding works.
 func TestJSONMarshal(t *testing.T) {
-
 	type TestStruct struct {
 		B1 []byte
 		B2 HexBytes
@@ -64,3 +64,10 @@ func TestJSONMarshal(t *testing.T) {
 		})
 	}
 }
+
+func TestHexBytes_String(t *testing.T) {
+	hs := HexBytes([]byte("test me"))
+	if _, err := strconv.ParseInt(hs.String(), 16, 64); err != nil {
+		t.Fatal(err)
+	}
+}

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

light/client.go

@@ -295,7 +295,7 @@ func (c *Client) checkTrustedHeaderUsingOptions(ctx context.Context, options Tru
 		c.logger.Info("Client initialized with old header (trusted is more recent)",
 			"old", options.Height,
 			"trustedHeight", c.latestTrustedBlock.Height,
-			"trustedHash", hash2str(c.latestTrustedBlock.Hash()))
+			"trustedHash", c.latestTrustedBlock.Hash())
 
 		action := fmt.Sprintf(
 			"Rollback to %d (%X)? Note this will remove newer light blocks up to %d (%X)",
@@ -319,7 +319,7 @@ func (c *Client) checkTrustedHeaderUsingOptions(ctx context.Context, options Tru
 
 	if !bytes.Equal(primaryHash, c.latestTrustedBlock.Hash()) {
 		c.logger.Info("Prev. trusted header's hash (h1) doesn't match hash from primary provider (h2)",
-			"h1", hash2str(c.latestTrustedBlock.Hash()), "h2", hash2str(primaryHash))
+			"h1", c.latestTrustedBlock.Hash(), "h2", primaryHash)
 
 		action := fmt.Sprintf(
 			"Prev. trusted header's hash %X doesn't match hash %X from primary provider. Remove all the stored light blocks?",
@@ -434,7 +434,7 @@ func (c *Client) Update(ctx context.Context, now time.Time) (*types.LightBlock,
 		if err != nil {
 			return nil, err
 		}
-		c.logger.Info("Advanced to new state", "height", latestBlock.Height, "hash", hash2str(latestBlock.Hash()))
+		c.logger.Info("Advanced to new state", "height", latestBlock.Height, "hash", latestBlock.Hash())
 		return latestBlock, nil
 	}
 
@@ -459,7 +459,7 @@ func (c *Client) VerifyLightBlockAtHeight(ctx context.Context, height int64, now
 	// Check if the light block already verified.
 	h, err := c.TrustedLightBlock(height)
 	if err == nil {
-		c.logger.Info("Header has already been verified", "height", height, "hash", hash2str(h.Hash()))
+		c.logger.Info("Header has already been verified", "height", height, "hash", h.Hash())
 		// Return already trusted light block
 		return h, nil
 	}
@@ -517,7 +517,7 @@ func (c *Client) VerifyHeader(ctx context.Context, newHeader *types.Header, now
 			return fmt.Errorf("existing trusted header %X does not match newHeader %X", l.Hash(), newHeader.Hash())
 		}
 		c.logger.Info("Header has already been verified",
-			"height", newHeader.Height, "hash", hash2str(newHeader.Hash()))
+			"height", newHeader.Height, "hash", newHeader.Hash())
 		return nil
 	}
 
@@ -535,7 +535,7 @@ func (c *Client) VerifyHeader(ctx context.Context, newHeader *types.Header, now
 }
 
 func (c *Client) verifyLightBlock(ctx context.Context, newLightBlock *types.LightBlock, now time.Time) error {
-	c.logger.Info("VerifyHeader", "height", newLightBlock.Height, "hash", hash2str(newLightBlock.Hash()))
+	c.logger.Info("VerifyHeader", "height", newLightBlock.Height, "hash", newLightBlock.Hash())
 
 	var (
 		verifyFunc func(ctx context.Context, trusted *types.LightBlock, new *types.LightBlock, now time.Time) error
@@ -616,9 +616,9 @@ func (c *Client) verifySequential(
 		// 2) Verify them
 		c.logger.Debug("Verify adjacent newLightBlock against verifiedBlock",
 			"trustedHeight", verifiedBlock.Height,
-			"trustedHash", hash2str(verifiedBlock.Hash()),
+			"trustedHash", verifiedBlock.Hash(),
 			"newHeight", interimBlock.Height,
-			"newHash", hash2str(interimBlock.Hash()))
+			"newHash", interimBlock.Hash())
 
 		err = VerifyAdjacent(verifiedBlock.SignedHeader, interimBlock.SignedHeader, interimBlock.ValidatorSet,
 			c.trustingPeriod, now, c.maxClockDrift)
@@ -707,9 +707,9 @@ func (c *Client) verifySkipping(
 	for {
 		c.logger.Debug("Verify non-adjacent newHeader against verifiedBlock",
 			"trustedHeight", verifiedBlock.Height,
-			"trustedHash", hash2str(verifiedBlock.Hash()),
+			"trustedHash", verifiedBlock.Hash(),
 			"newHeight", blockCache[depth].Height,
-			"newHash", hash2str(blockCache[depth].Hash()))
+			"newHash", blockCache[depth].Hash())
 
 		err := Verify(verifiedBlock.SignedHeader, verifiedBlock.ValidatorSet, blockCache[depth].SignedHeader,
 			blockCache[depth].ValidatorSet, c.trustingPeriod, now, c.maxClockDrift, c.trustLevel)
@@ -929,9 +929,9 @@ func (c *Client) backwards(
 		interimHeader = interimBlock.Header
 		c.logger.Debug("Verify newHeader against verifiedHeader",
 			"trustedHeight", verifiedHeader.Height,
-			"trustedHash", hash2str(verifiedHeader.Hash()),
+			"trustedHash", verifiedHeader.Hash(),
 			"newHeight", interimHeader.Height,
-			"newHash", hash2str(interimHeader.Hash()))
+			"newHash", interimHeader.Hash())
 		if err := VerifyBackwards(interimHeader, verifiedHeader); err != nil {
 			c.logger.Error("primary sent invalid header -> replacing", "err", err)
 			if replaceErr := c.replacePrimaryProvider(); replaceErr != nil {
@@ -1048,7 +1048,3 @@ and remove witness. Otherwise, use the different primary`, e.WitnessIndex), "wit
 
 	return nil
 }
-
-func hash2str(hash []byte) string {
-	return fmt.Sprintf("%X", hash)
-}

mempool/clist_mempool.go

@@ -757,7 +757,7 @@ func TxKey(tx types.Tx) [TxKeySize]byte {
 	return sha256.Sum256(tx)
 }
 
-// txID is the hex encoded hash of the bytes as a types.Tx.
-func txID(tx []byte) string {
-	return fmt.Sprintf("%X", types.Tx(tx).Hash())
+// txID is a hash of the Tx.
+func txID(tx []byte) []byte {
+	return types.Tx(tx).Hash()
 }

state/execution.go

@@ -237,7 +237,7 @@ func (blockExec *BlockExecutor) Commit(
 		"Committed state",
 		"height", block.Height,
 		"txs", len(block.Txs),
-		"appHash", fmt.Sprintf("%X", res.Data),
+		"appHash", res.Data,
 	)
 
 	// Update mempool.

statesync/syncer.go

@@ -104,7 +104,7 @@ func (s *syncer) AddSnapshot(peer p2p.Peer, snapshot *snapshot) (bool, error) {
 	}
 	if added {
 		s.logger.Info("Discovered new snapshot", "height", snapshot.Height, "format", snapshot.Format,
-			"hash", fmt.Sprintf("%X", snapshot.Hash))
+			"hash", snapshot.Hash)
 	}
 	return added, nil
 }
@@ -171,18 +171,18 @@ func (s *syncer) SyncAny(discoveryTime time.Duration) (sm.State, *types.Commit,
 		case errors.Is(err, errRetrySnapshot):
 			chunks.RetryAll()
 			s.logger.Info("Retrying snapshot", "height", snapshot.Height, "format", snapshot.Format,
-				"hash", fmt.Sprintf("%X", snapshot.Hash))
+				"hash", snapshot.Hash)
 			continue
 
 		case errors.Is(err, errTimeout):
 			s.snapshots.Reject(snapshot)
 			s.logger.Error("Timed out waiting for snapshot chunks, rejected snapshot",
-				"height", snapshot.Height, "format", snapshot.Format, "hash", fmt.Sprintf("%X", snapshot.Hash))
+				"height", snapshot.Height, "format", snapshot.Format, "hash", snapshot.Hash)
 
 		case errors.Is(err, errRejectSnapshot):
 			s.snapshots.Reject(snapshot)
 			s.logger.Info("Snapshot rejected", "height", snapshot.Height, "format", snapshot.Format,
-				"hash", fmt.Sprintf("%X", snapshot.Hash))
+				"hash", snapshot.Hash)
 
 		case errors.Is(err, errRejectFormat):
 			s.snapshots.RejectFormat(snapshot.Format)
@@ -190,7 +190,7 @@ func (s *syncer) SyncAny(discoveryTime time.Duration) (sm.State, *types.Commit,
 
 		case errors.Is(err, errRejectSender):
 			s.logger.Info("Snapshot senders rejected", "height", snapshot.Height, "format", snapshot.Format,
-				"hash", fmt.Sprintf("%X", snapshot.Hash))
+				"hash", snapshot.Hash)
 			for _, peer := range s.snapshots.GetPeers(snapshot) {
 				s.snapshots.RejectPeer(peer.ID())
 				s.logger.Info("Snapshot sender rejected", "peer", peer.ID())
@@ -267,7 +267,7 @@ func (s *syncer) Sync(snapshot *snapshot, chunks *chunkQueue) (sm.State, *types.
 
 	// Done! 🎉
 	s.logger.Info("Snapshot restored", "height", snapshot.Height, "format", snapshot.Format,
-		"hash", fmt.Sprintf("%X", snapshot.Hash))
+		"hash", snapshot.Hash)
 
 	return state, commit, nil
 }
@@ -276,7 +276,7 @@ func (s *syncer) Sync(snapshot *snapshot, chunks *chunkQueue) (sm.State, *types.
 // response, or nil if the snapshot was accepted.
 func (s *syncer) offerSnapshot(snapshot *snapshot) error {
 	s.logger.Info("Offering snapshot to ABCI app", "height", snapshot.Height,
-		"format", snapshot.Format, "hash", fmt.Sprintf("%X", snapshot.Hash))
+		"format", snapshot.Format, "hash", snapshot.Hash)
 	resp, err := s.conn.OfferSnapshotSync(abci.RequestOfferSnapshot{
 		Snapshot: &abci.Snapshot{
 			Height:   snapshot.Height,
@@ -293,7 +293,7 @@ func (s *syncer) offerSnapshot(snapshot *snapshot) error {
 	switch resp.Result {
 	case abci.ResponseOfferSnapshot_ACCEPT:
 		s.logger.Info("Snapshot accepted, restoring", "height", snapshot.Height,
-			"format", snapshot.Format, "hash", fmt.Sprintf("%X", snapshot.Hash))
+			"format", snapshot.Format, "hash", snapshot.Hash)
 		return nil
 	case abci.ResponseOfferSnapshot_ABORT:
 		return errAbort
@@ -428,8 +428,8 @@ func (s *syncer) verifyApp(snapshot *snapshot) (uint64, error) {
 	}
 	if !bytes.Equal(snapshot.trustedAppHash, resp.LastBlockAppHash) {
 		s.logger.Error("appHash verification failed",
-			"expected", fmt.Sprintf("%X", snapshot.trustedAppHash),
-			"actual", fmt.Sprintf("%X", resp.LastBlockAppHash))
+			"expected", snapshot.trustedAppHash,
+			"actual", resp.LastBlockAppHash)
 		return 0, errVerifyFailed
 	}
 	if uint64(resp.LastBlockHeight) != snapshot.Height {
@@ -437,7 +437,7 @@ func (s *syncer) verifyApp(snapshot *snapshot) (uint64, error) {
 			"expected", snapshot.Height, "actual", resp.LastBlockHeight)
 		return 0, errVerifyFailed
 	}
-	s.logger.Info("Verified ABCI app", "height", snapshot.Height,
-		"appHash", fmt.Sprintf("%X", snapshot.trustedAppHash))
+
+	s.logger.Info("Verified ABCI app", "height", snapshot.Height, "appHash", snapshot.trustedAppHash)
 	return resp.AppVersion, nil
 }

test/maverick/consensus/replay.go

@@ -255,7 +255,7 @@ func (h *Handshaker) Handshake(proxyApp proxy.AppConns) error {
 
 	h.logger.Info("ABCI Handshake App Info",
 		"height", blockHeight,
-		"hash", fmt.Sprintf("%X", appHash),
+		"hash", appHash,
 		"software-version", res.Version,
 		"protocol-version", res.AppVersion,
 	)
@@ -272,7 +272,7 @@ func (h *Handshaker) Handshake(proxyApp proxy.AppConns) error {
 	}
 
 	h.logger.Info("Completed ABCI Handshake - Tendermint and App are synced",
-		"appHeight", blockHeight, "appHash", fmt.Sprintf("%X", appHash))
+		"appHeight", blockHeight, "appHash", appHash)
 
 	// TODO: (on restart) replay mempool