panic in WriteBlockWithState for very long low-td sidechain eventually beating canon chain

[ryanschneider]

System information

Geth version: 1.8.22
OS & Version: Linux

Backtrace

INFO [01-31|20:34:43.732] Imported new chain segment               blocks=2048 txs=88    mgas=18.425   elapsed=819.636ms mgasps=22.480  number=819200 hash=341128…
INFO [01-31|20:34:43.815] Importing heavy sidechain segment        blocks=2048 start=819201 end=821248
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x1c0 pc=0x89e95a]
goroutine 359309 [running]:
github.com/ethereum/go-ethereum/core.(*BlockChain).WriteBlockWithState(0xc010364000, 0xc0f02a4090, 0x0, 0x0, 0x0, 0xc06916a0d0, 0x0, 0x0, 0x0)
        /ext-go/1/src/github.com/ethereum/go-ethereum/core/blockchain.go:976 +0xe7a
github.com/ethereum/go-ethereum/core.(*BlockChain).insertChain(0xc010364000, 0xc060afc000, 0x800, 0x900, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /ext-go/1/src/github.com/ethereum/go-ethereum/core/blockchain.go:1215 +0xcf7
github.com/ethereum/go-ethereum/core.(*BlockChain).insertSidechain(0xc010364000, 0xc06d5136a0, 0xc0000c30b0, 0xc0000c3001, 0x800, 0x800, 0xc0622aa000, 0x800, 0x80
        /ext-go/1/src/github.com/ethereum/go-ethereum/core/blockchain.go:1369 +0x1a3f
github.com/ethereum/go-ethereum/core.(*BlockChain).insertChain(0xc010364000, 0xc06b0b0000, 0x800, 0x800, 0x45beb41b51182401, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /ext-go/1/src/github.com/ethereum/go-ethereum/core/blockchain.go:1139 +0x2e15
github.com/ethereum/go-ethereum/core.(*BlockChain).InsertChain(0xc010364000, 0xc06b0b0000, 0x800, 0x800, 0x0, 0x0, 0x0)
        /ext-go/1/src/github.com/ethereum/go-ethereum/core/blockchain.go:1088 +0xb89
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).importBlockResults(0xc00020a820, 0xc06c0d6000, 0x800, 0x800, 0x800, 0x0)
        /ext-go/1/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:1490 +0x40e
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).processFullSyncContent(0xc00020a820, 0x0, 0xc000051798)
        /ext-go/1/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:1464 +0x79
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).processFullSyncContent-fm(0xc000000008, 0x1027608)
        /ext-go/1/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:479 +0x2a
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).spawnSync.func1(0xc00020a820, 0xc034737620, 0xc01073fe60)
        /ext-go/1/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:491 +0x59
created by github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).spawnSync
        /ext-go/1/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:491 +0xaf

The implication is that header is nil, which seems possible GetHeaderByNumber() returns nil if rawdb.ReadCanonicalHash()` returns an empty hash.

			// Find the next state trie we need to commit
			header := bc.GetHeaderByNumber(current - triesInMemory)
			chosen := header.Number.Uint64()  //header can be nil here

But, I'm not sure what err would be best to return in that case.

[holiman]

Seems like when importing a large sidechain, it tries to do pruning, and goes to collect the canonical head at block N-128. If N is way ahead of the canon chain, it becomes nil. So it seems that the sidechain has not (yet) switched over as the canonical chain. Still investigating ...

[holiman]

@ryanschneider do you have any more logs preceding the lines in the report? Would be interesting to see where the canon chain was at when this happened

[ryanschneider]

I'll try to grab some logs today, should still have them. BTW I only saw this on one or two nodes, so doesn't seem too pervasive but wanted to get the stack trace down in case it hints to a bigger underlaying issue.

[ryanschneider]

Ok here's the parts of systemd journal leading up to the SIGSEGV:
ropsten-nil.log

I also kept some of the log lines of after the restart, since afterwards the node kept hitting this error during syncing, which slowed it down considerably:

Jan 31 20:35:55 ip-10-0-25-83 geth[26789]: WARN [01-31|20:35:55.108] Synchronisation failed, dropping peer    peer=4e011cb2992bd7b5 err="retrieved ancestor is invalid"
Jan 31 20:35:58 ip-10-0-25-83 geth[26789]: WARN [01-31|20:35:58.413] Synchronisation failed, dropping peer    peer=c7e7675577416d6b err="action from bad peer ignored"
Jan 31 20:36:51 ip-10-0-25-83 geth[26789]: WARN [01-31|20:36:51.717] Ancestor below allowance                 peer=4e011cb2992bd7b5 number=730841 hash=000000…000000 allowance=730841

I don't think it's related, but wanted to include it just in case.

[holiman]

Thanks, that really helps!

Snippets from the logs

Jan 31 19:46:26  geth[9939]: INFO [01-31|19:46:26.187] Imported new state entries               count=1616 elapsed=7.919ms   processed=4575299 pending=2918  retry=0   duplicate=8 unexpected=922
Jan 31 19:46:26  geth[9939]: INFO [01-31|19:46:26.870] Imported new state entries               count=2303 elapsed=14.745ms  processed=4577602 pending=80    retry=2   duplicate=8 unexpected=922
Jan 31 19:46:28  geth[9939]: INFO [01-31|19:46:28.347] Imported new state entries               count=126  elapsed=1.269ms   processed=4577728 pending=0     retry=0   duplicate=8 unexpected=922
Jan 31 19:46:28  geth[9939]: INFO [01-31|19:46:28.347] Imported new block receipts              count=1    elapsed=128.03µs  number=820714 hash=effcbd…45a957 age=28m17s    size=4.00B
Jan 31 19:46:28  geth[9939]: INFO [01-31|19:46:28.348] Committed new head block                 number=820714 hash=effcbd…45a957
Jan 31 19:46:28  geth[9939]: INFO [01-31|19:46:28.384] Imported new chain segment               blocks=108 txs=0 mgas=0.000 elapsed=35.551ms  mgasps=0.000 number=820822 hash=83e767…e42d1d cache=363.96kB
Jan 31 19:46:28  geth[9939]: INFO [01-31|19:46:28.392] Upgrading chain index                    type=bloombits percentage=36
Jan 31 19:46:29  geth[9939]: INFO [01-31|19:46:29.258] Imported new block headers               count=2    elapsed=5.459ms   number=820824 hash=2de5fb…9551fb
Jan 31 19:46:29  geth[9939]: INFO [01-31|19:46:29.260] Imported new chain segment               blocks=2   txs=0 mgas=0.000 elapsed=1.221ms   mgasps=0.000 number=820824 hash=2de5fb…9551fb cache=370.70kB
Jan 31 19:46:29  geth[9939]: INFO [01-31|19:46:29.341] Fast sync complete, auto disabling
Jan 31 19:46:36  geth[9939]: INFO [01-31|19:46:36.509] Upgrading chain index                    type=bloombits percentage=52
Jan 31 19:46:36  geth[9939]: WARN [01-31|19:46:36.616] Ancestor below allowance                 peer=9984fe203477fcfa number=730824 hash=000000…000000 allowance=730824

... then some sidechain action

Jan 31 19:47:33  geth[9939]: WARN [01-31|19:47:33.065] Synchronisation failed, dropping peer    peer=f7bc214b51231edf err="retrieved ancestor is invalid"
Jan 31 19:47:33  geth[9939]: INFO [01-31|19:47:33.531] Imported new chain segment               blocks=1   txs=0 mgas=0.000 elapsed=2.834ms   mgasps=0.000 number=820828 hash=3c2d45…b8c13a cache=384.18kB
Jan 31 19:47:45  geth[9939]: INFO [01-31|19:47:45.485] Sidechain written to disk                start=772919 end=772933 sidetd=201388721547440 localtd=201496947937404
Jan 31 19:47:46  geth[9939]: INFO [01-31|19:47:46.129] Sidechain written to disk                start=772934 end=773297 sidetd=201388945000623 localtd=201496947937404
Jan 31 19:47:46  geth[9939]: INFO [01-31|19:47:46.692] Sidechain written to disk                start=773298 end=773551 sidetd=201389101624214 localtd=201496947937404
Jan 31 19:47:48  geth[9939]: INFO [01-31|19:47:48.995] Sidechain written to disk                start=773552 end=775599 sidetd=201390473790436 localtd=201496947937404
Jan 31 19:47:49  geth[9939]: INFO [01-31|19:47:49.000] Imported new chain segment               blocks=1   txs=0 mgas=0.000 elapsed=4.786ms   mgasps=0.000 number=820829 hash=1448ca…becbfb cache=387.55kB
Jan 31 19:47:50  geth[9939]: INFO [01-31|19:47:50.996] Sidechain written to disk                start=775600 end=777647 sidetd=201392233224704 localtd=201496951542984
...
Jan 31 19:49:47  geth[9939]: INFO [01-31|19:49:47.372] Sidechain written to disk                start=894384 end=896431 sidetd=201490982681086 localtd=201496994897760
Jan 31 19:49:49  geth[9939]: INFO [01-31|19:49:49.484] Sidechain written to disk                start=896432 end=898479 sidetd=201494002149870 localtd=201496994897760
Jan 31 19:50:22  geth[9939]: INFO [01-31|19:50:22.493] Importing heavy sidechain segment        blocks=2048 start=1      end=2048
Jan 31 19:50:23  geth[9939]: INFO [01-31|19:50:23.993] Imported new chain segment               blocks=2048 txs=22 mgas=1.258 elapsed=1.499s    mgasps=0.839 number=2048   hash=6708aa…742bab age=2y2mo3w   cache=611.95kB
Jan 31 19:50:24  geth[9939]: INFO [01-31|19:50:24.062] Importing heavy sidechain segment        blocks=2048 start=2049   end=4096
Jan 31 19:50:25  geth[9939]: INFO [01-31|19:50:25.010] Imported new chain segment               blocks=2048 txs=3  mgas=2.351 elapsed=948.191ms mgasps=2.480 number=4096   hash=769903…c570f8 age=2y2mo3w   cache=658.88kB
Jan 31 19:50:25  geth[9939]: INFO [01-31|19:50:25.081] Importing heavy sidechain segment        blocks=2048 start=4097   end=6144

... and finally

Jan 31 20:34:43  geth[9939]: INFO [01-31|20:34:43.732] Imported new chain segment               blocks=2048 txs=88    mgas=18.425   elapsed=819.636ms mgasps=22.480  number=819200 hash=341128…8218d7 age=1y6mo3w   cache=533.17mB
Jan 31 20:34:43  geth[9939]: INFO [01-31|20:34:43.815] Importing heavy sidechain segment        blocks=2048 start=819201 end=821248
Jan 31 20:34:44  geth[9939]: panic: runtime error: invalid memory address or nil pointer dereference
Jan 31 20:34:44  geth[9939]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x1c0 pc=0x89e95a]
Jan 31 20:34:44  geth[9939]: goroutine 359309 [running]:
Jan 31 20:34:44  geth[9939]: github.com/ethereum/go-ethereum/core.(*BlockChain).WriteBlockWithState(0xc010364000, 0xc0f02a4090, 0x0, 0x0, 0x0, 0xc06916a0d0, 0x0, 0x0, 0x0)
Jan 31 20:34:44  geth[9939]:         /ext-go/1/src/github.com/ethereum/go-ethereum/core/blockchain.go:976 +0xe7a
Jan 31 20:34:44  geth[9939]: github.com/ethereum/go-ethereum/core.(*BlockChain).insertChain(0xc010364000, 0xc060afc000,

I think it first fast-synced to a 'bad' destination.

Committed new head block                 number=820714 hash=effcbd…45a957

Here's canon 820714: https://ropsten.etherscan.io/block/820714 : 0xa3ea2545b163e845e2c205681100a58954448f9b0fab8b120b28b38d68118a47

The block 820714 is almost two years old: 646 days 4 hrs ago (Apr-26-2017 03:56:52 PM +UTC), and a totally different hash.
So you fast-synced to some stale sidechain, and then basially did a full-sync during sidechain import. I'm still not really sure why there is not a reorg earlier, before we pass 128 blocks into the better chain and thus wind up where we get a nil for the canon block block - 128

[holiman]

In the first case, @ryanschneider , here's a theory.

1. Someone mined a new chain A from ropsten genesis, with pretty low difficulty all the way
2. You fast-synced to that chain.
3. You then heard about a chain with even higher td, B , and started importing that
4. However, B, had even lower difficulty per block, and did not overtake A until more than 128 blocks after than A chain tip.