From 2b8b7043dd5b2ee299586b5c10a2654aaed94c60 Mon Sep 17 00:00:00 2001 From: Chengxuan Xing Date: Wed, 13 Nov 2024 17:57:37 +0000 Subject: [PATCH 1/5] adding warning logs for rebuiding in memory chain Signed-off-by: Chengxuan Xing --- internal/ethereum/blocklistener.go | 10 ++++++-- internal/ethereum/event_enricher.go | 6 +++++ internal/ethereum/event_listener_test.go | 32 ++++++++++++++++++++++++ internal/msgs/en_error_messages.go | 1 + 4 files changed, 47 insertions(+), 2 deletions(-) diff --git a/internal/ethereum/blocklistener.go b/internal/ethereum/blocklistener.go index 7e9555f..3ac5950 100644 --- a/internal/ethereum/blocklistener.go +++ b/internal/ethereum/blocklistener.go @@ -381,8 +381,7 @@ func (bl *blockListener) handleNewBlock(mbi *minimalBlockInfo, addAfter *list.El // a recent block advertisement. So we need to work backwards to the last point of consistency with the current // chain and re-query the chain state from there. func (bl *blockListener) rebuildCanonicalChain() *list.Element { - - log.L(bl.ctx).Debugf("Rebuilding in-memory canonical chain") + log.L(bl.ctx).Warn("Rebuilding in-memory canonical chain") // If none of our blocks were valid, start from the first block number we've notified about previously lastValidBlock := bl.trimToLastValidBlock() @@ -452,10 +451,14 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInfo) { // First remove from the end until we get a block that matches the current un-cached query view from the chain lastElem := bl.canonicalChain.Back() + var startingNumber *int64 for lastElem != nil && lastElem.Value != nil { // Query the block that is no at this blockNumber currentViewBlock := lastElem.Value.(*minimalBlockInfo) + if startingNumber == nil { + startingNumber = ¤tViewBlock.number + } var freshBlockInfo *blockInfoJSONRPC var reason ffcapi.ErrorReason err := bl.c.retry.Do(bl.ctx, "rebuild listener canonical chain", func(_ int) (retry bool, err error) { @@ -481,7 +484,10 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf break } lastElem = lastElem.Prev() + } + if startingNumber != nil && lastValidBlock != nil && *startingNumber != lastValidBlock.number { + log.L(bl.ctx).Warnf("Trimmed canonical chain to from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) } return lastValidBlock } diff --git a/internal/ethereum/event_enricher.go b/internal/ethereum/event_enricher.go index fda38c2..b131155 100644 --- a/internal/ethereum/event_enricher.go +++ b/internal/ethereum/event_enricher.go @@ -21,7 +21,9 @@ import ( "context" "github.com/hyperledger/firefly-common/pkg/fftypes" + "github.com/hyperledger/firefly-common/pkg/i18n" "github.com/hyperledger/firefly-common/pkg/log" + "github.com/hyperledger/firefly-evmconnect/internal/msgs" "github.com/hyperledger/firefly-signer/pkg/abi" "github.com/hyperledger/firefly-signer/pkg/ethtypes" "github.com/hyperledger/firefly-transaction-manager/pkg/ffcapi" @@ -84,6 +86,10 @@ func (ee *eventEnricher) filterEnrichEthLog(ctx context.Context, f *eventFilter, } } + if blockNumber < 0 || transactionIndex < 0 || logIndex < 0 { + log.L(ctx).Errorf("Invalid block number, transaction index or log index for event '%s'", protoID) + return nil, matched, decoded, i18n.NewError(ctx, msgs.MsgInvalidProtocolID, protoID) + } signature := f.Signature return &ffcapi.Event{ ID: ffcapi.EventID{ diff --git a/internal/ethereum/event_listener_test.go b/internal/ethereum/event_listener_test.go index f94fd50..4c42e9f 100644 --- a/internal/ethereum/event_listener_test.go +++ b/internal/ethereum/event_listener_test.go @@ -484,6 +484,38 @@ func TestFilterEnrichEthLogMethodInputsOk(t *testing.T) { } +func TestFilterEnrichEthLogInvalidNegativeID(t *testing.T) { + + l, mRPC, _ := newTestListener(t, true) + + var abiEvent *abi.Entry + err := json.Unmarshal([]byte(abiTransferEvent), &abiEvent) + assert.NoError(t, err) + + mRPC.On("CallRPC", mock.Anything, mock.Anything, "eth_getBlockByHash", mock.MatchedBy(func(bh string) bool { + return bh == "0x6b012339fbb85b70c58ecfd97b31950c4a28bcef5226e12dbe551cb1abaf3b4c" + }), false).Return(nil).Run(func(args mock.Arguments) { + *args[1].(**blockInfoJSONRPC) = &blockInfoJSONRPC{ + Number: ethtypes.NewHexInteger64(1024), + } + }) + mRPC.On("CallRPC", mock.Anything, mock.Anything, "eth_getTransactionByHash", mock.MatchedBy(func(th ethtypes.HexBytes0xPrefix) bool { + return th.String() == "0x1a1f797ee000c529b6a2dd330cedd0d081417a30d16a4eecb3f863ab4657246f" + })).Return(nil).Run(func(args mock.Arguments) { + *args[1].(**txInfoJSONRPC) = &txInfoJSONRPC{ + From: ethtypes.MustNewAddress("0x3968ef051b422d3d1cdc182a88bba8dd922e6fa4"), + Input: ethtypes.MustNewHexBytes0xPrefix("0xa9059cbb000000000000000000000000d0f2f5103fd050739a9fb567251bc460cc24d09100000000000000000000000000000000000000000000000000000000000003e8"), + } + }).Once() + + ethLogWithNegativeLogIndex := sampleTransferLog() + ethLogWithNegativeLogIndex.LogIndex = ethtypes.NewHexInteger64(-1) + _, ok, err := l.filterEnrichEthLog(context.Background(), l.config.filters[0], l.config.options.Methods, ethLogWithNegativeLogIndex) // cache miss + assert.False(t, ok) + assert.Regexp(t, "FF23055", err) + +} + func TestFilterEnrichEthLogMethodInputsTxInfoWithErr(t *testing.T) { l, mRPC, _ := newTestListener(t, true) diff --git a/internal/msgs/en_error_messages.go b/internal/msgs/en_error_messages.go index 979a0f8..4f5d445 100644 --- a/internal/msgs/en_error_messages.go +++ b/internal/msgs/en_error_messages.go @@ -70,4 +70,5 @@ var ( MsgUnableToCallDebug = ffe("FF23052", "Failed to call debug_traceTransaction to get error detail: %s") MsgReturnValueNotDecoded = ffe("FF23053", "Error return value for custom error: %s") MsgReturnValueNotAvailable = ffe("FF23054", "Error return value unavailable") + MsgInvalidProtocolID = ffe("FF23055", "Invalid protocol ID in event log: %s") ) From 27463c26f3ea07b3e9356b0e39383e80492f8f43 Mon Sep 17 00:00:00 2001 From: Chengxuan Xing Date: Wed, 13 Nov 2024 17:59:59 +0000 Subject: [PATCH 2/5] Update internal/ethereum/blocklistener.go Signed-off-by: Chengxuan Xing --- internal/ethereum/blocklistener.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/ethereum/blocklistener.go b/internal/ethereum/blocklistener.go index 3ac5950..2b529c4 100644 --- a/internal/ethereum/blocklistener.go +++ b/internal/ethereum/blocklistener.go @@ -487,7 +487,7 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf } if startingNumber != nil && lastValidBlock != nil && *startingNumber != lastValidBlock.number { - log.L(bl.ctx).Warnf("Trimmed canonical chain to from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) + log.L(bl.ctx).Warnf("Trimming canonical chain to from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) } return lastValidBlock } From 8cac23cac1975d690e377abadbd3c1b0ae32742f Mon Sep 17 00:00:00 2001 From: Chengxuan Xing Date: Thu, 14 Nov 2024 08:53:44 +0000 Subject: [PATCH 3/5] adding more logs Signed-off-by: Chengxuan Xing --- internal/ethereum/blocklistener.go | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/internal/ethereum/blocklistener.go b/internal/ethereum/blocklistener.go index 2b529c4..2c89b06 100644 --- a/internal/ethereum/blocklistener.go +++ b/internal/ethereum/blocklistener.go @@ -381,14 +381,13 @@ func (bl *blockListener) handleNewBlock(mbi *minimalBlockInfo, addAfter *list.El // a recent block advertisement. So we need to work backwards to the last point of consistency with the current // chain and re-query the chain state from there. func (bl *blockListener) rebuildCanonicalChain() *list.Element { - log.L(bl.ctx).Warn("Rebuilding in-memory canonical chain") - // If none of our blocks were valid, start from the first block number we've notified about previously lastValidBlock := bl.trimToLastValidBlock() var nextBlockNumber int64 var expectedParentHash string if lastValidBlock != nil { nextBlockNumber = lastValidBlock.number + 1 + log.L(bl.ctx).Warnf("rebuildCanonicalChain partial rebuild from block %d", nextBlockNumber) expectedParentHash = lastValidBlock.hash } else { firstBlock := bl.canonicalChain.Front() @@ -396,6 +395,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { return nil } nextBlockNumber = firstBlock.Value.(*minimalBlockInfo).number + log.L(bl.ctx).Warnf("rebuildCanonicalChain brand new in-memory canonical chain from block %d", nextBlockNumber) // Clear out the whole chain bl.canonicalChain = bl.canonicalChain.Init() } @@ -413,7 +413,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { } } if bi == nil { - log.L(bl.ctx).Debugf("Block listener canonical chain view rebuilt to head at block %d", nextBlockNumber-1) + log.L(bl.ctx).Infof("rebuildCanonicalChain successfully rebuilt the chain to the head block %d", nextBlockNumber-1) break } mbi := &minimalBlockInfo{ @@ -425,7 +425,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { // It's possible the chain will change while we're doing this, and we fall back to the next block notification // to sort that out. if expectedParentHash != "" && mbi.parentHash != expectedParentHash { - log.L(bl.ctx).Debugf("Block listener canonical chain view rebuilt up to new re-org at block %d", nextBlockNumber) + log.L(bl.ctx).Warnf("rebuildCanonicalChain rebuild stopped at block: %d due to mismatch hash for parent block (%d): %s (expected: %s)", nextBlockNumber, nextBlockNumber-1, mbi.parentHash, expectedParentHash) break } expectedParentHash = mbi.hash @@ -458,10 +458,12 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf currentViewBlock := lastElem.Value.(*minimalBlockInfo) if startingNumber == nil { startingNumber = ¤tViewBlock.number + log.L(bl.ctx).Debugf("trimToLastValidBlock checking from last block: %d", startingNumber) } var freshBlockInfo *blockInfoJSONRPC var reason ffcapi.ErrorReason err := bl.c.retry.Do(bl.ctx, "rebuild listener canonical chain", func(_ int) (retry bool, err error) { + log.L(bl.ctx).Debugf("trimToLastValidBlock checking block: %d", currentViewBlock.number) freshBlockInfo, reason, err = bl.getBlockInfoByNumber(bl.ctx, currentViewBlock.number, false, "") return reason != ffcapi.ErrorReasonNotFound, err }) @@ -472,7 +474,7 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf } if freshBlockInfo != nil && freshBlockInfo.Hash.String() == currentViewBlock.hash { - log.L(bl.ctx).Debugf("Canonical chain matches current chain up to block %d", currentViewBlock.number) + log.L(bl.ctx).Debugf("trimToLastValidBlock found last valid block %d", currentViewBlock.number) lastValidBlock = currentViewBlock // Trim everything after this point, as it's invalidated nextElem := lastElem.Next() @@ -487,7 +489,7 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf } if startingNumber != nil && lastValidBlock != nil && *startingNumber != lastValidBlock.number { - log.L(bl.ctx).Warnf("Trimming canonical chain to from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) + log.L(bl.ctx).Debugf("trimToLastValidBlock trimmed canonical chain from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) } return lastValidBlock } From 8bbc81248d399c36cba400d3634cf79ec07e8d4f Mon Sep 17 00:00:00 2001 From: Chengxuan Xing Date: Thu, 14 Nov 2024 09:54:18 +0000 Subject: [PATCH 4/5] address review comments Signed-off-by: Chengxuan Xing --- internal/ethereum/blocklistener.go | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/internal/ethereum/blocklistener.go b/internal/ethereum/blocklistener.go index 2c89b06..ed7ac53 100644 --- a/internal/ethereum/blocklistener.go +++ b/internal/ethereum/blocklistener.go @@ -387,7 +387,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { var expectedParentHash string if lastValidBlock != nil { nextBlockNumber = lastValidBlock.number + 1 - log.L(bl.ctx).Warnf("rebuildCanonicalChain partial rebuild from block %d", nextBlockNumber) + log.L(bl.ctx).Infof("Block listener in-memory canonical chain partially rebuilding from block %d", nextBlockNumber) expectedParentHash = lastValidBlock.hash } else { firstBlock := bl.canonicalChain.Front() @@ -395,7 +395,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { return nil } nextBlockNumber = firstBlock.Value.(*minimalBlockInfo).number - log.L(bl.ctx).Warnf("rebuildCanonicalChain brand new in-memory canonical chain from block %d", nextBlockNumber) + log.L(bl.ctx).Warnf("Block listener in-memory canonical chain re-initialized at block %d", nextBlockNumber) // Clear out the whole chain bl.canonicalChain = bl.canonicalChain.Init() } @@ -413,7 +413,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { } } if bi == nil { - log.L(bl.ctx).Infof("rebuildCanonicalChain successfully rebuilt the chain to the head block %d", nextBlockNumber-1) + log.L(bl.ctx).Infof("Block listener in-memory canonical chain rebuilt the chain to the head block %d", nextBlockNumber-1) break } mbi := &minimalBlockInfo{ @@ -425,7 +425,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { // It's possible the chain will change while we're doing this, and we fall back to the next block notification // to sort that out. if expectedParentHash != "" && mbi.parentHash != expectedParentHash { - log.L(bl.ctx).Warnf("rebuildCanonicalChain rebuild stopped at block: %d due to mismatch hash for parent block (%d): %s (expected: %s)", nextBlockNumber, nextBlockNumber-1, mbi.parentHash, expectedParentHash) + log.L(bl.ctx).Infof("Block listener in-memory canonical chain rebuilding stopped at block: %d due to mismatch hash for parent block (%d): %s (expected: %s)", nextBlockNumber, nextBlockNumber-1, mbi.parentHash, expectedParentHash) break } expectedParentHash = mbi.hash @@ -458,12 +458,12 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf currentViewBlock := lastElem.Value.(*minimalBlockInfo) if startingNumber == nil { startingNumber = ¤tViewBlock.number - log.L(bl.ctx).Debugf("trimToLastValidBlock checking from last block: %d", startingNumber) + log.L(bl.ctx).Debugf("Block listener in-memory canonical chain checking from last block: %d", startingNumber) } var freshBlockInfo *blockInfoJSONRPC var reason ffcapi.ErrorReason err := bl.c.retry.Do(bl.ctx, "rebuild listener canonical chain", func(_ int) (retry bool, err error) { - log.L(bl.ctx).Debugf("trimToLastValidBlock checking block: %d", currentViewBlock.number) + log.L(bl.ctx).Debugf("Block listener in-memory canonical chain validating block: %d", currentViewBlock.number) freshBlockInfo, reason, err = bl.getBlockInfoByNumber(bl.ctx, currentViewBlock.number, false, "") return reason != ffcapi.ErrorReasonNotFound, err }) @@ -474,7 +474,7 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf } if freshBlockInfo != nil && freshBlockInfo.Hash.String() == currentViewBlock.hash { - log.L(bl.ctx).Debugf("trimToLastValidBlock found last valid block %d", currentViewBlock.number) + log.L(bl.ctx).Debugf("Block listener in-memory canonical chain found last valid block %d", currentViewBlock.number) lastValidBlock = currentViewBlock // Trim everything after this point, as it's invalidated nextElem := lastElem.Next() @@ -489,7 +489,7 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf } if startingNumber != nil && lastValidBlock != nil && *startingNumber != lastValidBlock.number { - log.L(bl.ctx).Debugf("trimToLastValidBlock trimmed canonical chain from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) + log.L(bl.ctx).Debugf("Block listener in-memory canonical chain trimmed from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) } return lastValidBlock } From 7914431426dde08a4edcf71cdaac6b85bc2dd63b Mon Sep 17 00:00:00 2001 From: Chengxuan Xing Date: Thu, 14 Nov 2024 09:59:59 +0000 Subject: [PATCH 5/5] shorten the prefix string Signed-off-by: Chengxuan Xing --- internal/ethereum/blocklistener.go | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/internal/ethereum/blocklistener.go b/internal/ethereum/blocklistener.go index ed7ac53..bf0b489 100644 --- a/internal/ethereum/blocklistener.go +++ b/internal/ethereum/blocklistener.go @@ -387,7 +387,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { var expectedParentHash string if lastValidBlock != nil { nextBlockNumber = lastValidBlock.number + 1 - log.L(bl.ctx).Infof("Block listener in-memory canonical chain partially rebuilding from block %d", nextBlockNumber) + log.L(bl.ctx).Infof("Canonical chain partially rebuilding from block %d", nextBlockNumber) expectedParentHash = lastValidBlock.hash } else { firstBlock := bl.canonicalChain.Front() @@ -395,7 +395,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { return nil } nextBlockNumber = firstBlock.Value.(*minimalBlockInfo).number - log.L(bl.ctx).Warnf("Block listener in-memory canonical chain re-initialized at block %d", nextBlockNumber) + log.L(bl.ctx).Warnf("Canonical chain re-initialized at block %d", nextBlockNumber) // Clear out the whole chain bl.canonicalChain = bl.canonicalChain.Init() } @@ -413,7 +413,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { } } if bi == nil { - log.L(bl.ctx).Infof("Block listener in-memory canonical chain rebuilt the chain to the head block %d", nextBlockNumber-1) + log.L(bl.ctx).Infof("Canonical chain rebuilt the chain to the head block %d", nextBlockNumber-1) break } mbi := &minimalBlockInfo{ @@ -425,7 +425,7 @@ func (bl *blockListener) rebuildCanonicalChain() *list.Element { // It's possible the chain will change while we're doing this, and we fall back to the next block notification // to sort that out. if expectedParentHash != "" && mbi.parentHash != expectedParentHash { - log.L(bl.ctx).Infof("Block listener in-memory canonical chain rebuilding stopped at block: %d due to mismatch hash for parent block (%d): %s (expected: %s)", nextBlockNumber, nextBlockNumber-1, mbi.parentHash, expectedParentHash) + log.L(bl.ctx).Infof("Canonical chain rebuilding stopped at block: %d due to mismatch hash for parent block (%d): %s (expected: %s)", nextBlockNumber, nextBlockNumber-1, mbi.parentHash, expectedParentHash) break } expectedParentHash = mbi.hash @@ -458,12 +458,12 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf currentViewBlock := lastElem.Value.(*minimalBlockInfo) if startingNumber == nil { startingNumber = ¤tViewBlock.number - log.L(bl.ctx).Debugf("Block listener in-memory canonical chain checking from last block: %d", startingNumber) + log.L(bl.ctx).Debugf("Canonical chain checking from last block: %d", startingNumber) } var freshBlockInfo *blockInfoJSONRPC var reason ffcapi.ErrorReason err := bl.c.retry.Do(bl.ctx, "rebuild listener canonical chain", func(_ int) (retry bool, err error) { - log.L(bl.ctx).Debugf("Block listener in-memory canonical chain validating block: %d", currentViewBlock.number) + log.L(bl.ctx).Debugf("Canonical chain validating block: %d", currentViewBlock.number) freshBlockInfo, reason, err = bl.getBlockInfoByNumber(bl.ctx, currentViewBlock.number, false, "") return reason != ffcapi.ErrorReasonNotFound, err }) @@ -474,7 +474,7 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf } if freshBlockInfo != nil && freshBlockInfo.Hash.String() == currentViewBlock.hash { - log.L(bl.ctx).Debugf("Block listener in-memory canonical chain found last valid block %d", currentViewBlock.number) + log.L(bl.ctx).Debugf("Canonical chain found last valid block %d", currentViewBlock.number) lastValidBlock = currentViewBlock // Trim everything after this point, as it's invalidated nextElem := lastElem.Next() @@ -489,7 +489,7 @@ func (bl *blockListener) trimToLastValidBlock() (lastValidBlock *minimalBlockInf } if startingNumber != nil && lastValidBlock != nil && *startingNumber != lastValidBlock.number { - log.L(bl.ctx).Debugf("Block listener in-memory canonical chain trimmed from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) + log.L(bl.ctx).Debugf("Canonical chain trimmed from block %d to block %d (total number of in memory blocks: %d)", startingNumber, lastValidBlock.number, bl.unstableHeadLength) } return lastValidBlock }