From d76add65a66635f2c97374605bb85a4f6415acff Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Mon, 25 Jan 2021 16:25:29 +0400 Subject: [PATCH] libs/log: format []byte as hexidecimal string (uppercased) (#5960) Closes: #5806 Co-authored-by: Lanie Hei --- consensus/replay.go | 4 +- libs/bytes/bytes.go | 7 +++- libs/bytes/bytes_test.go | 9 +++- libs/log/tm_logger.go | 5 ++- libs/log/tm_logger_test.go | 69 +++++++++++++++++++++++++++++++ libs/log/tmfmt_logger.go | 7 ++++ libs/log/tmfmt_logger_test.go | 6 +++ light/client.go | 28 ++++++------- mempool/clist_mempool.go | 6 +-- state/execution.go | 2 +- statesync/syncer.go | 22 +++++----- test/maverick/consensus/replay.go | 4 +- 12 files changed, 130 insertions(+), 39 deletions(-) diff --git a/consensus/replay.go b/consensus/replay.go index 9e393fbda..6f4dabdcb 100644 --- a/consensus/replay.go +++ b/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 diff --git a/libs/bytes/bytes.go b/libs/bytes/bytes.go index fd27cf33f..d154f7b71 100644 --- a/libs/bytes/bytes.go +++ b/libs/bytes/bytes.go @@ -8,7 +8,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 var ( @@ -58,7 +58,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 } @@ -67,6 +67,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': diff --git a/libs/bytes/bytes_test.go b/libs/bytes/bytes_test.go index 6205beec2..db882f1c1 100644 --- a/libs/bytes/bytes_test.go +++ b/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) + } +} diff --git a/libs/log/tm_logger.go b/libs/log/tm_logger.go index 75273f88c..7c106336c 100644 --- a/libs/log/tm_logger.go +++ b/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 diff --git a/libs/log/tm_logger_test.go b/libs/log/tm_logger_test.go index 92fbe40eb..cbe29d994 100644 --- a/libs/log/tm_logger_test.go +++ b/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) } diff --git a/libs/log/tmfmt_logger.go b/libs/log/tmfmt_logger.go index 9519fd310..c6004cc62 100644 --- a/libs/log/tmfmt_logger.go +++ b/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 diff --git a/libs/log/tmfmt_logger_test.go b/libs/log/tmfmt_logger_test.go index be87432a1..955a9e405 100644 --- a/libs/log/tmfmt_logger_test.go +++ b/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) { diff --git a/light/client.go b/light/client.go index 3b54c48a9..04f9653fc 100644 --- a/light/client.go +++ b/light/client.go @@ -286,7 +286,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)", @@ -310,7 +310,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?", @@ -425,7 +425,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 } @@ -450,7 +450,7 @@ func (c *Client) VerifyLightBlockAtHeight(ctx context.Context, height int64, now // Check if the light block is 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 } @@ -508,7 +508,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 } @@ -526,7 +526,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 @@ -607,9 +607,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) @@ -698,9 +698,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) @@ -920,9 +920,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, "primary", c.primary) if replaceErr := c.replacePrimaryProvider(); replaceErr != nil { @@ -1033,7 +1033,3 @@ and remove witness. Otherwise, use the different primary`, e.WitnessIndex), "wit return nil } - -func hash2str(hash []byte) string { - return fmt.Sprintf("%X", hash) -} diff --git a/mempool/clist_mempool.go b/mempool/clist_mempool.go index 5e610ed4b..f9ef9ae23 100644 --- a/mempool/clist_mempool.go +++ b/mempool/clist_mempool.go @@ -776,7 +776,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() } diff --git a/state/execution.go b/state/execution.go index b8054fde2..3450b60dc 100644 --- a/state/execution.go +++ b/state/execution.go @@ -238,7 +238,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. diff --git a/statesync/syncer.go b/statesync/syncer.go index f87129c87..425705cb1 100644 --- a/statesync/syncer.go +++ b/statesync/syncer.go @@ -114,7 +114,7 @@ func (s *syncer) AddSnapshot(peerID p2p.NodeID, 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 } @@ -184,18 +184,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) @@ -203,7 +203,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) s.logger.Info("Snapshot sender rejected", "peer", peer) @@ -280,7 +280,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 } @@ -289,7 +289,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(context.Background(), abci.RequestOfferSnapshot{ Snapshot: &abci.Snapshot{ Height: snapshot.Height, @@ -306,7 +306,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 @@ -453,8 +453,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 } @@ -467,6 +467,6 @@ func (s *syncer) verifyApp(snapshot *snapshot) (uint64, error) { 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 } diff --git a/test/maverick/consensus/replay.go b/test/maverick/consensus/replay.go index 9e393fbda..6f4dabdcb 100644 --- a/test/maverick/consensus/replay.go +++ b/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