GoQuorum PANIC After Restart Post Enabling --privatetriecache.enable

[frankie-lim-partior]

GoQuorum Version: 22.1.1
Tessera Version: 22.1.0

Issue Description:
After enabling private trie cache by setting --privatetriecache.enable (#1353) , GoQuorum Geth will panic and crash consistently after 2nd restart. 1st time startup with --privatetriecache.enable works fine with transaction able to be perform.

Step to reproduce

1. Run a network with GoQuorum Version: 22.1.1 WITHOUT --privatetriecache.enable. Confirm network working fine.
2. Add --privatetriecache.enable to geth command line and restart.
3. Confirm network working fine after restart and able to make transaction
4. Stop GoQuorum geth as usual.
5. Start GoQuorum geth as usual (also with --privatetriecache.enable)
6. GoQuorum Geth panic with following. Consistently repeatable. attached 4 set of

Q-22.1.1-private-trie-cache-crash-4.log
Q-22.1.1-private-trie-cache-crash-3.log
Q-22.1.1-private-trie-cache-crash-2.log
Q-22.1.1-private-trie-cache-crash-1.log

INFO [04-13|07:47:45.024] Starting pprof server                    addr=http://0.0.0.0:9545/debug/pprof
DEBUG[04-13|07:47:45.024] Sanitizing Go's GC trigger               percent=25
INFO [04-13|07:47:45.024] Enabling metrics collection
INFO [04-13|07:47:45.024] Connecting to private tx manager using HTTP
INFO [04-13|07:47:45.047] Tessera API version: 5.0
INFO [04-13|07:47:45.047] Target Private Tx Manager                name=Tessera distributionVersion=22.1.0
INFO [04-13|07:47:45.048] Maximum peer count                       ETH=100 LES=0 total=100
INFO [04-13|07:47:45.048] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
DEBUG[04-13|07:47:45.049] FS scan times                            list="27.46µs" set="2.283µs" diff="1.675µs"
TRACE[04-13|07:47:45.049] Handled keystore changes                 time="34.368µs"
TRACE[04-13|07:47:45.049] Started watching keystore folder         path=/etc/quorum/qdata/dd/keystore
WARN [04-13|07:47:45.049] Found deprecated node list file /etc/quorum/qdata/dd/static-nodes.json, please use the TOML config file instead.
INFO [04-13|07:47:45.050] Enabling recording of key preimages since archive mode is used
INFO [04-13|07:47:45.050] Global gas cap disabled
INFO [04-13|07:47:45.050] Connecting to private tx manager using HTTP
INFO [04-13|07:47:45.067] Tessera API version: 5.0
INFO [04-13|07:47:45.067] Target Private Tx Manager                name=Tessera distributionVersion=22.1.0
INFO [04-13|07:47:45.067] Allocated trie memory caches             clean=614.00MiB dirty=1024.00MiB
INFO [04-13|07:47:45.067] Allocated cache and file handles         database=/etc/quorum/qdata/dd/geth/chaindata cache=2.00GiB handles=524288
DEBUG[04-13|07:47:45.092] Chain freezer table opened               database=/etc/quorum/qdata/dd/geth/chaindata/ancient table=receipts items=0 size=0.00B
DEBUG[04-13|07:47:45.092] Chain freezer table opened               database=/etc/quorum/qdata/dd/geth/chaindata/ancient table=diffs    items=0 size=0.00B
DEBUG[04-13|07:47:45.092] Chain freezer table opened               database=/etc/quorum/qdata/dd/geth/chaindata/ancient table=headers  items=0 size=0.00B
DEBUG[04-13|07:47:45.092] Chain freezer table opened               database=/etc/quorum/qdata/dd/geth/chaindata/ancient table=hashes   items=0 size=0.00B
DEBUG[04-13|07:47:45.092] Chain freezer table opened               database=/etc/quorum/qdata/dd/geth/chaindata/ancient table=bodies   items=0 size=0.00B
INFO [04-13|07:47:45.092] Opened ancient database                  database=/etc/quorum/qdata/dd/geth/chaindata/ancient
DEBUG[04-13|07:47:45.093] Current full block not old enough        number=885 hash="b7723c…060928" delay=3162240
DEBUG[04-13|07:47:45.093] Account Extra Data root                  hash="000000…000000"
INFO [04-13|07:47:45.093] Initialised chain configuration          config="{ChainID: 2004 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 IsQuorum: true Constantinople: 0 TransactionSizeLimit: 64 MaxCodeSize: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: <nil>, Berlin: <nil> YOLO v3: <nil> PrivacyEnhancements: <nil> PrivacyPrecompile: <nil> Engine: istanbul}"
INFO [04-13|07:47:45.093] Initialising Ethereum protocol           network=2004 dbversion=8
INFO [04-13|07:47:45.093] Initialising Quorum consensus protocol   name=istanbul versions="[100 99 64]" network=2004 dbversion=8
INFO [04-13|07:47:45.094] Using UnifiedCacheProvider.
WARN [04-13|07:47:45.094] Head private state missing, resetting chain number=885 hash="b7723c…060928"
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0xceebf4]

goroutine 1 [running]:
github.com/ethereum/go-ethereum/core/types.(*Block).NumberU64(...)
	github.com/ethereum/go-ethereum/core/types/block.go:329
github.com/ethereum/go-ethereum/core.(*BlockChain).SetHeadBeyondRoot(0xc000148c80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	github.com/ethereum/go-ethereum/core/blockchain.go:679 +0x1f4
github.com/ethereum/go-ethereum/core.(*BlockChain).SetHead(0xc000148c80, 0x0, 0xc000647030, 0xc0004c4ee0)
	github.com/ethereum/go-ethereum/core/blockchain.go:553 +0x45
github.com/ethereum/go-ethereum/core.(*BlockChain).ResetWithGenesisBlock(0xc000148c80, 0xc0004bec60, 0x0, 0x0)
	github.com/ethereum/go-ethereum/core/blockchain.go:826 +0x67
github.com/ethereum/go-ethereum/core.(*BlockChain).Reset(0xc000148c80, 0x1830b28, 0x2b)
	github.com/ethereum/go-ethereum/core/blockchain.go:819 +0x37
github.com/ethereum/go-ethereum/core.(*BlockChain).loadLastState(0xc000148c80, 0x17b6600, 0x0)
	github.com/ethereum/go-ethereum/core/blockchain.go:505 +0x14ff
github.com/ethereum/go-ethereum/core.NewBlockChain(0x1ac7dc8, 0xc00000e138, 0xc00037c410, 0xc0004feea0, 0x1ac4a20, 0xc00015a3c0, 0x0, 0x0, 0x0, 0x0, ...)
	github.com/ethereum/go-ethereum/core/blockchain.go:303 +0x8a5
github.com/ethereum/go-ethereum/eth.New(0xc0001b8820, 0xc000122700, 0x0, 0x0, 0x0)
	github.com/ethereum/go-ethereum/eth/backend.go:236 +0xde5
github.com/ethereum/go-ethereum/cmd/utils.RegisterEthService(0xc0001b8820, 0xc000122700, 0x0, 0x700, 0x0)
	github.com/ethereum/go-ethereum/cmd/utils/flags.go:1988 +0x225
main.makeFullNode(0xc000445600, 0x7, 0xc, 0xc000134010)
	github.com/ethereum/go-ethereum/cmd/geth/config.go:164 +0x176
main.geth(0xc000445600, 0x0, 0x0)
	github.com/ethereum/go-ethereum/cmd/geth/main.go:378 +0xf4
gopkg.in/urfave/cli%2ev1.HandleAction(0x1564c20, 0x1904008, 0xc000445600, 0xc00046a720, 0x0)
	gopkg.in/urfave/[email protected]/app.go:490 +0x82
gopkg.in/urfave/cli%2ev1.(*App).Run(0xc0002fd520, 0xc000138000, 0x56, 0x58, 0x0, 0x0)
	gopkg.in/urfave/[email protected]/app.go:264 +0x5f5
main.main()
	github.com/ethereum/go-ethereum/cmd/geth/main.go:299 +0x55

[baptiste-b-pegasys]

Hello, thank you for raising this.
My analysis is that without the option, we commit the private state at every block, whereas the public state is committed every hour.
With the option, both public and private state are committed at same time every hour.
Normally this would not be a problem because anyway when the public state exists, the private is always here.

When we kill abruptly (SIGKILL) the state is not saved, so a reset will occur at the next restart.

Here I propose a fix, I tested locally, but I think the node is kinda locked and need a restart to make a proper reset.

Would you mind to test ghcr.io/baptiste-b-pegasys/quorum:npe-private-state-cache and give me your impression?
Thank you

[frankie-lim-partior]

Thanks. Will test and revert

[frankie-lim-partior]

@baptiste-b-pegasys Your test build ghcr.io/baptiste-b-pegasys/quorum:npe-private-state-cache seems to be on a wrong baseline version 1.9.23-stable-0f56bd31(quorum-v21.4.2) . As such it did not allow me to set the flag

Incorrect Usage. flag provided but not defined: -privatetriecache.enable

[baptiste-b-pegasys]

@frankie-lim-sweeho sorry I made a mistake somewhere.
I rebased my branch for this image : ghcr.io/baptiste-b-pegasys/quorum:fix-npe

[frankie-lim-partior]

@baptiste-b-pegasys I have tested with the test build and confirmed it no longer panic are restart. Log attached incase u need.

Thanks!

private-cache-restart.log.zip