search

ethereum / go-ethereum

Go implementation of the Ethereum protocol
https://geth.ethereum.org
GNU Lesser General Public License v3.0
47.31k stars 20.02k forks source link

panic: pebble: batch too large: >= 4.0 G #27813

Closed muyinliu closed 1 year ago

muyinliu commented 1 year ago

System information

Geth version: 1.12.0-stable(build from source https://github.com/ethereum/go-ethereum/archive/refs/tags/v1.12.0.tar.gz with go1.19.11 linux/amd64) CL client & version: Prysm/v4.0.5/aa7d0df7ff5f74168bdaf93453c856f279ec1573. Built at: 2023-05-22 18:10:34+00:00 OS & Version: Linux(Ubuntu 22.04.2 LTS)

Expected behaviour

initial sync success

Actual behaviour

sync failed with error message: panic: pebble: batch too large: >= 4.0 G

Steps to reproduce the behaviour

/usr/local/bin/geth --datadir /mnt/data/geth-ethereum --port 34303 --discovery.port 34303 --maxpeers 100 --cache 16000 --http --http.api eth,net,web3,admin,debug,txpool,personal --http.port 8445 --ws --ws.api eth,net,web3,admin,debug,txpool,personal --ws.port 8446 --authrpc.port 8451 --syncmode snap

Backtrace

panic: pebble: batch too large: >= 4.0 G

goroutine 651770 [running]:
github.com/cockroachdb/pebble.(*Batch).grow(0x35dd1b567ceceea6?, 0xe344c46ded795670?)
    github.com/cockroachdb/pebble@v0.0.0-20230209160836-829675f94811/batch.go:1183 +0x129
github.com/cockroachdb/pebble.(*Batch).prepareDeferredKeyValueRecord(0xc006adac80, 0x20, 0x25, 0x1)
    github.com/cockroachdb/pebble@v0.0.0-20230209160836-829675f94811/batch.go:480 +0x8d
github.com/cockroachdb/pebble.(*Batch).SetDeferred(...)
    github.com/cockroachdb/pebble@v0.0.0-20230209160836-829675f94811/batch.go:576
github.com/cockroachdb/pebble.(*Batch).Set(0xc006adac80?, {0xc024129240?, 0x20?, 0x59a200?}, {0xc01088c000?, 0x25?, 0x1c?}, 0x1c?)
    github.com/cockroachdb/pebble@v0.0.0-20230209160836-829675f94811/batch.go:558 +0x45
github.com/ethereum/go-ethereum/ethdb/pebble.(*batch).Put(0xc00bdac678, {0xc024129240?, 0x20, 0xc01088c000?}, {0xc01088c000?, 0x25, 0x2060e20?})
    github.com/ethereum/go-ethereum/ethdb/pebble/pebble.go:514 +0x3b
github.com/ethereum/go-ethereum/ethdb.HookedBatch.Put({{0x206a9a0?, 0xc00bdac678?}, 0xc04404bec0?, 0x0?}, {0xc024129240?, 0x20?, 0x20?}, {0xc01088c000, 0x25, 0x4000})
    github.com/ethereum/go-ethereum/ethdb/batch.go:65 +0xc6
github.com/ethereum/go-ethereum/core/rawdb.WriteLegacyTrieNode({0x2060e20, 0xc01232dea0}, {0xb4, 0xfa, 0xde, 0x28, 0x9d, 0xbd, 0xa7, 0x67, ...}, ...)
    github.com/ethereum/go-ethereum/core/rawdb/accessors_trie.go:160 +0x99
github.com/ethereum/go-ethereum/core/rawdb.WriteTrieNode({0x2060e20?, 0xc01232dea0?}, {0x15, 0x9e, 0x48, 0x90, 0xcd, 0xe4, 0x6d, 0x5c, ...}, ...)
    github.com/ethereum/go-ethereum/core/rawdb/accessors_trie.go:230 +0xa5
github.com/ethereum/go-ethereum/eth/protocols/snap.(*Syncer).loadSyncStatus.func4({0x15, 0x9e, 0x48, 0x90, 0xcd, 0xe4, 0x6d, 0x5c, 0xad, 0xbf, ...}, ...)
    github.com/ethereum/go-ethereum/eth/protocols/snap/sync.go:752 +0x112
github.com/ethereum/go-ethereum/trie.(*StackTrie).hashRec(0xc04fbf21c0, 0xc03f1fa960, {0xc02c1e17d8, 0x8, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:483 +0x725
github.com/ethereum/go-ethereum/trie.(*StackTrie).hashRec(0xc04fbf28c0, 0xc03f1fa960, {0xc02c1e17d8, 0x7, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:429 +0x7f0
github.com/ethereum/go-ethereum/trie.(*StackTrie).hash(0xc02c1e17d0?, {0xc02c1e17d8, 0x7, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:405 +0x99
github.com/ethereum/go-ethereum/trie.(*StackTrie).insert(0xc04fbf2c40, {0xc011ef8c36, 0x3a, 0x3b}, {0xc006d54f48, 0x15, 0x15}, {0xc02c1e17d8, 0x6, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:257 +0xd25
github.com/ethereum/go-ethereum/trie.(*StackTrie).insert(0xc04fbf2a80, {0xc011ef8c35, 0x3b, 0x3c}, {0xc006d54f48, 0x15, 0x15}, {0xc02c1e17d8, 0x5, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:267 +0xe6f
github.com/ethereum/go-ethereum/trie.(*StackTrie).insert(0xc03f121340, {0xc011ef8c34, 0x3c, 0x3d}, {0xc006d54f48, 0x15, 0x15}, {0xc02c1e17d8, 0x4, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:267 +0xe6f
github.com/ethereum/go-ethereum/trie.(*StackTrie).insert(0xc04b3c47e0, {0xc011ef8c33, 0x3d, 0x3e}, {0xc006d54f48, 0x15, 0x15}, {0xc02c1e17d8, 0x3, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:267 +0xe6f
github.com/ethereum/go-ethereum/trie.(*StackTrie).insert(0xc04a3a6540, {0xc011ef8c32, 0x3e, 0x3f}, {0xc006d54f48, 0x15, 0x15}, {0xc02c1e17d8, 0x2, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:267 +0xe6f
github.com/ethereum/go-ethereum/trie.(*StackTrie).insert(0xc04034fc00, {0xc011ef8c31, 0x3f, 0x40}, {0xc006d54f48, 0x15, 0x15}, {0xc02c1e17d8, 0x1, 0x8})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:267 +0xe6f
github.com/ethereum/go-ethereum/trie.(*StackTrie).insert(0xc0108ddce0, {0xc011ef8c30, 0x40, 0x41}, {0xc006d54f48, 0x15, 0x15}, {0x0, 0x0, 0x0})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:282 +0x72e
github.com/ethereum/go-ethereum/trie.(*StackTrie).Update(0x5c6de4cd90489e15?, {0xc036210da0, 0x20, 0x12ae5ed03e74cc10?}, {0xc006d54f48, 0x15, 0x15})
    github.com/ethereum/go-ethereum/trie/stacktrie.go:211 +0x11d
github.com/ethereum/go-ethereum/eth/protocols/snap.(*Syncer).processStorageResponse(0xc000240900, 0xc0170c4500)
    github.com/ethereum/go-ethereum/eth/protocols/snap/sync.go:2089 +0x1499
github.com/ethereum/go-ethereum/eth/protocols/snap.(*Syncer).Sync(0xc000240900, {0x46, 0xa6, 0xa0, 0x1e, 0x70, 0x84, 0xa2, 0x4c, 0x97, ...}, ...)
    github.com/ethereum/go-ethereum/eth/protocols/snap/sync.go:709 +0xe5f
github.com/ethereum/go-ethereum/eth/downloader.(*stateSync).run(0xc016120a80)
    github.com/ethereum/go-ethereum/eth/downloader/statesync.go:107 +0x66
created by github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).runStateSync
    github.com/ethereum/go-ethereum/eth/downloader/statesync.go:63 +0x12a

INFO [07-30|23:30:51.790] Starting Geth on Ethereum mainnet... 
INFO [07-30|23:30:51.793] Maximum peer count                       ETH=100 LES=0 total=100
INFO [07-30|23:30:51.794] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
INFO [07-30|23:30:51.799] Set global gas cap                       cap=50,000,000
INFO [07-30|23:30:51.799] Initializing the KZG library             backend=gokzg
INFO [07-30|23:30:51.821] Allocated trie memory caches             clean=2.34GiB dirty=3.91GiB
INFO [07-30|23:30:51.829] Using pebble as the backing database 
INFO [07-30|23:30:51.829] Allocated cache and file handles         database=/mnt/data/geth-ethereum/geth/chaindata cache=7.81GiB handles=262,144
Fatal: Failed to register the Ethereum service: pebble: inconsistent batch count: 458287021 vs 501152459
INFO [07-30|23:30:52.975] Starting Geth on Ethereum mainnet... 
INFO [07-30|23:30:52.979] Maximum peer count                       ETH=100 LES=0 total=100
INFO [07-30|23:30:52.979] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
INFO [07-30|23:30:52.981] Set global gas cap                       cap=50,000,000
INFO [07-30|23:30:52.981] Initializing the KZG library             backend=gokzg
INFO [07-30|23:30:52.999] Allocated trie memory caches             clean=2.34GiB dirty=3.91GiB
INFO [07-30|23:30:53.006] Using pebble as the backing database 
INFO [07-30|23:30:53.007] Allocated cache and file handles         database=/mnt/data/geth-ethereum/geth/chaindata cache=7.81GiB handles=262,144
Fatal: Failed to register the Ethereum service: pebble: inconsistent batch count: 458287021 vs 501152459
karalabe commented 1 year ago

Do you have some logs from before the crash? I'm curious how fast you're downloading data (state specifically) that you managed to hit such an error.

muyinliu commented 1 year ago

All logs: chain.log

holiman commented 1 year ago

Relevant part

INFO [07-30|23:27:48.526] Forkchoice requested sync to new head    number=17,806,737 hash=6138d4..6f65b1 finalized=17,806,660
INFO [07-30|23:27:54.640] Syncing: chain download in progress      synced=25.29% chain=15.15GiB   headers=4,540,416@1.48GiB    bodies=4,502,789@8.88GiB    receipts=4,502,789@4.80GiB   eta=3h7m12.576s
INFO [07-30|23:27:56.454] Syncing: state download in progress      synced=10.91% state=36.56GiB   accounts=24,216,966@5.46GiB   slots=152,357,892@30.31GiB codes=143,498@810.30MiB eta=8h32m14.890s
INFO [07-30|23:28:00.569] Forkchoice requested sync to new head    number=17,806,738 hash=c07695..2f2fe2 finalized=17,806,660
ERROR[07-30|23:28:03.711] Expired request does not exist           peer=8cebf11b6c9db1de7a8c524b572e9918823de766935c16fcae6bdf80d5b81d05
INFO [07-30|23:28:04.197] Syncing: chain download in progress      synced=25.31% chain=15.20GiB   headers=4,546,560@1.48GiB    bodies=4,506,701@8.91GiB    receipts=4,506,701@4.81GiB   eta=3h7m27.734s
INFO [07-30|23:28:04.530] Syncing: state download in progress      synced=10.92% state=36.77GiB   accounts=24,238,641@5.47GiB   slots=153,404,946@30.51GiB codes=143,624@811.02MiB eta=8h34m50.969s
INFO [07-30|23:28:12.916] Syncing: state download in progress      synced=10.94% state=36.94GiB   accounts=24,271,042@5.48GiB   slots=154,243,493@30.67GiB codes=143,746@811.84MiB eta=8h36m34.187s
INFO [07-30|23:28:13.168] Syncing: chain download in progress      synced=25.36% chain=15.31GiB   headers=4,554,752@1.48GiB    bodies=4,515,330@8.99GiB    receipts=4,515,330@4.84GiB   eta=3h7m25.368s
INFO [07-30|23:28:13.613] Forkchoice requested sync to new head    number=17,806,739 hash=0ab0f7..1dfda6 finalized=17,806,660
INFO [07-30|23:28:20.925] Syncing: state download in progress      synced=10.97% state=37.12GiB   accounts=24,335,941@5.49GiB   slots=155,075,369@30.83GiB codes=144,114@814.01MiB eta=8h37m37.628s
INFO [07-30|23:28:21.223] Syncing: chain download in progress      synced=25.40% chain=15.40GiB   headers=4,560,896@1.48GiB    bodies=4,522,389@9.05GiB    receipts=4,522,389@4.86GiB   eta=3h7m25.507s
INFO [07-30|23:28:24.311] Forkchoice requested sync to new head    number=17,806,740 hash=7abd78..d5f62a finalized=17,806,660
INFO [07-30|23:28:29.355] Syncing: state download in progress      synced=11.00% state=37.31GiB   accounts=24,402,219@5.51GiB   slots=155,962,129@31.00GiB codes=144,442@815.94MiB eta=8h32m42.982s
INFO [07-30|23:28:29.528] Syncing: chain download in progress      synced=25.44% chain=15.50GiB   headers=4,569,088@1.49GiB    bodies=4,530,276@9.12GiB    receipts=4,530,276@4.89GiB   eta=3h7m23.611s
INFO [07-30|23:28:36.915] Forkchoice requested sync to new head    number=17,806,741 hash=81a5a9..c8ffad finalized=17,806,660
INFO [07-30|23:28:37.380] Syncing: state download in progress      synced=11.02% state=37.49GiB   accounts=24,445,526@5.52GiB   slots=156,847,684@31.18GiB codes=144,711@817.70MiB eta=8h34m23.604s
INFO [07-30|23:28:39.579] Syncing: chain download in progress      synced=25.49% chain=15.61GiB   headers=4,579,328@1.49GiB    bodies=4,539,429@9.20GiB    receipts=4,539,429@4.92GiB   eta=3h7m22.574s
INFO [07-30|23:28:45.407] Syncing: state download in progress      synced=11.05% state=37.65GiB   accounts=24,510,445@5.53GiB   slots=157,578,566@31.32GiB codes=144,997@819.44MiB eta=8h35m7.414s
INFO [07-30|23:28:47.828] Syncing: chain download in progress      synced=25.55% chain=15.73GiB   headers=4,587,520@1.50GiB    bodies=4,549,155@9.28GiB    receipts=4,549,155@4.95GiB   eta=3h7m14.359s
INFO [07-30|23:28:48.825] Forkchoice requested sync to new head    number=17,806,742 hash=1eff5a..1d4a9e finalized=17,806,660
INFO [07-30|23:28:53.435] Syncing: state download in progress      synced=11.08% state=37.83GiB   accounts=24,576,639@5.55GiB   slots=158,427,018@31.48GiB codes=145,321@821.35MiB eta=8h36m10.788s
INFO [07-30|23:28:56.695] Syncing: chain download in progress      synced=25.59% chain=15.83GiB   headers=4,595,712@1.50GiB    bodies=4,556,080@9.35GiB    receipts=4,556,080@4.98GiB   eta=3h7m17.210s
INFO [07-30|23:29:00.406] Forkchoice requested sync to new head    number=17,806,743 hash=12ab7e..db7cfe finalized=17,806,660
INFO [07-30|23:29:01.465] Syncing: state download in progress      synced=11.11% state=38.01GiB   accounts=24,645,017@5.56GiB   slots=159,273,750@31.65GiB codes=145,752@824.13MiB eta=8h31m3.993s
INFO [07-30|23:29:05.116] Syncing: chain download in progress      synced=25.60% chain=15.88GiB   headers=4,597,760@1.50GiB    bodies=4,559,323@9.39GiB    receipts=4,559,323@4.99GiB   eta=3h7m30.941s
INFO [07-30|23:29:09.467] Syncing: state download in progress      synced=11.14% state=38.18GiB   accounts=24,699,058@5.57GiB   slots=160,042,804@31.80GiB codes=146,025@825.97MiB eta=8h32m5.874s
INFO [07-30|23:29:12.836] Forkchoice requested sync to new head    number=17,806,744 hash=040c37..294c84 finalized=17,806,660
INFO [07-30|23:29:13.162] Syncing: chain download in progress      synced=25.65% chain=16.00GiB   headers=4,605,952@1.50GiB    bodies=4,567,657@9.47GiB    receipts=4,567,657@5.02GiB   eta=3h7m26.657s
INFO [07-30|23:29:17.479] Syncing: state download in progress      synced=11.16% state=38.36GiB   accounts=24,753,131@5.59GiB   slots=160,909,929@31.96GiB codes=146,302@827.76MiB eta=8h33m24.447s
INFO [07-30|23:29:25.019] Syncing: chain download in progress      synced=25.70% chain=16.10GiB   headers=4,616,192@1.51GiB    bodies=4,575,606@9.54GiB    receipts=4,575,606@5.05GiB   eta=3h7m34.670s
INFO [07-30|23:29:25.412] Forkchoice requested sync to new head    number=17,806,745 hash=339d7b..4a166b finalized=17,806,660
INFO [07-30|23:29:25.578] Syncing: state download in progress      synced=11.19% state=38.56GiB   accounts=24,817,971@5.60GiB   slots=161,869,504@32.15GiB codes=146,648@830.08MiB eta=8h34m46.636s
INFO [07-30|23:29:31.809] Syncing: state download in progress      synced=11.21% state=38.68GiB   accounts=24,850,360@5.61GiB   slots=162,404,599@32.25GiB codes=146,810@831.23MiB eta=8h29m26.151s
WARN [07-30|23:29:31.829] Unexpected storage ranges packet         peer=7d00185b reqid=460,519,733,052,131,223
WARN [07-30|23:29:31.982] Unexpected storage ranges packet         peer=98caaca1 reqid=6,927,607,668,762,139,694
ERROR[07-30|23:29:33.211] Expired request does not exist           peer=6c5e799dfe03a45ff523c4be89eeb38b9ffb00e746c27de0ad914414a1d0c886
ERROR[07-30|23:29:33.211] Expired request does not exist           peer=6c5e799dfe03a45ff523c4be89eeb38b9ffb00e746c27de0ad914414a1d0c886
INFO [07-30|23:29:33.642] Syncing: chain download in progress      synced=25.74% chain=16.22GiB   headers=4,622,336@1.51GiB    bodies=4,584,225@9.62GiB    receipts=4,584,225@5.08GiB   eta=3h7m31.068s
INFO [07-30|23:29:36.771] Forkchoice requested sync to new head    number=17,806,746 hash=ef80bf..a798b3 finalized=17,806,660
INFO [07-30|23:29:41.915] Syncing: chain download in progress      synced=25.77% chain=16.29GiB   headers=4,626,432@1.51GiB    bodies=4,589,316@9.67GiB    receipts=4,589,316@5.10GiB   eta=3h7m38.091s
INFO [07-30|23:29:49.073] Forkchoice requested sync to new head    number=17,806,747 hash=8ff477..626d72 finalized=unknown
INFO [07-30|23:29:49.962] Syncing: chain download in progress      synced=25.81% chain=16.40GiB   headers=4,634,624@1.52GiB    bodies=4,596,579@9.75GiB    receipts=4,596,579@5.13GiB   eta=3h7m37.242s
INFO [07-30|23:29:58.529] Syncing: chain download in progress      synced=25.86% chain=16.51GiB   headers=4,642,816@1.52GiB    bodies=4,604,062@9.83GiB    receipts=4,604,062@5.16GiB   eta=3h7m37.150s
INFO [07-30|23:30:01.923] Forkchoice requested sync to new head    number=17,806,748 hash=245962..3486f1 finalized=unknown
INFO [07-30|23:30:08.966] Syncing: chain download in progress      synced=25.89% chain=16.59GiB   headers=4,648,960@1.52GiB    bodies=4,609,811@9.89GiB    receipts=4,609,811@5.18GiB   eta=3h7m48.099s
panic: pebble: batch too large: >= 4.0 G
karalabe commented 1 year ago

Thanks for the report. It surfaces a rare and mostly harmless bug. You seem to have hit the very improbable path that actually blew up :)