From 0bbc2f4a02255b3e13cec4d1f4430c8710d16faa Mon Sep 17 00:00:00 2001 From: lklimek <842586+lklimek@users.noreply.github.com> Date: Mon, 18 Mar 2024 19:16:22 +0100 Subject: [PATCH] fix(types: don't log all txs in block (#764) --- libs/log/testing.go | 10 ++++++++++ types/block.go | 7 +++---- types/block_test.go | 31 +++++++++++++++++++++++++++++++ types/tx.go | 17 +++++++++++++---- 4 files changed, 57 insertions(+), 8 deletions(-) diff --git a/libs/log/testing.go b/libs/log/testing.go index f7e0b47f19..f25e3c5815 100644 --- a/libs/log/testing.go +++ b/libs/log/testing.go @@ -118,6 +118,16 @@ func (tw *TestingLogger) AssertMatch(re *regexp.Regexp) { tw.Logger = tw.Logger.Level(zerolog.DebugLevel) } +// AssertContains defines assertions to check for each subsequent +// log item. It must be called before the log is generated. +// Assertion will pass if at least one log contains `s`. +// +// Note that assertions are only executed on logs matching defined log level. +// Use NewTestingLoggerWithLevel(t, zerolog.LevelDebugValue) to control this. +func (tw *TestingLogger) AssertContains(s string) { + tw.AssertMatch(regexp.MustCompile(regexp.QuoteMeta(s))) +} + // Run implements zerolog.Hook. // Execute all log assertions against a message. func (tw *TestingLogger) checkAssertions(msg string) { diff --git a/types/block.go b/types/block.go index 6da8e57911..0cd4c5b67d 100644 --- a/types/block.go +++ b/types/block.go @@ -303,9 +303,9 @@ func (b *Block) MarshalZerologObject(e *zerolog.Event) { e.Interface("header", b.Header) e.Interface("core_chain_lock", b.CoreChainLock) - e.Interface("data", b.Data) + e.Object("data", &b.Data) e.Interface("evidence", b.Evidence) - e.Interface("last_commit", b.LastCommit) + e.Object("last_commit", b.LastCommit) } // FromProto sets a protobuf Block to the given pointer. @@ -1062,8 +1062,7 @@ func (data *Data) MarshalZerologObject(e *zerolog.Event) { e.Bool("nil", false) e.Str("hash", data.Hash().ShortString()) - e.Int("num_txs", len(data.Txs)) - e.Array("txs", &data.Txs) + e.Object("txs", data.Txs) } // DataFromProto takes a protobuf representation of Data & diff --git a/types/block_test.go b/types/block_test.go index 743237f491..d7b263ab86 100644 --- a/types/block_test.go +++ b/types/block_test.go @@ -22,6 +22,7 @@ import ( "github.com/dashpay/tenderdash/crypto/bls12381" "github.com/dashpay/tenderdash/crypto/merkle" tmbytes "github.com/dashpay/tenderdash/libs/bytes" + "github.com/dashpay/tenderdash/libs/log" tmrand "github.com/dashpay/tenderdash/libs/rand" tmtime "github.com/dashpay/tenderdash/libs/time" tmproto "github.com/dashpay/tenderdash/proto/tendermint/types" @@ -213,6 +214,36 @@ func TestBlockSize(t *testing.T) { } } +// Given a block with more than `maxLoggedTxs` transactions, +// when we marshal it for logging, +// then we should see short hashes of the first `maxLoggedTxs` transactions in the log message, ending with "..." +func TestBlockMarshalZerolog(t *testing.T) { + ctx := context.Background() + logger := log.NewTestingLogger(t) + + txs := make(Txs, 0, 2*maxLoggedTxs) + expectTxs := make(Txs, 0, maxLoggedTxs) + for i := 0; i < 2*maxLoggedTxs; i++ { + txs = append(txs, Tx(fmt.Sprintf("tx%d", i))) + if i < maxLoggedTxs { + expectTxs = append(expectTxs, txs[i]) + } + } + + block := MakeBlock(1, txs, randCommit(ctx, t, 1, RandStateID()), nil) + + // define assertions + expected := fmt.Sprintf(",\"txs\":{\"num_txs\":%d,\"hashes\":[", 2*maxLoggedTxs) + for i := 0; i < maxLoggedTxs; i++ { + expected += "\"" + expectTxs[i].Hash().ShortString() + "\"," + } + expected += "\"...\"]}" + logger.AssertContains(expected) + + // execute test + logger.Info("test block", "block", block) +} + func TestBlockString(t *testing.T) { assert.Equal(t, "nil-Block", (*Block)(nil).String()) assert.Equal(t, "nil-Block", (*Block)(nil).StringIndented("")) diff --git a/types/tx.go b/types/tx.go index 60ddb4e91f..27688ea9f5 100644 --- a/types/tx.go +++ b/types/tx.go @@ -16,6 +16,9 @@ import ( tmproto "github.com/dashpay/tenderdash/proto/tendermint/types" ) +// maxLoggedTxs is the maximum number of transactions to log in a Txs object. +const maxLoggedTxs = 20 + // Tx is an arbitrary byte array. // NOTE: Tx has no types at this level, so when wire encoded it's just length-prefixed. // Might we want types here ? @@ -105,20 +108,26 @@ func (txs Txs) ToSliceOfBytes() [][]byte { return txBzs } -func (txs *Txs) MarshalZerologArray(e *zerolog.Array) { +func (txs Txs) MarshalZerologArray(e *zerolog.Array) { if txs == nil { return } - for i, tx := range *txs { - e.Str(tx.Hash().ShortString()) - if i >= 20 { + for i, tx := range txs { + if i >= maxLoggedTxs { e.Str("...") return } + + e.Str(tx.Hash().ShortString()) } } +func (txs Txs) MarshalZerologObject(e *zerolog.Event) { + e.Int("num_txs", len(txs)) + e.Array("hashes", txs) +} + // TxRecordSet contains indexes into an underlying set of transactions. // These indexes are useful for validating and working with a list of TxRecords // from the PrepareProposal response.