Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

It took quite a long time for node to shutdown #1674

Closed
brilliant-lx opened this issue Jun 7, 2023 · 0 comments
Closed

It took quite a long time for node to shutdown #1674

brilliant-lx opened this issue Jun 7, 2023 · 0 comments
Assignees
@brilliant-lx

Comments

@brilliant-lx
Copy link
Collaborator

brilliant-lx commented Jun 7, 2023 •
edited

System information

Geth version: geth v1.2.4
OS & Version: Linux
Commit hash : just the tag v1.2.4

Expected behaviour

When node shutdown, it can be shutdown gracefully within a few second.

Actual behaviour

It took more than several minutes for node to shutdown.

Steps to reproduce the behaviour

Start a BSC full node with v1.2.4, sync to the latest block, shut it down by: kill <pid of bsc>
The process can not be shutdown, it keeps printing the following logs.

t=2023-06-06T14:50:53+0000 lvl=info msg="Got interrupt, shutting down..."
t=2023-06-06T14:50:53+0000 lvl=warn msg="HTTP server graceful shutdown timed out"
t=2023-06-06T14:50:53+0000 lvl=info msg="HTTP server stopped"                 endpoint=...:8545
t=2023-06-06T14:50:53+0000 lvl=info msg="IPC endpoint closed"                 url=/.../geth.ipc
t=2023-06-06T14:50:53+0000 lvl=info msg="Les server stopped"
t=2023-06-06T14:50:53+0000 lvl=info msg="Ethereum protocol stopped"
t=2023-06-06T14:50:53+0000 lvl=info msg="Transaction pool stopped"
t=2023-06-06T14:50:53+0000 lvl=eror msg="Bsc extension Handshake failed"      peer=803058b1 err=EOF
t=2023-06-06T14:50:53+0000 lvl=eror msg="Bsc extension Handshake failed"      peer=a7ca772b err=EOF
t=2023-06-06T14:50:53+0000 lvl=eror msg="Bsc extension Handshake failed"      peer=3370c8d6 err=EOF
t=2023-06-06T14:50:54+0000 lvl=info msg="commitWork SubscribeNewTxsEvent return nil"
t=2023-06-06T14:50:55+0000 lvl=info msg="Writing cached state to disk"        block=28,867,106 hash=0x84d3a9ee5dcfcc08508835f26fdb15c6957e7459b26404130d4a74facd7c14bb root=0xaccf7080ec70b8f33944cb1a0d29c75f4a3e20b5e93e0d6b8d2a52b7a3c107b9
t=2023-06-06T14:50:57+0000 lvl=info msg="Persisted trie from memory database" nodes=407,591   size="129.51 MiB" time=2.780703481s  gcnodes=410,882   gcsize="162.27 MiB" gctime=1.352388374s  livenodes=106,325 livesize="41.81 MiB"
t=2023-06-06T14:50:57+0000 lvl=info msg="Writing cached state to disk"        block=28,867,105 hash=0xf4d0d507442ed4d23f5f1b4dbad7383da3beb36775a44bf772a46336337ca8e6 root=0x8f06931fcf60374ea8c119ff935f1e645ce58023e410160214c5e956900e6967
t=2023-06-06T14:50:57+0000 lvl=info msg="Persisted trie from memory database" nodes=5255      size="2.01 MiB"   time=40.148022ms   gcnodes=0         gcsize="0.00 B"     gctime=0s            livenodes=101,070 livesize="39.80 MiB"
t=2023-06-06T14:50:57+0000 lvl=info msg="Writing cached state to disk"        block=28,867,075 hash=0xccda367d6d1a1be7e78e5fb0e1df99c242fc05b655e9eba3f1b77e94343092f4 root=0xc10216cd73b552bccbed684c069db377a44fcc0007072d9ffd60f7d9ce31c7ab
t=2023-06-06T14:50:58+0000 lvl=info msg="Persisted trie from memory database" nodes=42798     size="16.35 MiB"  time=317.797785ms  gcnodes=0         gcsize="0.00 B"     gctime=0s            livenodes=58272   livesize="23.44 MiB"
t=2023-06-06T14:50:58+0000 lvl=info msg="Writing snapshot state to disk"      root=0x24c86abe9775a4e703c92891c9689e190d1ed3df89742e755c70962f7d9d32ec
t=2023-06-06T14:50:58+0000 lvl=info msg="Persisted trie from memory database" nodes=0         size="0.00 B"     time="1.875µs"     gcnodes=0         gcsize="0.00 B"     gctime=0s            livenodes=58272   livesize="23.44 MiB"
t=2023-06-06T14:50:58+0000 lvl=eror msg="Dangling trie nodes after full cleanup"
t=2023-06-06T14:50:58+0000 lvl=info msg="Writing clean trie cache to disk"       path=/.../geth/triecache threads=24
t=2023-06-06T14:50:58+0000 lvl=info msg="Persisted the clean trie cache"         path=/.../geth/triecache elapsed=519.793ms
t=2023-06-06T14:50:58+0000 lvl=info msg="Blockchain stopped"
t=2023-06-06T14:51:03+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=38 static=44
t=2023-06-06T14:51:04+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=ffbcb224 err=EOF
t=2023-06-06T14:51:14+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=1  static=44
t=2023-06-06T14:51:24+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=4  static=44
t=2023-06-06T14:51:25+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=9085feb0 err=EOF
t=2023-06-06T14:51:28+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=a7ca772b err=EOF
t=2023-06-06T14:51:28+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=c5da28e2 err=EOF
t=2023-06-06T14:51:28+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=0c789f51 err=EOF
t=2023-06-06T14:51:28+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=9fdfe7c2 err=EOF
t=2023-06-06T14:51:38+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=38 static=44
t=2023-06-06T14:51:39+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=ffbcb224 err=EOF
t=2023-06-06T14:51:49+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=1  static=44
t=2023-06-06T14:51:59+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=4  static=44
t=2023-06-06T14:52:00+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=9085feb0 err=EOF
t=2023-06-06T14:52:03+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=0e4f9869 err=EOF
t=2023-06-06T14:52:03+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=803058b1 err=EOF
t=2023-06-06T14:52:03+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=c5da28e2 err=EOF
t=2023-06-06T14:52:03+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=1b59f42e err=EOF
t=2023-06-06T14:52:03+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=0c789f51 err=EOF
t=2023-06-06T14:52:03+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=3370c8d6 err=EOF
t=2023-06-06T14:52:03+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=9fdfe7c2 err=EOF
t=2023-06-06T14:52:13+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=38 static=44
t=2023-06-06T14:52:24+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=1  static=44
t=2023-06-06T14:52:34+0000 lvl=info msg="Looking for peers"                      peercount=0 tried=4  static=44
t=2023-06-06T14:52:35+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=9085feb0 err=EOF
t=2023-06-06T14:52:38+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=0e4f9869 err=EOF
t=2023-06-06T14:52:38+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=803058b1 err=EOF
t=2023-06-06T14:52:38+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=c5da28e2 err=EOF
t=2023-06-06T14:52:38+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=e29e3e88 err=EOF
t=2023-06-06T14:52:38+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=a7ca772b err=EOF
t=2023-06-06T14:52:38+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=1b59f42e err=EOF
t=2023-06-06T14:52:38+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=3370c8d6 err=EOF
t=2023-06-06T14:52:38+0000 lvl=eror msg="Bsc extension Handshake failed"         peer=9fdfe7c2 err=EOF

Backtrace

//== dump 1: 
goroutine 18035443 [runnable]:
github.com/syndtr/goleveldb/leveldb/cache.(*lru).Evict(0xc002b104c0?, 0xc06977fa40?)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/lru.go:138 +0x175
github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Close.func1({0xc26ac58000, 0x131ce, 0xc1481f3b60?})
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:661 +0x7f

github.com/syndtr/goleveldb/leveldb/cache.(*mHead).enumerateNodesWithCB(0xc144998380, 0xc1ddfb3b98)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:327 +0x58
github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Close(0xc0018823f0, 0x1)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:652 +0xb0
github.com/syndtr/goleveldb/leveldb.(*tOps).close(0xc002b0e690)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/table.go:494 +0x2a
github.com/syndtr/goleveldb/leveldb.(*session).close(0xc001ed4e10)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/session.go:101 +0x29
github.com/syndtr/goleveldb/leveldb.(*DB).Close(0x17?)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/db.go:1218 +0x2b4

github.com/ethereum/go-ethereum/ethdb/leveldb.(*Database).Close(0xc002252200)
        /home/runner/work/bsc/bsc/ethdb/leveldb/leveldb.go:180 +0x205
github.com/ethereum/go-ethereum/core/rawdb.(*freezerdb).Close(0xc0018f45a0)
        /home/runner/work/bsc/bsc/core/rawdb/database.go:50 +0xd0
github.com/ethereum/go-ethereum/node.(*closeTrackingDB).Close(0xc0002827c8)
        /home/runner/work/bsc/bsc/node/node.go:698 +0x99
github.com/ethereum/go-ethereum/eth.(*Ethereum).Stop(0xc0002a6360)
        /home/runner/work/bsc/bsc/eth/backend.go:684 +0x158
github.com/ethereum/go-ethereum/node.(*Node).stopServices(0xc00228c410, {0xc01dfece40, 0x2, 0x3be62318a99cbdfe?})
        /home/runner/work/bsc/bsc/node/node.go:321 +0xbd
github.com/ethereum/go-ethereum/node.(*Node).Close(0xc00228c410)
        /home/runner/work/bsc/bsc/node/node.go:241 +0x191
created by github.com/ethereum/go-ethereum/cmd/utils.StartNode.func1.1
        /home/runner/work/bsc/bsc/cmd/utils/cmd.go:92 +0x96


//== dump 2: 17s
goroutine 18035443 [runnable]:
github.com/syndtr/goleveldb/leveldb/cache.(*Node).callFinalizer(0xc1ca643b20)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:722 +0xf9
github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Close.func1({0xc273374000, 0x2190f, 0xc1481f3b60?})
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:665 +0xae

github.com/syndtr/goleveldb/leveldb/cache.(*mHead).enumerateNodesWithCB(0xc144998380, 0xc1ddfb3b98)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:327 +0x58
github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Close(0xc0018823f0, 0x1)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:652 +0xb0
github.com/syndtr/goleveldb/leveldb.(*tOps).close(0xc002b0e690)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/table.go:494 +0x2a
github.com/syndtr/goleveldb/leveldb.(*session).close(0xc001ed4e10)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/session.go:101 +0x29
github.com/syndtr/goleveldb/leveldb.(*DB).Close(0x17?)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/db.go:1218 +0x2b4

github.com/ethereum/go-ethereum/ethdb/leveldb.(*Database).Close(0xc002252200)
        /home/runner/work/bsc/bsc/ethdb/leveldb/leveldb.go:180 +0x205
github.com/ethereum/go-ethereum/core/rawdb.(*freezerdb).Close(0xc0018f45a0)
        /home/runner/work/bsc/bsc/core/rawdb/database.go:50 +0xd0
github.com/ethereum/go-ethereum/node.(*closeTrackingDB).Close(0xc0002827c8)
        /home/runner/work/bsc/bsc/node/node.go:698 +0x99
github.com/ethereum/go-ethereum/eth.(*Ethereum).Stop(0xc0002a6360)
        /home/runner/work/bsc/bsc/eth/backend.go:684 +0x158
github.com/ethereum/go-ethereum/node.(*Node).stopServices(0xc00228c410, {0xc01dfece40, 0x2, 0x3be62318a99cbdfe?})
        /home/runner/work/bsc/bsc/node/node.go:321 +0xbd
github.com/ethereum/go-ethereum/node.(*Node).Close(0xc00228c410)
        /home/runner/work/bsc/bsc/node/node.go:241 +0x191
created by github.com/ethereum/go-ethereum/cmd/utils.StartNode.func1.1
        /home/runner/work/bsc/bsc/cmd/utils/cmd.go:92 +0x96


//== dump 3: after 70s
goroutine 18035443 [runnable]:
github.com/syndtr/goleveldb/leveldb/cache.(*Node).callFinalizer(0xc03d4843f0)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:722 +0xf9
github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Close.func1({0xc299162000, 0x3b882, 0x39c00?})
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:665 +0xae

github.com/syndtr/goleveldb/leveldb/cache.(*mHead).enumerateNodesWithCB(0xc144998380, 0xc1ddfb3b98)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:327 +0x58
github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Close(0xc0018823f0, 0x1)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/cache/cache.go:652 +0xb0
github.com/syndtr/goleveldb/leveldb.(*tOps).close(0xc002b0e690)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/table.go:494 +0x2a
github.com/syndtr/goleveldb/leveldb.(*session).close(0xc001ed4e10)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/session.go:101 +0x29
github.com/syndtr/goleveldb/leveldb.(*DB).Close(0x17?)
        /home/runner/go/pkg/mod/github.com/syndtr/goleveldb@v1.0.1-0.20220721030215-126854af5e6d/leveldb/db.go:1218 +0x2b4

github.com/ethereum/go-ethereum/ethdb/leveldb.(*Database).Close(0xc002252200)
        /home/runner/work/bsc/bsc/ethdb/leveldb/leveldb.go:180 +0x205
github.com/ethereum/go-ethereum/core/rawdb.(*freezerdb).Close(0xc0018f45a0)
        /home/runner/work/bsc/bsc/core/rawdb/database.go:50 +0xd0
github.com/ethereum/go-ethereum/node.(*closeTrackingDB).Close(0xc0002827c8)
        /home/runner/work/bsc/bsc/node/node.go:698 +0x99
github.com/ethereum/go-ethereum/eth.(*Ethereum).Stop(0xc0002a6360)
        /home/runner/work/bsc/bsc/eth/backend.go:684 +0x158
github.com/ethereum/go-ethereum/node.(*Node).stopServices(0xc00228c410, {0xc01dfece40, 0x2, 0x3be62318a99cbdfe?})
        /home/runner/work/bsc/bsc/node/node.go:321 +0xbd
github.com/ethereum/go-ethereum/node.(*Node).Close(0xc00228c410)
        /home/runner/work/bsc/bsc/node/node.go:241 +0x191
created by github.com/ethereum/go-ethereum/cmd/utils.StartNode.func1.1
        /home/runner/work/bsc/bsc/cmd/utils/cmd.go:92 +0x96
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@brilliant-lx brilliant-lx

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@brilliant-lx