Gracefully stopping Geth but it hangs on net/http.Shutdown() #25257
Description
System information
Geth
Version: 1.10.19
Architecture: amd64
Go Version: go1.18.3
Operating System: linux
Expected behaviour
By typing Ctrl - c or kill -SIGINT or systemctl stop, geth should be stopped gracefully with all components properly take themselves.
The log output should looks like:
t=2022-07-06T03:00:42+0000 lvl=info msg="Got interrupt, shutting down..."
t=2022-07-06T03:00:42+0000 lvl=info msg="HTTP server stopped" endpoint=[::]:8545
t=2022-07-06T03:00:42+0000 lvl=info msg="HTTP server stopped" endpoint=[::]:8546
t=2022-07-06T03:00:42+0000 lvl=info msg="IPC endpoint closed" url=/eth/geth/state/geth.ipc
t=2022-07-06T03:00:42+0000 lvl=info msg="Ethereum protocol stopped"
t=2022-07-06T03:00:42+0000 lvl=info msg="Transaction pool stopped"
t=2022-07-06T03:00:42+0000 lvl=info msg="Writing cached state to disk" block=15,086,437
Actual behaviour
While actually, it looks like geth totally ignoring the SIGINT signal and continues syncing blocks from peers. The actually log output is:
t=2022-07-06T00:51:23+0000 lvl=info msg="Imported new chain segment" blocks=1 txs=29 mgas=2.935 elapsed=43.776ms mgasps=67.040 number=15,085,853 hash=0xe21a04ec30080765cd9d842b9e9482b689b942167bf9454328d11787c1e55060 dirty="1017.41 MiB"
t=2022-07-06T00:51:23+0000 lvl=info msg="Unindexed transactions" blocks=1 txs=130 tail=14,995,854 elapsed=2.285ms
**t=2022-07-06T00:51:26+0000 lvl=info msg="Got interrupt, shutting down..."**
t=2022-07-06T00:52:39+0000 lvl=info msg="Imported new chain segment" blocks=1 txs=223 mgas=30.029 elapsed=192.792ms mgasps=155.759 number=15,085,854 hash=0xbba1dad5c937c8e59b163a69b5e781cb651828e3a8b171069d1119e349cd7ed0 age=1m16s dirty="1016.93 MiB"
t=2022-07-06T00:52:39+0000 lvl=info msg="Unindexed transactions" blocks=1 txs=210 tail=14,995,855 elapsed=2.407ms
t=2022-07-06T00:53:05+0000 lvl=info msg="Imported new chain segment" blocks=1 txs=191 mgas=29.999 elapsed=130.565ms mgasps=229.762 number=15,085,855 hash=0xd5a58548de09b08d4b9fb65f0f50bd9c09b43c1498f7b1158455a612a238423f dirty="1017.55 MiB"
t=2022-07-06T00:53:05+0000 lvl=info msg="Unindexed transactions" blocks=1 txs=45 tail=14,995,856 elapsed="802.229µs"
t=2022-07-06T00:53:08+0000 lvl=info msg="Imported new chain segment" blocks=1 txs=262 mgas=29.981 elapsed=106.978ms mgasps=280.253 number=15,085,856 hash=0x150cc74970a7aec6d190dd010e5a5775017b64a78921a561d932be58797210c4 dirty="1019.33 MiB"
t=2022-07-06T00:53:08+0000 lvl=info msg="Unindexed transactions" blocks=1 txs=787 tail=14,995,857 elapsed=7.301ms
**t=2022-07-06T00:53:10+0000 lvl=warn msg="Already shutting down, interrupt more to panic." times=9**
t=2022-07-06T00:53:13+0000 lvl=info msg="Imported new chain segment" blocks=1 txs=222 mgas=29.990 elapsed=140.488ms mgasps=213.467 number=15,085,857 hash=0x53a98d5276306b9556aec32c3aca0125304c827e7d2f74898b775d0ce4a326c8 dirty="1018.80 MiB"
t=2022-07-06T00:53:13+0000 lvl=info msg="Unindexed transactions" blocks=1 txs=0 tail=14,995,858 elapsed="435.13µs"
t=2022-07-06T00:53:21+0000 lvl=info msg="Imported new chain segment" blocks=1 txs=43 mgas=4.896 elapsed=58.528ms mgasps=83.643 number=15,085,858 hash=0x6df5f2794b760822306784c19985c32669c91e368082b1bf7d332f10ab5c4f63 dirty="1016.55 MiB"
Steps to reproduce the behaviour
it occurs seldomly, we have not found a fixed pattern to reproduce it yet.
Backtrace
Seems something's wrong inside the net/http.Shutdown() it never returns so the rpc server cannot stop, rpc server is at the first when the node stops, so other components are not able to stop too.
goroutine 19333821 [select]:
net/http.(*Server).Shutdown(0xc014d0c620, {0x17deb68, 0xc000138000})
net/http/server.go:2775 +0x269
github.com/ethereum/go-ethereum/node.(*httpServer).doStop(0xc0002a3040)
github.com/ethereum/go-ethereum/node/rpcstack.go:264 +0x152
github.com/ethereum/go-ethereum/node.(*httpServer).stop(0x1357081a9754b950?)
github.com/ethereum/go-ethereum/node/rpcstack.go:245 +0x8b
github.com/ethereum/go-ethereum/node.(*Node).stopRPC(0xc0002135e0)
github.com/ethereum/go-ethereum/node/node.go:523 +0x2c
github.com/ethereum/go-ethereum/node.(*Node).stopServices(0xc0002135e0, {0xc014d6e690, 0x1, 0x1c69da15893bce9d?})
github.com/ethereum/go-ethereum/node/node.go:312 +0x32
github.com/ethereum/go-ethereum/node.(*Node).Close(0xc0002135e0)
github.com/ethereum/go-ethereum/node/node.go:237 +0x191
created by github.com/ethereum/go-ethereum/cmd/utils.StartNode.func1.1
github.com/ethereum/go-ethereum/cmd/utils/cmd.go:92 +0x96
...
goroutine 205 [chan receive, 5 minutes]:
github.com/ethereum/go-ethereum/cmd/utils.StartNode.func1.1()
github.com/ethereum/go-ethereum/cmd/utils/cmd.go:94 +0xbb
github.com/ethereum/go-ethereum/cmd/utils.StartNode.func1()
github.com/ethereum/go-ethereum/cmd/utils/cmd.go:115 +0x2f0
created by github.com/ethereum/go-ethereum/cmd/utils.StartNode
github.com/ethereum/go-ethereum/cmd/utils/cmd.go:75 +0xc5