search

node-real / bsc-erigon

Ethereum implementation on the efficiency frontier
GNU Lesser General Public License v3.0
125 stars 40 forks source link

err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:2" #387

Closed pc-quiknode closed 4 months ago

pc-quiknode commented 4 months ago

System information

Erigon version: erigon version 1.2.7-dev

OS & Version: Linux

Commit hash: https://github.com/node-real/bsc-erigon/commit/1c9e207c65e4cec47e68a3eee32ca569a5d714d6

Issue

Our nodes are stuck in a loop of [5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:2

[2/15 Headers] Waiting for headers...    from=40177466
[2/15 Headers] Processed                 highest=40177533 age=53s headers=67 in=0.128 blk/sec=523
[5/15 Bodies] Processing bodies...       from=40177466 to=40177533
Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:2"
[2/15 Headers] Waiting for headers...    from=40177466
[2/15 Headers] Processed                 highest=40177554 age=2s headers=88 in=0.118 blk/sec=745
[5/15 Bodies] Processing bodies...       from=40177466 to=40177554
Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:2"
[2/15 Headers] Waiting for headers...    from=40177466
[2/15 Headers] Processed                 highest=40177557 age=1s headers=91 in=0.158 blk/sec=577
[5/15 Bodies] Processing bodies...       from=40177466 to=40177557
Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:2"
[2/15 Headers] Waiting for headers...    from=40177466
[2/15 Headers] Processed                 highest=40177560 age=3s headers=94 in=0.125 blk/sec=750
[5/15 Bodies] Processing bodies...       from=40177466 to=40177560
Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:2"
[2/15 Headers] Waiting for headers...    from=40177466
[2/15 Headers] Processed                 highest=40177564 age=2s headers=98 in=0.130 blk/sec=753
[5/15 Bodies] Processing bodies...       from=40177466 to=40177564
harshsingh-cs commented 4 months ago

Facing the same issue

blxdyx commented 4 months ago

Try restart?

harshsingh-cs commented 4 months ago

@blxdyx Tried did not help Actually the [EROR] [05-09|09:12:01.705] Staged Sync err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:4" appeared after restart Before it was 

 err="failed MdbxKV cursor.Seek(): mdbx_cursor_get: MDBX_BAD_VALSIZE: Invalid size or alignment of key or data for target database, either invalid subDB name, bucket: PoolTransaction,  key: 292f5c308341e0d92e6327f0daf26bfb02e242d0d7a1f418cec61ac34e23be7e"
[WARN] [05-09|08:53:29.175] [rpc] served                             conn=10.100.26.88:33974 method=eth_feeHistory reqid=6369023567291614 t=302.945µs err="request beyond head block: requested 40177058, head 40177056"
[WARN] [05-09|08:53:29.282] [rpc] served                             conn=10.100.26.88:33974 method=eth_feeHistory reqid=4716567559346192 t=376.484µs err="request beyond head block: requested 40177057, head 40177056"
[INFO] [05-09|08:53:29.408] [2/15 Headers] Waiting for headers...    from=40177056
[WARN] [05-09|08:53:29.412] [rpc] served                             conn=10.100.26.88:33974 method=eth_feeHistory reqid=7345505564336888 t=307.732µs err="request beyond head block: requested 40177058, head 40177056"
[WARN] [05-09|08:53:29.429] [rpc] served                             conn=10.100.26.88:33974 method=eth_feeHistory reqid=3608448839414913 t=407.434µs err="request beyond head block: requested 40177058, head 40177056"
[WARN] [05-09|08:53:29.504] [downloader] Rejected header marked as bad hash=0xd9a63d09204e68780f80a852cd49a44a00019cd607d370264373464920ede0ef height=40177057
[WARN] [05-09|08:53:29.505] [downloader] Rejected header marked as bad
blxdyx commented 4 months ago

Reproduced, checking

blxdyx commented 4 months ago

temporary fix: integration state_stages --unwind=20 --chain=bsc --datadir=/path integration stage_headers --unwind=20 --chain=bsc --datadir=/path then restart

use v1.2.6

Zorato commented 4 months ago

Unwinding resolved the issue. Using v1.2.7 on BSC testnet.

harshsingh-cs commented 4 months ago

It did not help :( 

INFO] [05-09|11:53:19.108] [txpool] stat                            pending=0 baseFee=0 queued=2690 alloc=158.6MB sys=564.5MB
[WARN] [05-09|11:53:59.919] Caller gas above allowance, capping      requested=69998932 cap=50000000
[INFO] [05-09|11:54:03.179] [13/15 LogIndex] processing              from=40177037 to=40180460
[INFO] [05-09|11:54:34.041] [13/15 LogIndex] ETL [2/2] Loading       into=LogTopicIndex current_prefix=000000000000000000000000f8cee87a2bb8f3dd618f7ef5725c7e1934d58e35ffffffff
[WARN] [05-09|11:54:37.479] Caller gas above allowance, capping      requested=69998932 cap=50000000
[INFO] [05-09|11:55:27.147] [14/15 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=7f2e7beb
[INFO] [05-09|11:55:57.152] [14/15 TxLookup] ETL [2/2] Loading       into=BlockTransactionLookup current_prefix=fbae26c5
[INFO] [05-09|11:55:58.082] [14/15 TxLookup] DONE                    in=1m2.176015683s
[INFO] [05-09|11:55:58.950] RPC Daemon notified of new headers       from=40179436 to=40180460 amount=1024 hash=0xf702deb0c8c7d3f58a84826d52ad48d2c4656d63e797203e8c7f6595f09b6dfc header sending=1.478421ms log sending=500.908732ms
[INFO] [05-09|11:55:58.950] Timings (slower than 50ms)               Headers=7.128s BlockHashes=2.524s Bodies=3m20.286s Senders=803ms Execution=1m50.81s HashState=51.507s IntermediateHashes=1m58.093s CallTraces=40.845s AccountHistoryIndex=30.321s StorageHistoryIndex=21.733s LogIndex=52.727s TxLookup=1m2.176s
[INFO] [05-09|11:55:58.950] Tables                                   PlainState=41.6GB AccountChangeSet=28.7GB StorageChangeSet=92.3GB BlockTransaction=216.0GB TransactionLog=196.2GB FreeList=112.0KB ReclaimableSpace=112.0MB
[INFO] [05-09|11:55:59.655] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:56:00.454] [2/15 Headers] Processed                 highest=40180691 age=1s headers=231 in=0.800 blk/sec=288
[INFO] [05-09|11:56:00.605] [5/15 Bodies] Processing bodies...       from=40180460 to=40180691
[EROR] [05-09|11:56:06.741] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:56:07.966] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:56:08.468] [2/15 Headers] Processed                 highest=40180694 age=0 headers=234 in=0.502 blk/sec=466
[INFO] [05-09|11:56:08.472] [5/15 Bodies] Processing bodies...       from=40180460 to=40180694
[INFO] [05-09|11:56:12.045] [p2p] GoodPeers                          eth68=4
[INFO] [05-09|11:56:12.494] [mem] memory stats                       Rss=8.1MB Size=0B Pss=8.1MB SharedClean=4B SharedDirty=0B PrivateClean=7.7MB PrivateDirty=394.7KB Referenced=8.1MB Anonymous=395.2KB Swap=0B alloc=139.5MB sys=564.5MB
[EROR] [05-09|11:56:14.381] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:56:15.566] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:56:17.312] [2/15 Headers] Processed                 highest=40180697 age=0 headers=237 in=1.746 blk/sec=135
[INFO] [05-09|11:56:17.316] [5/15 Bodies] Processing bodies...       from=40180460 to=40180697
[INFO] [05-09|11:56:19.107] [txpool] stat                            pending=0 baseFee=0 queued=3349 alloc=185.8MB sys=564.5MB
[WARN] [05-09|11:56:23.179] Caller gas above allowance, capping      requested=70000000 cap=50000000
[EROR] [05-09|11:56:25.249] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:56:26.451] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:56:28.072] [2/15 Headers] Processed                 highest=40180700 age=2s headers=240 in=1.622 blk/sec=147
[INFO] [05-09|11:56:28.077] [5/15 Bodies] Processing bodies...       from=40180460 to=40180700
[EROR] [05-09|11:56:33.457] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:56:34.680] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:56:35.269] [2/15 Headers] Processed                 highest=40180703 age=0 headers=243 in=0.589 blk/sec=412
[INFO] [05-09|11:56:35.274] [5/15 Bodies] Processing bodies...       from=40180460 to=40180703
[EROR] [05-09|11:56:41.248] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:56:42.552] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:56:44.173] [2/15 Headers] Processed                 highest=40180706 age=0 headers=246 in=1.621 blk/sec=151
[INFO] [05-09|11:56:44.177] [5/15 Bodies] Processing bodies...       from=40180460 to=40180706
[EROR] [05-09|11:56:49.474] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:56:50.962] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:56:52.760] [2/15 Headers] Processed                 highest=40180708 age=2s headers=248 in=1.799 blk/sec=137
[INFO] [05-09|11:56:52.765] [5/15 Bodies] Processing bodies...       from=40180460 to=40180708
[EROR] [05-09|11:56:58.676] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:56:59.830] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:57:01.605] [2/15 Headers] Processed                 highest=40180711 age=2s headers=251 in=1.775 blk/sec=141
[INFO] [05-09|11:57:01.610] [5/15 Bodies] Processing bodies...       from=40180460 to=40180711
[EROR] [05-09|11:57:09.944] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:57:11.351] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:57:12.489] [2/15 Headers] Processed                 highest=40180715 age=1s headers=255 in=1.138 blk/sec=224
[INFO] [05-09|11:57:12.495] [5/15 Bodies] Processing bodies...       from=40180460 to=40180715
[EROR] [05-09|11:57:20.961] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:57:22.143] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:57:23.297] [2/15 Headers] Processed                 highest=40180719 age=0 headers=259 in=1.154 blk/sec=224
[INFO] [05-09|11:57:23.302] [5/15 Bodies] Processing bodies...       from=40180460 to=40180719
[EROR] [05-09|11:57:32.005] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:57:33.203] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:57:34.946] [2/15 Headers] Processed                 highest=40180722 age=2s headers=262 in=1.742 blk/sec=150
[INFO] [05-09|11:57:34.954] [5/15 Bodies] Processing bodies...       from=40180460 to=40180722
[EROR] [05-09|11:57:42.512] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:57:43.649] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:57:44.420] [2/15 Headers] Processed                 highest=40180726 age=0 headers=266 in=0.771 blk/sec=344
[INFO] [05-09|11:57:44.426] [5/15 Bodies] Processing bodies...       from=40180460 to=40180726
[EROR] [05-09|11:57:50.994] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
[INFO] [05-09|11:57:52.226] [2/15 Headers] Waiting for headers...    from=40180460
[INFO] [05-09|11:57:53.416] [2/15 Headers] Processed                 highest=40180729 age=0 headers=269 in=1.190 blk/sec=226
[INFO] [05-09|11:57:53.422] [5/15 Bodies] Processing bodies...       from=40180460 to=40180729
[EROR] [05-09|11:58:02.822] Staged Sync                              err="[5/15 Bodies] blob info mismatch: sidecars 0, versionedHashes:3"
blxdyx commented 4 months ago

Try again?

harshsingh-cs commented 4 months ago

Worked, thanks @blxdyx

harshsingh-cs commented 4 months ago

It has happened again

pc-quiknode commented 4 months ago

unwind doesn't seem to work this time

blxdyx commented 4 months ago

unwind and use v.1.2.6 can work v1.2.7 have some bugs

harshsingh-cs commented 4 months ago

It is happening on 1.2.6 as well 

[WARN] [05-10|11:19:49.465] [fetch] onNewBlock                       err="failed MdbxKV cursor.Seek(): mdbx_cursor_get: MDBX_BAD_VALSIZE: Invalid size or alignment of key or data for target database, either invalid subDB name, bucket: PoolTransaction,  key: 363187a30387868f8a45452ed9c10ec294b1f8f3e8c2572040e6d08a20e0e6bc"
[EROR] [05-10|11:19:49.586] RPC method eth_getTransactionCount crashed: runtime error: invalid memory address or nil pointer dereference
[service.go:219 panic.go:914 panic.go:261 signal_unix.go:861 eth_accounts.go:70 value.go:596 value.go:380 service.go:224 handler.go:532 handler.go:482 handler.go:421 handler.go:204 asm_amd64.s:1650]
[WARN] [05-10|11:19:49.586] [rpc] served                             conn=10.100.10.65:60288 method=eth_getTransactionCount reqid=1149839364325318 t=480.81µs err="method handler crashed"
[INFO] [05-10|11:19:49.593] [2/15 Headers] Waiting for headers...    from=40208752
[WARN] [05-10|11:19:49.626] [downloader] Rejected header marked as bad hash=0x99c053e882fc3cdc60ec554cb1ba633cced2f8f0e01165646da4f90999e7b0ad height=40208753
[WARN] [05-10|11:19:49.726] [downloader] Rejected header marked as bad hash=0x99c053e882fc3cdc60ec554cb1ba633cced2f8f0e01165646da4f90999e7b0ad height=40208753
[WARN] [05-10|11:19:49.734] [downloader] Rejected header marked as bad hash=0x99c053e882fc3cdc60ec554cb1ba633cced2f8f0e01165646da4f90999e7b0ad height=40208753
[WARN] [05-10|11:19:49.982] [rpc] served                             conn=10.100.10.65:60288 method=eth_sendRawTransaction reqid=1149839364325319 t=774.935µs err="ALREADY_EXISTS: already known"
[WARN] [05-10|11:19:50.268] [downloader] Rejected header marked as bad hash=0x99c053e882fc3cdc60ec554cb1ba633cced2f8f0e01165646da4f90999e7b0ad height=40208753
[WARN] [05-10|11:19:50.356] [downloader] Rejected header marked as bad hash=0x99c053e882fc3cdc60ec554cb1ba633cced2f8f0e01165646da4f90999e7b0ad height=40208753
[WARN] [05-10|11:19:50.374] [downloader] Rejected header marked as bad hash=0x99c053e882fc3cdc60ec554cb1ba633cced2f8f0e01165646da4f90999e7b0ad height=40208753
[WARN] [05-10|11:19:50.384] [downloader] Rejected header marked as bad hash=0x99c053e882fc3cdc60ec554cb1ba633cced2f8f0e01165646da4f90999e7b0ad height=40208753
harshsingh-cs commented 4 months ago

@pc-quiknode did you manage to get it syncing again?

pc-quiknode commented 4 months ago

@pc-quiknode did you manage to get it syncing again?

Downgrading to 1.2.6 works for me

harshsingh-cs commented 4 months ago

Yes it did work for me but just now started see the errors again

harshsingh-cs commented 4 months ago

@blxdyx will there be an official release which fixes this issue ?

sokiaoba commented 4 months ago

Constantly having the same issue with 1.2.6

avinashbo commented 4 months ago

Rewind + 1.2.6 only helps for a while before the nodes stop syncing again

insider89 commented 4 months ago

Have the same issue. Unwind didn't fix the issue.

blxdyx commented 4 months ago

Will release a bug fix version later

sokiaoba commented 4 months ago

Thank you, when the new release will be created? We need a docker image for it. @blxdyx

avinashbo commented 4 months ago

Any update on the bug fix ?

blxdyx commented 4 months ago

The latest release v1.2.8 have fixed it.