Node doesn't shutdown gracefully during block import

[s1na]

System information

Geth version: geth version v1.15.6
CL client & version: e.g. lighthouse/nimbus/prysm@v1.0.0
OS & Version: Windows/Linux/OSX
Commit hash : (if develop)

Expected behaviour

Node shuts down gracefully on ctrl+c

Actual behaviour

INFO [03-27|17:26:00.331] Imported new chain segment               number=8998  hash=a9ee42..af8559 blocks=109 txs=837  mgas=2087.455 elapsed=8.045s      mgasps=259.468 age=1w1d19h snapdiffs=2.49MiB   triedirty=169.78MiB
INFO [03-27|17:26:08.384] Imported new chain segment               number=9107  hash=0486b7..d5cac1 blocks=109 txs=834  mgas=2074.864 elapsed=8.053s      mgasps=257.650 age=1w1d19h snapdiffs=2.56MiB   triedirty=169.74MiB
^CINFO [03-27|17:26:12.630] Got interrupt, shutting down...
INFO [03-27|17:26:12.630] HTTP server stopped                      endpoint=127.0.0.1:8545
INFO [03-27|17:26:12.630] HTTP server stopped                      endpoint=127.0.0.1:8551
INFO [03-27|17:26:12.630] IPC endpoint closed                      url=/home/ubuntu/datadir-hoodi/geth.ipc
INFO [03-27|17:26:16.466] Imported new chain segment               number=9222  hash=bd6fbd..58e400 blocks=115 txs=924  mgas=2157.052 elapsed=8.082s      mgasps=266.876 age=1w1d18h snapdiffs=2.65MiB   triedirty=170.03MiB

[rjl493456442]

I guess the interruption signal is only handled after processing a batch of blocks, which takes time.
We could somehow propagate the signal into the chain insertion to solve it.

[s1na]

Got a report that this can happen after sync has finished too.

[alecalve]

I am encountering a similar situation:

INFO [04-16|11:19:13.011] Got interrupt, shutting down...
INFO [04-16|11:19:13.289] Imported new potential chain segment     number=22,281,212 hash=4be7e2..3b4846 blocks=1 txs=141 mgas=11.353 elapsed=434.508ms    mgasps=26.128  triedirty=0.00B
INFO [04-16|11:19:13.497] Chain head was updated                   number=22,281,212 hash=4be7e2..3b4846 root=02b74f..10402d elapsed=2.165357ms
WARN [04-16|11:19:18.014] HTTP server graceful shutdown timed out
INFO [04-16|11:19:18.053] HTTP server stopped                      endpoint=[::]:8545
INFO [04-16|11:19:18.053] HTTP server stopped                      endpoint=[::]:8551
INFO [04-16|11:19:18.054] IPC endpoint closed                      url=/opt/data/geth.ipc
INFO [04-16|11:19:18.059] Ethereum protocol stopped
INFO [04-16|11:19:33.060] Looking for peers                        peercount=0 tried=104 static=0
INFO [04-16|11:19:44.049] Looking for peers                        peercount=0 tried=79  static=0
INFO [04-16|11:19:54.051] Looking for peers                        peercount=0 tried=78  static=0
INFO [04-16|11:20:04.059] Looking for peers                        peercount=0 tried=46  static=0
INFO [04-16|11:20:14.111] Looking for peers                        peercount=0 tried=51  static=0

It's still running 10+ minutes after having received an interrupt.

[s1na]

@alecalve can you share a bit of logs prior to the interruption signal. I mainly want to know if the node was in doing the sync, or was already synced.

[alecalve]

@s1na

The node is fully synced and runs with --syncmode=snap --gcmode=archive.

Here are the logs above the interrupt:

INFO [04-16|11:18:02.637] Imported new potential chain segment     number=22,281,206 hash=eac0a7..565e2f blocks=1 txs=194 mgas=31.480 elapsed=1.784s       mgasps=17.638  triedirty=0.00B
INFO [04-16|11:18:02.864] Chain head was updated                   number=22,281,206 hash=eac0a7..565e2f root=d463f7..1fba8f elapsed=3.119291ms
INFO [04-16|11:18:14.143] Imported new potential chain segment     number=22,281,207 hash=5ec614..c27032 blocks=1 txs=202 mgas=18.191 elapsed=722.222ms    mgasps=25.187  triedirty=0.00B
INFO [04-16|11:18:14.354] Chain head was updated                   number=22,281,207 hash=5ec614..c27032 root=70afe7..3f43e1 elapsed=3.174558ms
INFO [04-16|11:18:25.363] Imported new potential chain segment     number=22,281,208 hash=b057f8..e55aa4 blocks=1 txs=155 mgas=12.294 elapsed=543.435ms    mgasps=22.623  triedirty=0.00B
INFO [04-16|11:18:25.571] Chain head was updated                   number=22,281,208 hash=b057f8..e55aa4 root=ea87c6..c418a5 elapsed=2.307142ms
INFO [04-16|11:18:37.737] Imported new potential chain segment     number=22,281,209 hash=8b462b..1a0ad9 blocks=1 txs=175 mgas=13.538 elapsed=557.257ms    mgasps=24.295  triedirty=0.00B
INFO [04-16|11:18:37.968] Chain head was updated                   number=22,281,209 hash=8b462b..1a0ad9 root=30b325..88388c elapsed=2.494938ms
INFO [04-16|11:18:51.176] Imported new potential chain segment     number=22,281,210 hash=332196..a87a3e blocks=1 txs=136 mgas=12.542 elapsed=628.050ms    mgasps=19.969  triedirty=0.00B
INFO [04-16|11:18:51.379] Chain head was updated                   number=22,281,210 hash=332196..a87a3e root=9b230c..00a377 elapsed=2.323504ms
WARN [04-16|11:18:56.998] Served eth_call                          conn=10.0.21.170:45410 reqid=2183898 duration=1.333401ms err="execution reverted" errdata="\"0x\""
WARN [04-16|11:18:59.438] Served eth_call                          conn=10.0.3.204:59690 reqid=8236 duration=2.450792ms err="missing trie node 88055672b7ba6d0a11d65865ef1fd821a32ba1a9d4a68deb20e5dad3e9904e65 (path ) state 0x88055672b7ba6d0a11d65865ef1fd821a32ba1a9d4a68deb20e5dad3e9904e65 is not available, not found"
INFO [04-16|11:19:04.233] Imported new potential chain segment     number=22,281,211 hash=1ecd5f..f05965 blocks=1 txs=189 mgas=35.995 elapsed=1.811s       mgasps=19.869  triedirty=0.00B
INFO [04-16|11:19:04.448] Chain head was updated                   number=22,281,211 hash=1ecd5f..f05965 root=9343d3..4a8108 elapsed=2.948929ms
INFO [04-16|11:19:13.011] Got interrupt, shutting down...

[jsvisa]

As the log Ethereum protocol stopped was shown, and Looking for peers logs are still showing, so the P2P servers are alive, maybe one or more procedures are still hanging

maybe hangs after s.handler.Stop()

go-ethereum/eth/backend.go

Lines 555 to 577 in ac50181

	func (s *Ethereum) Stop() error {
	// Stop all the peer-related stuff first.
	s.discmix.Close()
	s.dropper.Stop()
	s.handler.Stop()
	// Then stop everything else.
	ch := make(chan struct{})
	s.closeFilterMaps <- ch
	<-ch
	s.filterMaps.Stop()
	s.txPool.Close()
	s.blockchain.Stop()
	s.engine.Close()
	// Clean shutdown marker as the last thing before closing db
	s.shutdownTracker.Stop()
	s.chainDb.Close()
	s.eventMux.Stop()
	return nil
	}