Failed to terminate geth when disk space is insufficient

[rjl493456442]

It's a report from ethpandaOps team, looks like the geth is not properly terminated when the disk space is not sufficient.

ERROR[07-21|15:11:02.696] Low disk space. Gracefully shutting down Geth to prevent database corruption. available=65.43MiB  path=/data/geth
INFO [07-21|15:11:02.697] Got interrupt, shutting down...
INFO [07-21|15:11:02.700] HTTP server stopped                      endpoint=[::]:8545
INFO [07-21|15:11:02.701] HTTP server stopped                      endpoint=[::]:8551
INFO [07-21|15:11:02.707] IPC endpoint closed                      url=/data/geth.ipc
INFO [07-21|15:11:07.967] Imported new chain segment               number=22,875,106 hash=9cbd93..01cb8a blocks=1   txs=47    mgas=575.798  elapsed=14.103s   mgasps=40.826  age=2d23h32m triediffs=4.12GiB   triedirty=67.22MiB
INFO [07-21|15:11:16.391] Imported new chain segment               number=22,875,109 hash=2b9987..217e46 blocks=3   txs=35    mgas=515.294  elapsed=8.424s    mgasps=61.169  age=2d23h32m triediffs=4.09GiB   triedirty=125.03MiB
ERROR[07-21|15:11:21.631] Number of finalized block is missing
INFO [07-21|15:11:26.623] Imported new chain segment               number=22,875,111 hash=be59b4..18286d blocks=2   txs=59    mgas=860.090  elapsed=10.232s   mgasps=84.054  age=2d23h31m triediffs=4.08GiB   triedirty=186.96MiB
INFO [07-21|15:11:36.549] Imported new chain segment               number=22,875,113 hash=f3f622..51c223 blocks=2   txs=55    mgas=840.106  elapsed=9.925s    mgasps=84.638  age=2d23h31m triediffs=4.07GiB   triedirty=241.95MiB
INFO [07-21|15:11:44.703] Imported new chain segment               number=22,875,116 hash=d9742f..7c17de blocks=3   txs=53    mgas=636.582  elapsed=8.154s    mgasps=78.066  age=2d23h30m triediffs=4.04GiB   triedirty=35.54MiB
INFO [07-21|15:11:55.173] Imported new chain segment               number=22,875,117 hash=a5622c..e17bec blocks=1   txs=41    mgas=575.556  elapsed=10.469s   mgasps=54.977  age=2d23h30m triediffs=4.05GiB   triedirty=67.22MiB
INFO [07-21|15:12:04.465] Imported new chain segment               number=22,875,119 hash=b14427..3c6808 blocks=2   txs=37    mgas=635.056  elapsed=9.292s    mgasps=68.342  age=2d23h30m triediffs=4.03GiB   triedirty=120.93MiB
INFO [07-21|15:12:15.531] Imported new chain segment               number=22,875,121 hash=d1de92..c4a39a blocks=2   txs=54    mgas=969.941  elapsed=11.066s   mgasps=87.646  age=2d23h29m triediffs=4.04GiB   triedirty=173.60MiB
ERROR[07-21|15:12:21.632] Number of finalized block is missing
INFO [07-21|15:12:26.265] Imported new chain segment               number=22,875,123 hash=d2f731..b4b0fa blocks=2   txs=65    mgas=921.032  elapsed=10.733s   mgasps=85.810  age=2d23h29m triediffs=4.03GiB   triedirty=232.65MiB
INFO [07-21|15:12:38.026] Imported new chain segment               number=22,875,125 hash=8d02c1..be6db0 blocks=2   txs=72    mgas=1060.301 elapsed=11.761s   mgasps=90.152  age=2d23h29m triediffs=4.05GiB   triedirty=0.00B
INFO [07-21|15:12:51.061] Imported new chain segment               number=22,875,127 hash=4993f0..10e5a6 blocks=2   txs=28    mgas=574.920  elapsed=13.035s   mgasps=44.106  age=2d23h28m triediffs=4.02GiB   triedirty=71.06MiB
INFO [07-21|15:13:05.386] Imported new chain segment               number=22,875,129 hash=a03f99..e847d7 blocks=2   txs=85    mgas=577.491  elapsed=14.324s   mgasps=40.314  age=2d23h28m triediffs=4.01GiB   triedirty=117.35MiB
ERROR[07-21|15:13:21.631] Number of finalized block is missing
INFO [07-21|15:13:21.758] Imported new chain segment               number=22,875,130 hash=9c777d..6df591 blocks=1   txs=39    mgas=575.699  elapsed=16.371s   mgasps=35.164  age=2d23h28m triediffs=4.01GiB   triedirty=147.08MiB
INFO [07-21|15:13:31.754] Imported new chain segment               number=22,875,131 hash=397aeb..9a49ea blocks=1   txs=19    mgas=429.651  elapsed=9.996s    mgasps=42.981  age=2d23h28m triediffs=4.01GiB   triedirty=173.51MiB
INFO [07-21|15:13:41.566] Imported new chain segment               number=22,875,132 hash=b9160c..200e67 blocks=1   txs=17    mgas=454.642  elapsed=9.812s    mgasps=46.335  age=2d23h28m triediffs=4.05GiB   triedirty=173.52MiB
ERROR[07-21|15:13:50.071] Nil finalized block cannot evict old blobs
ERROR[07-21|15:13:50.073] Beacon backfilling failed                err="retrieved hash chain is invalid: write /data/geth/chaindata/ancient/state/storage.index.0020.cdat: no space left on device"
INFO [07-21|15:13:50.109] Ethereum protocol stopped
INFO [07-21|15:13:50.111] Transaction pool stopped
INFO [07-21|15:13:50.116] Waiting background transaction indexer to exit
INFO [07-21|15:13:50.451] Persisting dirty state to disk           head=22,875,132 root=82e71d..383c00 layers=135
INFO [07-21|15:14:00.303] Looking for peers                        peercount=0 tried=150 static=0
INFO [07-21|15:14:10.307] Looking for peers                        peercount=1 tried=27  static=0
INFO [07-21|15:14:20.331] Looking for peers                        peercount=0 tried=83  static=0
ERROR[07-21|15:14:21.632] Number of finalized block is missing
panic: write /data/geth/chaindata/2517646.log: no space left on device

goroutine 834330372 [running]:
github.com/cockroachdb/pebble.(*DB).rotateWAL(0xc000254d88)
	github.com/cockroachdb/pebble@v1.1.5/db.go:2679 +0x8e5
github.com/cockroachdb/pebble.(*DB).makeRoomForWrite(0xc000254d88, 0xc0066bc900)
	github.com/cockroachdb/pebble@v1.1.5/db.go:2474 +0x3cf
github.com/cockroachdb/pebble.(*DB).commitWrite(0xc000254d88, 0xc0066bc900, 0x0, 0x0)
	github.com/cockroachdb/pebble@v1.1.5/db.go:940 +0x19e
github.com/cockroachdb/pebble.(*commitPipeline).prepare(0xc000a6e000, 0xc0066bc900, 0xc0?, 0x38?)
	github.com/cockroachdb/pebble@v1.1.5/commit.go:466 +0x174
github.com/cockroachdb/pebble.(*commitPipeline).Commit(0xc000a6e000, 0xc0066bc900, 0x0, 0x0)
	github.com/cockroachdb/pebble@v1.1.5/commit.go:315 +0xaf
github.com/cockroachdb/pebble.(*DB).applyInternal(0xc000254d88, 0xc0066bc900, 0x3370b98?, 0x0)
	github.com/cockroachdb/pebble@v1.1.5/db.go:854 +0x1f4
github.com/cockroachdb/pebble.(*DB).Apply(...)
	github.com/cockroachdb/pebble@v1.1.5/db.go:780
github.com/cockroachdb/pebble.(*DB).Set(0xc000254d88, {0x314ac00, 0xb, 0xb}, {0xcaae500000, 0xfc44d814, 0x180000000}, 0x3370b98)
	github.com/cockroachdb/pebble@v1.1.5/db.go:609 +0xeb
github.com/ethereum/go-ethereum/ethdb/pebble.(*Database).Put(0x7fe1e62a45c8?, {0x314ac00?, 0x7fe1e730d888?, 0x2283358?}, {0xcaae500000?, 0x669420?, 0x3371670?})
	github.com/ethereum/go-ethereum/ethdb/pebble/pebble.go:404 +0x145
github.com/ethereum/go-ethereum/core/rawdb.WriteTrieJournal({0x7fe23adb2b10?, 0xc00435a0f0?}, {0xcaae500000?, 0xc245961960?, 0xc4fbffe6c0?})
	github.com/ethereum/go-ethereum/core/rawdb/accessors_state.go:155 +0x52
github.com/ethereum/go-ethereum/triedb/pathdb.(*Database).Journal(0xc004360060, {0x82, 0xe7, 0x1d, 0x80, 0xb6, 0x8e, 0x56, 0x59, 0x50, ...})
	github.com/ethereum/go-ethereum/triedb/pathdb/journal.go:338 +0x705
github.com/ethereum/go-ethereum/triedb.(*Database).Journal(0xc326415cf8?, {0x82, 0xe7, 0x1d, 0x80, 0xb6, 0x8e, 0x56, 0x59, 0x50, ...})
	github.com/ethereum/go-ethereum/triedb/database.go:321 +0x3a
github.com/ethereum/go-ethereum/core.(*BlockChain).Stop(0xc06709ee08)
	github.com/ethereum/go-ethereum/core/blockchain.go:1268 +0x225
github.com/ethereum/go-ethereum/eth.(*Ethereum).Stop(0xc00436a4e0)
	github.com/ethereum/go-ethereum/eth/backend.go:523 +0xc5
github.com/ethereum/go-ethereum/node.(*Node).stopServices(0xc000234620, {0xc06f7bab80, 0x3, 0x100000001158d57?})
	github.com/ethereum/go-ethereum/node/node.go:291 +0xb3
github.com/ethereum/go-ethereum/node.(*Node).Close(0xc000234620)
	github.com/ethereum/go-ethereum/node/node.go:221 +0x167
created by github.com/ethereum/go-ethereum/cmd/utils.StartNode.func1.1 in goroutine 9237
	github.com/ethereum/go-ethereum/cmd/utils/cmd.go:102 +0x78

[rjl493456442]

WARN [07-21|15:07:32.691] Disk space is running low. Geth will shutdown if disk space runs below critical level. available=815.43MiB critical_level=512.00MiB path=/data/geth

The first occurrence is 7 minutes ahead

[rjl493456442]

Fatal: Failed to register the Ethereum service: decoding SET value: pebble: invalid batch
Fatal: Failed to register the Ethereum service: decoding SET value: pebble: invalid batch

After this panic, the database is corrupted

[MariusVanDerWijden]

Maybe we should increase the critical level, since we are flushing the data in much bigger batches now than what we did back in the day when this was added

[rjl493456442]

I guess the root cause is Got interrupt, shutting down..., Geth is stuck with the interruption signal, which is a known issue ...

[fjl]

This issue should be fixed by recent PRs. In #32062, we made Geth terminate faster during full sync when a signal is received. And in #32060, the trie journal code was changed to not write into Pebble, but into a separate file. This should mean that even if disk space runs low, like in the scenario here, the failed trie journal write operation cannot crash Geth anymore.

We should definitely consider raising the limit though.