SIGSEGV: segmentation violation code=0x1 downloader.(*Downloader).findAncestorBinarySearch()

[dzianisv]

System information

Geth version: 1.10.21
OS & Version: Linux, Docker, ubuntu:20.04

Expected behaviour

Log/Handle the error

Actual behaviour

Crashing

Steps to reproduce the behaviour

• Start a geth node
• Wait

Backtrace

 INFO [08-11|00:15:48.207] Starting pprof server                    addr=http://0.0.0.0:6060/debug/pprof
INFO [08-11|00:15:48.208] Starting Geth on Görli testnet...
INFO [08-11|00:15:48.208] Enabling metrics collection
INFO [08-11|00:15:48.210] Maximum peer count                       ETH=50 LES=0 total=50
INFO [08-11|00:15:48.212] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
INFO [08-11|00:15:48.216] Set global gas cap                       cap=50,000,000
INFO [08-11|00:15:48.218] Allocated trie memory caches             clean=614.00MiB dirty=1024.00MiB
INFO [08-11|00:15:48.218] Allocated cache and file handles         database=/ethereum/geth/chaindata cache=2.00GiB handles=524,288
INFO [08-11|00:15:48.575] Opened ancient database                  database=/ethereum/geth/chaindata/ancient readonly=false
INFO [08-11|00:15:48.642] Persisted trie from memory database      nodes=361 size=51.17KiB time="408.098µs" gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
INFO [08-11|00:15:48.649]
INFO [08-11|00:15:48.649] ---------------------------------------------------------------------------------------------------------------------------------------------------------
INFO [08-11|00:15:48.649] Chain ID:  5 (goerli)
INFO [08-11|00:15:48.649] Consensus: Beacon (proof-of-stake), merged from Clique (proof-of-authority)
INFO [08-11|00:15:48.649]
INFO [08-11|00:15:48.649] Pre-Merge hard forks:
INFO [08-11|00:15:48.649]  - Homestead:                   0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/homestead.md)
INFO [08-11|00:15:48.649]  - Tangerine Whistle (EIP 150): 0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/tangerine-whistle.md)
INFO [08-11|00:15:48.649]  - Spurious Dragon/1 (EIP 155): 0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/spurious-dragon.md)
INFO [08-11|00:15:48.649]  - Spurious Dragon/2 (EIP 158): 0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/spurious-dragon.md)
INFO [08-11|00:15:48.649]  - Byzantium:                   0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/byzantium.md)
INFO [08-11|00:15:48.649]  - Constantinople:              0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/constantinople.md)
INFO [08-11|00:15:48.649]  - Petersburg:                  0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/petersburg.md)
INFO [08-11|00:15:48.649]  - Istanbul:                    1561651  (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/istanbul.md)
INFO [08-11|00:15:48.649]  - Berlin:                      4460644  (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/berlin.md)
INFO [08-11|00:15:48.649]  - London:                      5062605  (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/london.md)
INFO [08-11|00:15:48.649]
INFO [08-11|00:15:48.649] Merge configured:
INFO [08-11|00:15:48.649]  - Hard-fork specification:   https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/paris.md)
INFO [08-11|00:15:48.649]  - Total terminal difficulty: 10790000
INFO [08-11|00:15:48.650]  - Merge netsplit block:      <nil>
INFO [08-11|00:15:48.650] ---------------------------------------------------------------------------------------------------------------------------------------------------------
INFO [08-11|00:15:48.650]
INFO [08-11|00:15:48.744] Initialising Ethereum protocol           network=5 dbversion=8
INFO [08-11|00:15:48.772] Loaded most recent local header          number=0 hash=bf7e33..b88c1a td=1 age=3y6mo4w
INFO [08-11|00:15:48.772] Loaded most recent local full block      number=0 hash=bf7e33..b88c1a td=1 age=3y6mo4w
INFO [08-11|00:15:48.772] Loaded most recent local fast block      number=0 hash=bf7e33..b88c1a td=1 age=3y6mo4w
WARN [08-11|00:15:48.780] Snapshot maintenance disabled (syncing)
INFO [08-11|00:15:48.780] Loaded local transaction journal         transactions=0 dropped=0
INFO [08-11|00:15:48.780] Regenerated local transaction journal    transactions=0 accounts=0
INFO [08-11|00:15:48.781] Gasprice oracle is ignoring threshold set threshold=2
WARN [08-11|00:15:48.783] Old unclean shutdowns found              count=205
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-10T23:15:56+0000 age=59m52s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-10T23:21:19+0000 age=54m29s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-10T23:26:55+0000 age=48m53s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-10T23:32:44+0000 age=43m4s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-10T23:37:59+0000 age=37m49s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-10T23:43:45+0000 age=32m3s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-10T23:49:13+0000 age=26m35s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-10T23:54:44+0000 age=21m4s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-11T00:00:01+0000 age=15m47s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-11T00:05:18+0000 age=10m30s
WARN [08-11|00:15:48.783] Unclean shutdown detected                booted=2022-08-11T00:10:30+0000 age=5m18s
WARN [08-11|00:15:48.784] Engine API enabled                       protocol=eth
INFO [08-11|00:15:48.785] Starting peer-to-peer node               instance=Geth/v1.10.21-stable-67109427/linux-amd64/go1.18.5
INFO [08-11|00:15:48.808] New local node record                    seq=1,660,169,419,868 id=c21e36782d2aaab1 ip=127.0.0.1 udp=29888 tcp=29888
INFO [08-11|00:15:48.809] Started P2P networking                   self=enode://147d71be9c8828d45d8407c0df9e319a7414c2f4be920deed562c670284d973cebc8895d5aeb1c74348fbe15082184eb3ba135361750a98ca127256e10a13751@127.0.0.1:29888
INFO [08-11|00:15:48.810] IPC endpoint opened                      url=/ethereum/geth.ipc
INFO [08-11|00:15:48.810] Loaded JWT secret file                   path=/usr/local/genesis/kiln/jwtsecret crc32=0x3121e41e
INFO [08-11|00:15:48.811] WebSocket enabled                        url=ws://[::]:8545
INFO [08-11|00:15:48.811] HTTP server started                      endpoint=[::]:8545 auth=false prefix= cors= vhosts=*
INFO [08-11|00:15:48.811] WebSocket enabled                        url=ws://[::]:8551
INFO [08-11|00:15:48.811] HTTP server started                      endpoint=[::]:8551 auth=true  prefix= cors=localhost vhosts=*
INFO [08-11|00:15:59.534] Looking for peers                        peercount=0 tried=19 static=0
INFO [08-11|00:16:08.342] New local node record                    seq=1,660,169,419,869 id=c21e36782d2aaab1 ip=3.144.46.197 udp=29888 tcp=29888
INFO [08-11|00:16:09.878] Looking for peers                        peercount=0 tried=31 static=0
INFO [08-11|00:16:20.131] Looking for peers                        peercount=0 tried=35 static=0
INFO [08-11|00:16:30.192] Looking for peers                        peercount=0 tried=27 static=0
INFO [08-11|00:16:40.192] Looking for peers                        peercount=1 tried=34 static=0
INFO [08-11|00:16:50.502] Looking for peers                        peercount=0 tried=38 static=0
WARN [08-11|00:16:51.387] Snapshot extension registration failed   peer=7bcee16b err="peer connected on snap without compatible eth support"
INFO [08-11|00:17:00.835] Looking for peers                        peercount=0 tried=39 static=0
INFO [08-11|00:17:10.858] Looking for peers                        peercount=0 tried=40 static=0
INFO [08-11|00:17:20.866] Looking for peers                        peercount=0 tried=34 static=0
INFO [08-11|00:17:22.371] Block synchronisation started
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x1c0 pc=0xa9db59]

goroutine 2081 [running]:
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).findAncestorBinarySearch(0xc000178180, 0xc099f02240, 0x1, 0x70a5c5, 0xffffffffffffffff)
	github.com/ethereum/go-ethereum/eth/downloader/downloader.go:965 +0x319
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).findAncestor(0xc000178180, 0xc099f02240, 0x1e?)
	github.com/ethereum/go-ethereum/eth/downloader/downloader.go:857 +0x2db
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).syncWithPeer(0xc000178180, 0xc099f02240, {0x42, 0xe9, 0xf4, 0x38, 0x7b, 0x92, 0x90, 0x25, ...}, ...)
	github.com/ethereum/go-ethereum/eth/downloader/downloader.go:521 +0x985
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).synchronise(0x73ad25?, {0xc099e2e800, 0x40}, {0x42, 0xe9, 0xf4, 0x38, 0x7b, 0x92, 0x90, ...}, ...)
	github.com/ethereum/go-ethereum/eth/downloader/downloader.go:439 +0x505
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).LegacySync(0xc000178180, {0xc099e2e800, 0x40}, {0x42, 0xe9, 0xf4, 0x38, 0x7b, 0x92, 0x90, ...}, ...)
	github.com/ethereum/go-ethereum/eth/downloader/downloader.go:334 +0x65
github.com/ethereum/go-ethereum/eth.(*handler).doSync(0xc00538a100, 0xc099d47100?)
	github.com/ethereum/go-ethereum/eth/sync.go:255 +0x225
github.com/ethereum/go-ethereum/eth.(*chainSyncer).startSync.func1()
	github.com/ethereum/go-ethereum/eth/sync.go:231 +0x29
created by github.com/ethereum/go-ethereum/eth.(*chainSyncer).startSync
	github.com/ethereum/go-ethereum/eth/sync.go:231 +0xaa

When submitting logs: please submit them as text and not screenshots.

[holiman]

Old unclean shutdowns found count=205 -- it seems you often do not shut down geth properly, but just tear the process down. This may lead to data corruption.
I don't have any better idea on why this specific error happens.

[dzianisv]

Even so, do we expect a segvfault/panic because of a nil pointer?

[holiman]

Even so, do we expect a segvfault/panic because of a nil pointer?

Ideally no, but if data is corrupted in a way which does not make sense (e.g. we have stored the head of the latest block, but not the block body, so loading it via one method works fine but loading it via the 'full' method does not work), then you're bound to crash at some point. Geth does have some assumptions about the structure of the data, and tries as far as possible to guarantee certain things. If those things are not true, then geth cannot gracefully recover.

I'm leaving the issue open, but ensuring a graceful shutdown is often a good strategy to avoid these types of issues.

[holiman]

We believe #25578 fixes this issue.