From 72851a12d38f2b190353679f20f0224d5f175419 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 | 24 +++++------ test/maverick/consensus/replay.go | 4 +- 12 files changed, 131 insertions(+), 40 deletions(-) diff --git a/consensus/replay.go b/consensus/replay.go index bfec9e96d..9fd59a40e 100644 --- a/consensus/replay.go +++ b/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 diff --git a/libs/bytes/bytes.go b/libs/bytes/bytes.go index 809049e84..be294de4e 100644 --- a/libs/bytes/bytes.go +++ b/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': 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 c271c790e..c758a2a6b 100644 --- a/light/client.go +++ 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) -} diff --git a/mempool/clist_mempool.go b/mempool/clist_mempool.go index e58a84df3..a82dfd181 100644 --- a/mempool/clist_mempool.go +++ b/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() } diff --git a/state/execution.go b/state/execution.go index 241c15e93..41fb248bd 100644 --- a/state/execution.go +++ b/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. diff --git a/statesync/syncer.go b/statesync/syncer.go index 8bf0f7f7b..e58837bb2 100644 --- a/statesync/syncer.go +++ b/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 } diff --git a/test/maverick/consensus/replay.go b/test/maverick/consensus/replay.go index 22709b6ab..227030595 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