Log/LogTrie processing panic #161

New Issue

i-norden · 2021-11-29T06:23:42Z

i-norden commented

2021-11-29 06:23:42 +00:00

On mainnet data we sometimes run into blocks where the log/logTrie processing causes the below panic. Infrequent enough to have not caught in our unit tests/earlier trial runs, but often enough to be a major issue with the current production deployment.

panic: runtime error: index out of range [1] with length 1

goroutine 1 [running]:
github.com/ethereum/go-ethereum/statediff/indexer/database/file.(*StateDiffIndexer).processReceiptsAndTxs(0xc00169fec0, 0xc0aaff1360, 0x42, 0xc0ab9810a0, 0xc0a9a34a00, 0x93, 0x93, 0xc0a9a34500, 0x93, 0x93, ...)                                                                                  
        /go/pkg/mod/github.com/vulcanize/go-ethereum@v1.10.11-statediff-0.0.27e/statediff/indexer/database/file/indexer.go:347 +0x174e
github.com/ethereum/go-ethereum/statediff/indexer/database/file.(*StateDiffIndexer).PushBlock(0xc00169fec0, 0xc0ab0be000, 0xc0a9a34a00, 0x93, 0x93, 0xc0ab0f2d20, 0x53d68d, 0x93, 0x0, 0x0)                                                                                                         
        /go/pkg/mod/github.com/vulcanize/go-ethereum@v1.10.11-statediff-0.0.27e/statediff/indexer/database/file/indexer.go:165 +0xfbc
github.com/vulcanize/eth-statediff-service/pkg.(*Service).writeStateDiff(0xc000c8b5c0, 0xc0ab0be000, 0xaffe16f90a9292c1, 0x299fc7f29c987b94, 0xf558386f7b3133aa, 0x67e72fbc2abd72bd, 0x10101010101, 0x1941188, 0x0, 0x0, ...)                                                                       
        /go/src/github.com/vulcanize/eth-statediff-service/pkg/service.go:376 +0x24e
github.com/vulcanize/eth-statediff-service/pkg.(*Service).WriteStateDiffAt(0xc000c8b5c0, 0xc50fe8, 0x10101010101, 0x1941188, 0x0, 0x0, 0x1941188, 0x0, 0x0, 0x0, ...)                                                                                                                               
        /go/src/github.com/vulcanize/eth-statediff-service/pkg/service.go:331 +0x1d5
github.com/vulcanize/eth-statediff-service/pkg.(*Service).Run(0xc000c8b5c0, 0x0, 0x0, 0x0, 0x1, 0x0)
        /go/src/github.com/vulcanize/eth-statediff-service/pkg/service.go:125 +0xbd
github.com/vulcanize/eth-statediff-service/cmd.serve()
        /go/src/github.com/vulcanize/eth-statediff-service/cmd/serve.go:60 +0x16b
github.com/vulcanize/eth-statediff-service/cmd.glob..func1(0x1881ca0, 0xc000276310, 0x0, 0x7)
        /go/src/github.com/vulcanize/eth-statediff-service/cmd/serve.go:42 +0xd8
github.com/spf13/cobra.(*Command).execute(0x1881ca0, 0xc0002762a0, 0x7, 0x7, 0x1881ca0, 0xc0002762a0)
        /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:854 +0x2c2
github.com/spf13/cobra.(*Command).ExecuteC(0x1881a00, 0x200000004, 0xc0005c1f58, 0x1)
        /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:958 +0x375
github.com/spf13/cobra.(*Command).Execute(...)
        /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:895
github.com/vulcanize/eth-statediff-service/cmd.Execute()
        /go/src/github.com/vulcanize/eth-statediff-service/cmd/root.go:53 +0x85
main.main()
        /go/src/github.com/vulcanize/eth-statediff-service/main.go:21 +0x25

On mainnet data we sometimes run into blocks where the log/logTrie processing causes the below panic. Infrequent enough to have not caught in our unit tests/earlier trial runs, but often enough to be a major issue with the current production deployment. ``` panic: runtime error: index out of range [1] with length 1 goroutine 1 [running]: github.com/ethereum/go-ethereum/statediff/indexer/database/file.(*StateDiffIndexer).processReceiptsAndTxs(0xc00169fec0, 0xc0aaff1360, 0x42, 0xc0ab9810a0, 0xc0a9a34a00, 0x93, 0x93, 0xc0a9a34500, 0x93, 0x93, ...) /go/pkg/mod/github.com/vulcanize/go-ethereum@v1.10.11-statediff-0.0.27e/statediff/indexer/database/file/indexer.go:347 +0x174e github.com/ethereum/go-ethereum/statediff/indexer/database/file.(*StateDiffIndexer).PushBlock(0xc00169fec0, 0xc0ab0be000, 0xc0a9a34a00, 0x93, 0x93, 0xc0ab0f2d20, 0x53d68d, 0x93, 0x0, 0x0) /go/pkg/mod/github.com/vulcanize/go-ethereum@v1.10.11-statediff-0.0.27e/statediff/indexer/database/file/indexer.go:165 +0xfbc github.com/vulcanize/eth-statediff-service/pkg.(*Service).writeStateDiff(0xc000c8b5c0, 0xc0ab0be000, 0xaffe16f90a9292c1, 0x299fc7f29c987b94, 0xf558386f7b3133aa, 0x67e72fbc2abd72bd, 0x10101010101, 0x1941188, 0x0, 0x0, ...) /go/src/github.com/vulcanize/eth-statediff-service/pkg/service.go:376 +0x24e github.com/vulcanize/eth-statediff-service/pkg.(*Service).WriteStateDiffAt(0xc000c8b5c0, 0xc50fe8, 0x10101010101, 0x1941188, 0x0, 0x0, 0x1941188, 0x0, 0x0, 0x0, ...) /go/src/github.com/vulcanize/eth-statediff-service/pkg/service.go:331 +0x1d5 github.com/vulcanize/eth-statediff-service/pkg.(*Service).Run(0xc000c8b5c0, 0x0, 0x0, 0x0, 0x1, 0x0) /go/src/github.com/vulcanize/eth-statediff-service/pkg/service.go:125 +0xbd github.com/vulcanize/eth-statediff-service/cmd.serve() /go/src/github.com/vulcanize/eth-statediff-service/cmd/serve.go:60 +0x16b github.com/vulcanize/eth-statediff-service/cmd.glob..func1(0x1881ca0, 0xc000276310, 0x0, 0x7) /go/src/github.com/vulcanize/eth-statediff-service/cmd/serve.go:42 +0xd8 github.com/spf13/cobra.(*Command).execute(0x1881ca0, 0xc0002762a0, 0x7, 0x7, 0x1881ca0, 0xc0002762a0) /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:854 +0x2c2 github.com/spf13/cobra.(*Command).ExecuteC(0x1881a00, 0x200000004, 0xc0005c1f58, 0x1) /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:958 +0x375 github.com/spf13/cobra.(*Command).Execute(...) /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:895 github.com/vulcanize/eth-statediff-service/cmd.Execute() /go/src/github.com/vulcanize/eth-statediff-service/cmd/root.go:53 +0x85 main.main() /go/src/github.com/vulcanize/eth-statediff-service/main.go:21 +0x25 ```

i-norden commented

2021-12-02 07:17:59 +00:00

The bug we are running into is due to this optimization in Ethereum’s modified merle Patricia trie where if a “leaf node” (partial path + RLP encoding of the value it stores) is less than or equal to 32 bytes in size (the size of a keccak256 hash) then its parent branch node will store it directly in one of its 16 hex slots rather than it existing as a distinct leaf node referenced by a hash in that hex slot. In this case there is a leaf value but it is not stored in a distinct leaf node and can't be associated with a leaf key.

This can also occur, and often does, in the storage trie where contract variables can be less than 32 bytes in length. It can’t occur in the state trie because an RLP encoded account is always greater than 32 bytes even when it is empty. Nor can it occur in the tx or rct tries as txs and rcts always encode to >32 bytes.

We aren’t properly accounting for this in the new LogTrie (which doesn’t exist in canonical Ethereum data structures). Somewhat rarely, contracts will emit event logs that don’t contain any topics or data, the log only contains a 20 byte address. If the partial path for the node in the trie is <= 12 bytes then the “leaf node” is <= 32 bytes and will be stored in its parent branch node. When this happens, the number of leaf nodes in the trie does not match the number of logs (hence the panic on out-of-bounds where we expected them to match), and it is not possible to associate the eth.log_cids entry with a leaf_cid/leaf_mh_key (the association becomes nonsensical).

The bug we are running into is due to this optimization in Ethereum’s modified merle Patricia trie where if a “leaf node” (partial path + RLP encoding of the value it stores) is less than or equal to 32 bytes in size (the size of a keccak256 hash) then its parent branch node will store it directly in one of its 16 hex slots rather than it existing as a distinct leaf node referenced by a hash in that hex slot. In this case there is a leaf value but it is not stored in a distinct leaf node and can't be associated with a leaf key. This can also occur, and often does, in the storage trie where contract variables can be less than 32 bytes in length. It can’t occur in the state trie because an RLP encoded account is always greater than 32 bytes even when it is empty. Nor can it occur in the tx or rct tries as txs and rcts always encode to >32 bytes. We aren’t properly accounting for this in the new LogTrie (which doesn’t exist in canonical Ethereum data structures). Somewhat rarely, contracts will emit event logs that don’t contain any topics or data, the log only contains a 20 byte address. If the partial path for the node in the trie is <= 12 bytes then the “leaf node” is <= 32 bytes and will be stored in its parent branch node. When this happens, the number of leaf nodes in the trie does not match the number of logs (hence the panic on out-of-bounds where we expected them to match), and it is not possible to associate the eth.log_cids entry with a leaf_cid/leaf_mh_key (the association becomes nonsensical).

Sign in to join this conversation.

No Milestone

No project

No Assignees

1 Participants

Notifications

Due Date

The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: cerc-io/go-ethereum#161