search

node-real / bsc-erigon

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

Node stuck with bad_block_hash=0x000...000 #121

Closed Zorato closed 1 year ago

Zorato commented 1 year ago

System information

Erigon version: 1.0.9

OS & Version: Ubuntu 22.04

Erigon Command (with flags/config):

./erigon \
 --chain=bsc \
 --log.console.verbosity=info \
 --datadir=./chaindata \
 --authrpc.port=8552  \
 --port=30310 \
 --torrent.download.rate=256mb \
 --private.api.addr=0.0.0.0:9093 \
 --torrent.port=42073 \
 --bodies.cache=1268435456 \
 --db.pagesize="16kb" \
  --maxpeers=1000 \
  --sentry.drop-useless-peers \
   --bootnodes="enode://f3cfd69f2808ef64838abd8786342c0b22fdd28268703c8d6812e26e109f9a7cb2b37bd49724ebb46c233289f22da82991c87345eb9a2dadeddb8f37eeb259ac@18.180.28.21:30311","enode://c0e8d1abd27c3c13ca879e16f34c12ffee936a7e5d7b7fb6f1af5cc75c6fad704e5667c7bbf7826fcb200d22b9bf86395271b0f76c21e63ad9a388ed548d4c90@54.65.247.12:30311","enode://b5772a14fdaeebf4c1924e73c923bdf11c35240a6da7b9e5ec0e6cbb95e78327690b90e8ab0ea5270debc8834454b98eca34cc2a19817f5972498648a6959a3a@54.170.158.102:30311","enode://352a361a9240d4d23bb6fab19cc6dc5a5fc6921abf19de65afe13f1802780aecd67c8c09d8c89043ff86947f171d98ab06906ef616d58e718067e02abea0dda9@79.125.105.65:30311","enode://21530e423b42aed17d7eef67882ebb23357db4f8b10c94d4c71191f52955d97dc13eec03cfeff0fe3a1c89c955e81a6970c09689d21ecbec2142b26b7e759c45@54.216.119.18:30311","enode://d61a31410c365e7fcd50e24d56a77d2d9741d4a57b295cc5070189ad90d0ec749d113b4b0432c6d795eb36597efce88d12ca45e645ec51b3a2144e1c1c41b66a@34.204.129.242:30311","enode://4653bc7c235c3480968e5e81d91123bc67626f35c207ae4acab89347db675a627784c5982431300c02f547a7d33558718f7795e848d547a327abb111eac73636@54.144.170.236:30311","enode://1479af5ea7bda822e8747d0b967309bced22cad5083b93bc6f4e1d7da7be067cd8495dc4c5a71579f2da8d9068f0c43ad6933d2b335a545b4ae49a846122b261@52.7.247.132:30311","enode://1cc4534b14cfe351ab740a1418ab944a234ca2f702915eadb7e558a02010cb7c5a8c295a3b56bcefa7701c07752acd5539cb13df2aab8ae2d98934d712611443@52.71.43.172:30311","enode://28b1d16562dac280dacaaf45d54516b85bc6c994252a9825c5cc4e080d3e53446d05f63ba495ea7d44d6c316b54cd92b245c5c328c37da24605c4a93a0d099c4@34.246.65.14:30311","enode://5a7b996048d1b0a07683a949662c87c09b55247ce774aeee10bb886892e586e3c604564393292e38ef43c023ee9981e1f8b335766ec4f0f256e57f8640b079d5@35.73.137.11:30311" \
 --metrics --metrics.port=6062 --metrics.addr=127.0.0.1

Chain/Network: Mainnet

Expected behaviour

Node survives reorgs or bad blocks, unwinds and keeps syncing.

Actual behaviour

Node is stuck and requires restart. After restart unwinds successfully and keeps synced. Happens occasionally, i.e. once a week.

Backtrace

[INFO] [06-04|11:27:55.267] [7/15 Execution] Completed on            block=28805641
[INFO] [06-04|11:27:55.675] Commit cycle                             in=106.970228ms
[INFO] [06-04|11:27:55.675] Timings (slower than 50ms)               Headers=2.514s Execution=113ms IntermediateHashes=64ms StorageHistoryIndex=56ms LogIndex=98ms
[INFO] [06-04|11:27:55.675] Tables                                   PlainState=241.2GB AccountChangeSet=558.7GB StorageChangeSet=1.3TB BlockTransaction=4.8GB TransactionLog=2.3TB FreeList=22.5MB ReclaimableSpace=90.1GB
[INFO] [06-04|11:27:55.675] RPC Daemon notified of new headers       from=28805640 to=28805641 hash=0xb64cd34989ff3c45f48048a376e67b2926107af7119671280f45de0a587f42bb header sending=19.969µs log sending=220ns
[INFO] [06-04|11:27:55.770] [2/15 Headers] Waiting for headers...    from=28805641
[INFO] [06-04|11:27:55.776] UnwindTo                                 block=28805639 bad_block_hash=0x0000000000000000000000000000000000000000000000000000000000000000
[INFO] [06-04|11:27:55.776] [2/15 Headers] Processed                 highest inserted=28805641 age=0
[INFO] [06-04|11:27:56.052] [8/15 HashState] Unwinding started       from=28805641 to=28805639 storage=false codes=true
[INFO] [06-04|11:27:56.058] [8/15 HashState] Unwinding started       from=28805641 to=28805639 storage=false codes=false
[INFO] [06-04|11:27:56.064] [8/15 HashState] Unwinding started       from=28805641 to=28805639 storage=true codes=false
[INFO] [06-04|11:27:56.083] [9/15 IntermediateHashes] Unwinding      from=28805641 to=28805639 csbucket=AccountChangeSet
[INFO] [06-04|11:27:56.087] [9/15 IntermediateHashes] Unwinding      from=28805641 to=28805639 csbucket=StorageChangeSet
[INFO] [06-04|11:27:56.202] [9/15 IntermediateHashes] Trie root      hash=0x6003aa23820ca834b19c9eb1ad6e38794964262b090bafc3cf3702ea84b806d5
[INFO] [06-04|11:27:56.257] [7/15 Execution] Unwind Execution        from=28805641 to=28805639
[WARN] [06-04|11:27:56.981] [txpool] flush: sender address not found by ID senderID=9614895
[WARN] [06-04|11:27:56.982] [txpool] flush: sender address not found by ID senderID=9245715
[WARN] [06-04|11:27:56.984] [txpool] flush: sender address not found by ID senderID=8081435
[INFO] [06-04|11:27:57.339] [7/15 Execution] Completed on            block=28805641
[EROR] [06-04|11:27:57.532] [9/15 IntermediateHashes] Wrong trie root of block 28805641: 21f195e6992094a1efee22be019b9f53c14dcb51ddd8e3747d7b15902ae0f0cf, expected (from header): 1c18a14e50e726846f4cf2deb4a32cb4109edca289ddb8ec9041dd9c2961aa72. Block hash: 3e6ddfd7739bb8a6ceeaaef1b55994921e2d7a8dc87a4ca19f9b54e20d6f4544 
[WARN] [06-04|11:27:57.532] Unwinding due to incorrect root hash     to=28805640
[INFO] [06-04|11:27:57.532] UnwindTo                                 block=28805640 bad_block_hash=0x3e6ddfd7739bb8a6ceeaaef1b55994921e2d7a8dc87a4ca19f9b54e20d6f4544
[INFO] [06-04|11:27:57.532] [8/15 HashState] Unwinding started       from=28805641 to=28805640 storage=false codes=true
[INFO] [06-04|11:27:57.538] [8/15 HashState] Unwinding started       from=28805641 to=28805640 storage=false codes=false
[INFO] [06-04|11:27:57.542] [8/15 HashState] Unwinding started       from=28805641 to=28805640 storage=true codes=false
[INFO] [06-04|11:27:57.552] [7/15 Execution] Unwind Execution        from=28805641 to=28805640
[INFO] [06-04|11:27:57.781] Commit cycle                             in=207.378218ms
[INFO] [06-04|11:27:57.781] Timings (slower than 50ms)               Unwind LogIndex=91ms Unwind StorageHistoryIndex=54ms Unwind CallTraces=88ms Unwind IntermediateHashes=174ms Bodies=720ms Execution=261ms IntermediateHashes=162ms
[INFO] [06-04|11:27:57.781] Tables                                   PlainState=241.2GB AccountChangeSet=558.7GB StorageChangeSet=1.3TB BlockTransaction=4.8GB TransactionLog=2.3TB FreeList=22.5MB ReclaimableSpace=90.1GB
[INFO] [06-04|11:27:57.958] [2/15 Headers] Waiting for headers...    from=28805640
[WARN] [06-04|11:27:57.999] [downloader] Rejected header marked as bad hash=0x3e6ddfd7739bb8a6ceeaaef1b55994921e2d7a8dc87a4ca19f9b54e20d6f4544 height=28805641
[WARN] [06-04|11:27:58.000] [downloader] Rejected header marked as bad hash=0x3e6ddfd7739bb8a6ceeaaef1b55994921e2d7a8dc87a4ca19f9b54e20d6f4544 height=28805641
[WARN] [06-04|11:27:58.003] [downloader] Rejected header marked as bad hash=0x3e6ddfd7739bb8a6ceeaaef1b55994921e2d7a8dc87a4ca19f9b54e20d6f4544 height=28805641
[WARN] [06-04|11:27:58.006] [downloader] Rejected header marked as bad hash=0x3e6ddfd7739bb8a6ceeaaef1b55994921e2d7a8dc87a4ca19f9b54e20d6f4544 height=28805641

After restart:

[INFO] [06-04|15:30:55.409] [1/15 Snapshots] Fetching torrent files metadata 
[INFO] [06-04|15:30:55.439] [snapshots] Blocks Stat                  blocks=28715k indices=28715k alloc=2.9GB sys=3.1GB
[INFO] [06-04|15:30:55.439] [2/15 Headers] Waiting for headers...    from=28805640
[INFO] [06-04|15:31:05.170] New txs subscriber joined 
[INFO] [06-04|15:31:05.170] new subscription to newHeaders established 
[INFO] [06-04|15:31:15.440] [2/15 Headers] Wrote block headers       number=28809440 blk/second=190.000 alloc=2.9GB sys=5.0GB
[INFO] [06-04|15:31:17.823] UnwindTo                                 block=28805639 bad_block_hash=0x0000000000000000000000000000000000000000000000000000000000000000
[INFO] [06-04|15:31:17.828] [2/15 Headers] Processed                 highest inserted=28810502 age=1s
[INFO] [06-04|15:31:17.828] [8/15 HashState] Unwinding started       from=28805640 to=28805639 storage=false codes=true
[INFO] [06-04|15:31:17.832] [8/15 HashState] Unwinding started       from=28805640 to=28805639 storage=false codes=false
[INFO] [06-04|15:31:17.836] [8/15 HashState] Unwinding started       from=28805640 to=28805639 storage=true codes=false
[INFO] [06-04|15:31:17.866] [7/15 Execution] Unwind Execution        from=28805640 to=28805639
[INFO] [06-04|15:31:18.400] [5/15 Bodies] Processing bodies...       from=28805639 to=28810502
[INFO] [06-04|15:31:38.401] [5/15 Bodies] Downloading block bodies   block_num=28805674 delivery/sec=740.9KB wasted/sec=0B remaining=4827 delivered=234 cache=12.4MB alloc=4.1GB sys=5.0GB
[INFO] [06-04|15:31:55.368] [txpool] stat                            pending=1279 baseFee=0 queued=2264 alloc=4.3GB sys=5.0GB
[INFO] [06-04|15:31:58.401] [5/15 Bodies] Downloading block bodies   block_num=28805674 delivery/sec=932.2KB wasted/sec=0B remaining=4827 delivered=543 cache=30.6MB alloc=4.4GB sys=5.0GB
[INFO] [06-04|15:32:18.401] [5/15 Bodies] Downloading block bodies   block_num=28805674 delivery/sec=941.6KB wasted/sec=0B remaining=4827 delivered=857 cache=49.0MB alloc=2.5GB sys=5.1GB
[INFO] [06-04|15:32:38.401] [5/15 Bodies] Downloading block bodies   block_num=28805741 delivery/sec=1.6MB wasted/sec=0B remaining=4760 delivered=1387 cache=77.6MB alloc=3.1GB sys=5.1GB

And syncing normally:

[INFO] [06-04|15:34:58.401] [5/15 Bodies] Downloading block bodies   block_num=28805809 delivery/sec=443.3KB wasted/sec=0B remaining=4692 delivered=3952 cache=226.1MB alloc=3.1GB sys=5.8GB
[INFO] [06-04|15:35:18.401] [5/15 Bodies] Downloading block bodies   block_num=28805809 delivery/sec=284.7KB wasted/sec=0B remaining=4692 delivered=4052 cache=231.7MB alloc=3.6GB sys=5.8GB
[INFO] [06-04|15:35:18.425] [5/15 Bodies] Processed                  highest=28805809
[INFO] [06-04|15:35:18.425] [5/15 Bodies] DONE                       in=4m0.024612117s
[INFO] [06-04|15:35:18.425] [6/15 Senders] Started                   from=28805639 to=28805809
[INFO] [06-04|15:35:18.515] [7/15 Execution] Blocks execution        from=28805639 to=28805809
[INFO] [06-04|15:35:35.506] [7/15 Execution] Completed on            block=28805809
[INFO] [06-04|15:35:35.506] [8/15 HashState] Promoting plain state   from=28805639 to=28805809
[INFO] [06-04|15:35:35.506] [8/15 HashState] Incremental promotion   from=28805639 to=28805809 codes=true csbucket=AccountChangeSet
[INFO] [06-04|15:35:36.431] [8/15 HashState] Incremental promotion   from=28805639 to=28805809 codes=false csbucket=AccountChangeSet
[INFO] [06-04|15:35:38.503] [8/15 HashState] Incremental promotion   from=28805639 to=28805809 codes=false csbucket=StorageChangeSet
[INFO] [06-04|15:35:43.675] [9/15 IntermediateHashes] Generating intermediate hashes from=28805639 to=28805809
[INFO] [06-04|15:35:53.466] [10/15 CallTraces] Pruned call trace intermediate table from=28715641 to=28715808
[INFO] [06-04|15:35:55.369] [txpool] stat                            pending=9910 baseFee=0 queued=11804 alloc=4.1GB sys=6.6GB
[INFO] [06-04|15:36:09.864] [13/15 LogIndex] processing              from=28805640 to=28805809
[INFO] [06-04|15:36:20.416] Timings (slower than 50ms)               Headers=22.388s BlockHashes=458ms Bodies=4m0.024s Senders=90ms Execution=16.99s HashState=8.169s IntermediateHashes=9.682s CallTraces=6.109s AccountHistoryIndex=3.991s Storage
HistoryIndex=6.405s LogIndex=5.752s TxLookup=4.799s
[INFO] [06-04|15:36:20.417] RPC Daemon notified of new headers       from=28809478 to=28810502 hash=0xd2fcecf7629e690b8da2fc8d449898a95c09e81785d77486e0554f76555aa536 header sending=910.869µs log sending=230ns
[INFO] [06-04|15:36:20.418] [2/15 Headers] Waiting for headers...    from=28810502
[INFO] [06-04|15:36:21.920] [2/15 Headers] Processed                 highest inserted=28810603 age=2s
[INFO] [06-04|15:36:21.936] [5/15 Bodies] Processing bodies...       from=28805809 to=28810603

Any help appreciated.

setunapo commented 1 year ago

Not sure if the database was broken, try unwind?

Zorato commented 1 year ago

Database is fine, after restart it does unwind automatically and proceeds syncing. The question is: why restart is necessary?

densone commented 1 year ago

I hav the same issue. It's killing me on a daily basis.

fylsan3 commented 1 year ago

我也有同样的问题，没有解决

Zorato commented 1 year ago

Happened again this night:

[INFO] [06-12|17:27:24.602] Commit cycle                             in=46.241019ms
[INFO] [06-12|17:27:24.602] Timings (slower than 50ms)               Headers=2.32s Execution=74ms HashState=54ms IntermediateHashes=96ms
[INFO] [06-12|17:27:24.602] Tables                                   PlainState=243.4GB AccountChangeSet=563.1GB StorageChangeSet=1.3TB BlockTransaction=4.7GB TransactionLog=2.3TB FreeList=400.0KB ReclaimableSpace=1.6GB
[INFO] [06-12|17:27:24.602] RPC Daemon notified of new headers       from=29042671 to=29042672 hash=0x1101b64939b0cb8973b17a650dc0ac31be661dea246960848d85c7e9ec244dbe header sending=10.057µs log sending=171ns
[INFO] [06-12|17:27:24.654] [2/15 Headers] Waiting for headers...    from=29042672
[INFO] [06-12|17:27:28.198] [2/15 Headers] Processed                 highest inserted=29042673 age=1s
[INFO] [06-12|17:27:29.797] [7/15 Execution] Completed on            block=29042673
[WARN] [06-12|17:27:32.074] [txpool] flush: sender address not found by ID senderID=2424745
[WARN] [06-12|17:27:32.074] [txpool] flush: sender address not found by ID senderID=2813765
[WARN] [06-12|17:27:32.074] [txpool] flush: sender address not found by ID senderID=2774952
[WARN] [06-12|17:27:32.074] [txpool] flush: sender address not found by ID senderID=2745241
[WARN] [06-12|17:27:32.075] [txpool] flush: sender address not found by ID senderID=878125
[INFO] [06-12|17:27:37.329] Commit cycle                             in=359.966601ms
[INFO] [06-12|17:27:37.329] Timings (slower than 50ms)               Headers=3.544s Bodies=71ms Execution=1.495s HashState=1.713s IntermediateHashes=3.278s CallTraces=737ms AccountHistoryIndex=395ms StorageHistoryIndex=499ms LogIndex=388ms TxLo
okup=157ms
[INFO] [06-12|17:27:37.329] Tables                                   PlainState=243.4GB AccountChangeSet=563.1GB StorageChangeSet=1.3TB BlockTransaction=4.7GB TransactionLog=2.3TB FreeList=400.0KB ReclaimableSpace=1.6GB
[INFO] [06-12|17:27:37.329] RPC Daemon notified of new headers       from=29042672 to=29042673 hash=0x08a4d0b5245ad8045b050551487cb7692944092566050158061838cd3054f4d3 header sending=10.228µs log sending=183ns
[INFO] [06-12|17:27:37.690] [2/15 Headers] Waiting for headers...    from=29042673
[INFO] [06-12|17:27:37.694] UnwindTo                                 block=29042672 bad_block_hash=0x0000000000000000000000000000000000000000000000000000000000000000
[INFO] [06-12|17:27:37.694] [2/15 Headers] Processed                 highest inserted=29042675 age=2s
[INFO] [06-12|17:27:37.908] [8/15 HashState] Unwinding started       from=29042673 to=29042672 storage=false codes=true
[INFO] [06-12|17:27:38.453] [8/15 HashState] Unwinding started       from=29042673 to=29042672 storage=false codes=false
[INFO] [06-12|17:27:38.464] [8/15 HashState] Unwinding started       from=29042673 to=29042672 storage=true codes=false
[INFO] [06-12|17:27:38.505] [9/15 IntermediateHashes] Unwinding      from=29042673 to=29042672 csbucket=AccountChangeSet
[INFO] [06-12|17:27:38.512] [9/15 IntermediateHashes] Unwinding      from=29042673 to=29042672 csbucket=StorageChangeSet
[INFO] [06-12|17:27:38.798] [9/15 IntermediateHashes] Trie root      hash=0x868c71da3011cd8d5aab4f337f8b9dc43dbca9662b369da4615f41c69b756219
[INFO] [06-12|17:27:39.032] [7/15 Execution] Unwind Execution        from=29042673 to=29042672
[INFO] [06-12|17:27:39.511] [7/15 Execution] Completed on            block=29042675
[INFO] [06-12|17:27:40.367] Commit cycle                             in=352.459461ms
[INFO] [06-12|17:27:40.367] Timings (slower than 50ms)               Unwind LogIndex=88ms Unwind StorageHistoryIndex=68ms Unwind AccountHistoryIndex=52ms Unwind HashState=597ms Unwind IntermediateHashes=526ms Unwind Execution=100ms Bodies=243ms Execution=125ms HashState=87ms IntermediateHashes=168ms CallTraces=70ms StorageHistoryIndex=53ms
[INFO] [06-12|17:27:40.367] Tables                                   PlainState=243.4GB AccountChangeSet=563.1GB StorageChangeSet=1.3TB BlockTransaction=4.7GB TransactionLog=2.3TB FreeList=400.0KB ReclaimableSpace=1.6GB
[INFO] [06-12|17:27:40.367] RPC Daemon notified of new headers       from=29042672 to=29042675 hash=0x1f13dc6fafe0eb0bf6a6cdda06020630f3e1c8b2ee95c889045fce1e4f090bfb header sending=15.461µs log sending=180ns
[INFO] [06-12|17:27:40.728] [2/15 Headers] Waiting for headers...    from=29042675
[INFO] [06-12|17:27:40.729] UnwindTo                                 block=29042672 bad_block_hash=0x0000000000000000000000000000000000000000000000000000000000000000
[INFO] [06-12|17:27:40.729] [2/15 Headers] Processed                 highest inserted=29042675 age=2s
[INFO] [06-12|17:27:40.889] [8/15 HashState] Unwinding started       from=29042675 to=29042672 storage=false codes=true
[INFO] [06-12|17:27:40.896] [8/15 HashState] Unwinding started       from=29042675 to=29042672 storage=false codes=false
[INFO] [06-12|17:27:40.900] [8/15 HashState] Unwinding started       from=29042675 to=29042672 storage=true codes=false
[INFO] [06-12|17:27:40.906] [9/15 IntermediateHashes] Unwinding      from=29042675 to=29042672 csbucket=AccountChangeSet
[INFO] [06-12|17:27:40.908] [9/15 IntermediateHashes] Unwinding      from=29042675 to=29042672 csbucket=StorageChangeSet
[INFO] [06-12|17:27:40.959] [9/15 IntermediateHashes] Trie root      hash=0x868c71da3011cd8d5aab4f337f8b9dc43dbca9662b369da4615f41c69b756219
[INFO] [06-12|17:27:40.975] [7/15 Execution] Unwind Execution        from=29042675 to=29042672
[INFO] [06-12|17:27:41.689] [7/15 Execution] Completed on            block=29042675
[EROR] [06-12|17:27:42.395] [9/15 IntermediateHashes] Wrong trie root of block 29042675: 08040d1f958f27325d13d17420a2c7edfc908b8088f1c5e28c9f93375d9adf38, expected (from header): 5ad0bf6d2a817c45662635150c1fa932b5f8fc3409f98b8cba836692bebfb2ce. Block hash: 013b83a729b399f15f9f75f608a50f5186b3eb1f19154221eaf62c34a0657926 
[WARN] [06-12|17:27:42.395] Unwinding due to incorrect root hash     to=29042673
[INFO] [06-12|17:27:42.395] UnwindTo                                 block=29042673 bad_block_hash=0x013b83a729b399f15f9f75f608a50f5186b3eb1f19154221eaf62c34a0657926
[INFO] [06-12|17:27:42.395] [8/15 HashState] Unwinding started       from=29042675 to=29042673 storage=false codes=true
[INFO] [06-12|17:27:42.398] [8/15 HashState] Unwinding started       from=29042675 to=29042673 storage=false codes=false
[INFO] [06-12|17:27:42.400] [8/15 HashState] Unwinding started       from=29042675 to=29042673 storage=true codes=false
[INFO] [06-12|17:27:42.405] [7/15 Execution] Unwind Execution        from=29042675 to=29042673
[INFO] [06-12|17:27:42.644] Commit cycle                             in=231.03729ms
[INFO] [06-12|17:27:42.645] Timings (slower than 50ms)               Unwind CallTraces=93ms Unwind IntermediateHashes=68ms Bodies=244ms Execution=426ms HashState=167ms IntermediateHashes=539ms
[INFO] [06-12|17:27:42.645] Tables                                   PlainState=243.4GB AccountChangeSet=563.1GB StorageChangeSet=1.3TB BlockTransaction=4.7GB TransactionLog=2.3TB FreeList=400.0KB ReclaimableSpace=1.6GB
[INFO] [06-12|17:27:42.859] [2/15 Headers] Waiting for headers...    from=29042673
[INFO] [06-12|17:27:46.270] [p2p] GoodPeers                          eth67=121 eth66=48 eth68=36
[WARN] [06-12|17:27:47.167] [downloader] Rejected header marked as bad hash=0x013b83a729b399f15f9f75f608a50f5186b3eb1f19154221eaf62c34a0657926 height=29042675
[WARN] [06-12|17:27:47.336] [txpool] flush: sender address not found by ID senderID=2424745
[WARN] [06-12|17:27:47.337] [txpool] flush: sender address not found by ID senderID=2813765
[WARN] [06-12|17:27:47.337] [txpool] flush: sender address not found by ID senderID=2774952
[WARN] [06-12|17:27:47.337] [txpool] flush: sender address not found by ID senderID=2745241
[WARN] [06-12|17:27:47.338] [txpool] flush: sender address not found by ID senderID=878125
[WARN] [06-12|17:28:02.591] [txpool] flush: sender address not found by ID senderID=2745241
[WARN] [06-12|17:28:02.592] [txpool] flush: sender address not found by ID senderID=878125
[WARN] [06-12|17:28:02.593] [txpool] flush: sender address not found by ID senderID=2424745
[WARN] [06-12|17:28:02.593] [txpool] flush: sender address not found by ID senderID=2813765
[WARN] [06-12|17:28:02.593] [txpool] flush: sender address not found by ID senderID=2774952
[INFO] [06-12|17:28:02.859] [2/15 Headers] No block headers to write in this log period block number=29042673

Logs after restart this morning:

[INFO] [06-13|05:59:15.297] Got interrupt, shutting down... 
[INFO] [06-13|05:59:15.299] Exiting... 
[INFO] [06-13|05:59:15.300] Exiting Engine... 
[INFO] [06-13|05:59:15.300] RPC server shutting down 
[INFO] [06-13|05:59:15.300] RPC server shutting down 
[INFO] [06-13|05:59:15.301] HTTP endpoint closed                     url=127.0.0.1:8545
[INFO] [06-13|05:59:15.301] RPC server shutting down 
[WARN] [06-13|05:59:15.301] Failed to serve http endpoint            err="http: Server closed"
[WARN] [06-13|05:59:15.301] Failed to serve http endpoint            err="http: Server closed"
[INFO] [06-13|05:59:15.301] Engine HTTP endpoint close               url=127.0.0.1:8551
[INFO] [06-13|05:59:18.769] logging to file system                   log dir=/home/blockchain/bsc-mainnet/chaindata/logs file prefix=erigon log level=info json=false
[INFO] [06-13|05:59:18.769] Starting metrics server                  addr=http://0.0.0.0:8675/debug/metrics/prometheus
[INFO] [06-13|05:59:18.775] Build info                               git_branch=HEAD git_tag= git_commit=fd69c47adc6170a54bedb320ab010800cf6b0776
[INFO] [06-13|05:59:18.775] Starting Erigon on BSC mainnet... 
[INFO] [06-13|05:59:18.777] Maximum peer count                       ETH=1000 total=1000
[INFO] [06-13|05:59:18.777] starting HTTP APIs                       APIs=eth,erigon,engine
[INFO] [06-13|05:59:18.777] torrent verbosity                        level=WRN
[INFO] [06-13|05:59:20.881] Set global gas cap                       cap=50000000
[INFO] [06-13|05:59:20.886] [Downloader] Runnning with               ipv6-enabled=true ipv4-enabled=true download.rate=16mb upload.rate=4mb
[INFO] [06-13|05:59:20.888] Opening Database                         label=chaindata path=/home/blockchain/bsc-mainnet/chaindata/chaindata
[INFO] [06-13|05:59:20.888] [db] params: growStep=2GB, mapsSize=7TB, shrinkThreshold=-1, pageSize=16KB, label=chaindata, WriteMap=false, Durable=false, NoReadahead=true,  
[INFO] [06-13|05:59:20.891] Initialised chain configuration          config="{ChainID: 56 Ramanujan: 0, Niels: 0, MirrorSync: 5184000, Bruno: 13082000, Euler: 18907621, Gibbs: 23846001, Nano: 21962149, Moran: 22107423, Gibbs: 23846001, Planck: 
27281024, Luban: 29020050, Plato: <nil>, Engine: parlia}" genesis=0x0d21840abff46b96c84b2ac9e10e4f5cdaeb5693cb665db62a2f3b02d2d57b5b
[INFO] [06-13|05:59:20.891] Effective                                prune_flags= snapshot_flags="--snapshots=true" history.v3=false
[INFO] [06-13|05:59:25.162] Initialising Ethereum protocol           network=56
[INFO] [06-13|05:59:26.228] Starting private RPC server              on=127.0.0.1:9090
[INFO] [06-13|05:59:26.228] new subscription to logs established 
[INFO] [06-13|05:59:26.228] rpc filters: subscribing to Erigon events 
[INFO] [06-13|05:59:26.228] new subscription to newHeaders established 
[INFO] [06-13|05:59:26.228] New txs subscriber joined 
[INFO] [06-13|05:59:26.229] Reading JWT secret                       path=/home/blockchain/bsc-mainnet/chaindata/jwt.hex
[INFO] [06-13|05:59:26.229] HTTP endpoint opened for Engine API      url=127.0.0.1:8551 ws=true ws.compression=true
[INFO] [06-13|05:59:26.229] HTTP endpoint opened                     url=127.0.0.1:8545 ws=false ws.compression=true grpc=false
[INFO] [06-13|05:59:26.269] [txpool] Started 
[INFO] [06-13|05:59:26.273] Started P2P networking                   version=68 self=enode://a37960674277b55eacc6ec7e1cfba4b1f875e222fc06a6d7f33f94b4c2b810a58e520a11b3b3316dbabc7eb4b7262862dfccd94f36f66c075d4ec0eb500c720f@127.0.0.1:0 name=erigo
n/v2.43.0-dev-fd69c47a/linux-amd64/go1.19.9
[INFO] [06-13|05:59:26.274] Started P2P networking                   version=67 self=enode://a37960674277b55eacc6ec7e1cfba4b1f875e222fc06a6d7f33f94b4c2b810a58e520a11b3b3316dbabc7eb4b7262862dfccd94f36f66c075d4ec0eb500c720f@127.0.0.1:0 name=erigo
n/v2.43.0-dev-fd69c47a/linux-amd64/go1.19.9
[INFO] [06-13|05:59:26.276] [1/15 Snapshots] Fetching torrent files metadata 
[INFO] [06-13|05:59:26.292] [snapshots] Blocks Stat                  blocks=28952k indices=28952k alloc=3.2GB sys=3.4GB
[INFO] [06-13|05:59:26.292] [2/15 Headers] Waiting for headers...    from=29042673
[INFO] [06-13|05:59:29.263] New txs subscriber joined 
[INFO] [06-13|05:59:29.263] new subscription to newHeaders established 
[INFO] [06-13|05:59:46.293] [2/15 Headers] Wrote block headers       number=29046473 blk/second=190.000 alloc=3.6GB sys=5.2GB
[INFO] [06-13|06:00:06.293] [2/15 Headers] Wrote block headers       number=29050273 blk/second=190.000 alloc=4.4GB sys=5.2GB
[INFO] [06-13|06:00:15.897] UnwindTo                                 block=29042672 bad_block_hash=0x0000000000000000000000000000000000000000000000000000000000000000
[INFO] [06-13|06:00:15.905] [2/15 Headers] Processed                 highest inserted=29057679 age=2s
[INFO] [06-13|06:00:15.905] [8/15 HashState] Unwinding started       from=29042673 to=29042672 storage=false codes=true
[INFO] [06-13|06:00:16.105] [8/15 HashState] Unwinding started       from=29042673 to=29042672 storage=false codes=false
[INFO] [06-13|06:00:16.263] [8/15 HashState] Unwinding started       from=29042673 to=29042672 storage=true codes=false
[INFO] [06-13|06:00:16.879] [7/15 Execution] Unwind Execution        from=29042673 to=29042672
[INFO] [06-13|06:00:20.261] [5/15 Bodies] Processing bodies...       from=29042672 to=29057679
[INFO] [06-13|06:00:40.262] [5/15 Bodies] Downloading block bodies   block_num=29046264 delivery/sec=11.9MB wasted/sec=0B remaining=11414 delivered=4885 cache=59.5MB alloc=4.6GB sys=6.0GB
[INFO] [06-13|06:01:00.263] [5/15 Bodies] Downloading block bodies   block_num=29046264 delivery/sec=11.6MB wasted/sec=0B remaining=11414 delivered=10463 cache=256.0MB alloc=3.9GB sys=6.0GB
[INFO] [06-13|06:01:20.262] [5/15 Bodies] Downloading block bodies   block_num=29052651 delivery/sec=10.2MB wasted/sec=0B remaining=5027 delivered=14811 cache=136.5MB alloc=2.7GB sys=6.5GB
[INFO] [06-13|06:01:25.162] [p2p] GoodPeers                          eth66=48 eth67=22 eth68=1
[INFO] [06-13|06:01:40.262] [5/15 Bodies] Downloading block bodies   block_num=29052941 delivery/sec=2.9MB wasted/sec=0B remaining=4737 delivered=16088 cache=183.2MB alloc=3.3GB sys=6.5GB
[INFO] [06-13|06:02:00.263] [5/15 Bodies] Downloading block bodies   block_num=29052941 delivery/sec=1.6MB wasted/sec=0B remaining=4737 delivered=16713 cache=215.4MB alloc=3.7GB sys=6.5GB
[INFO] [06-13|06:02:07.310] [5/15 Bodies] Processed                  highest=29057679
[INFO] [06-13|06:02:07.310] [5/15 Bodies] DONE                       in=1m47.048327286s
[INFO] [06-13|06:02:07.310] [6/15 Senders] Started                   from=29042672 to=29057679
[INFO] [06-13|06:02:21.846] [7/15 Execution] Blocks execution        from=29042672 to=29057679
[INFO] [06-13|06:02:41.902] [7/15 Execution] Executed blocks         number=29042880 blk/s=10.4 tx/s=1490.1 Mgas/s=173.3 gasState=0.01 batch=6.4MB alloc=6.0GB sys=6.6GB
[INFO] [06-13|06:03:01.948] [7/15 Execution] Executed blocks         number=29043109 blk/s=11.4 tx/s=1596.9 Mgas/s=198.4 gasState=0.01 batch=15.1MB alloc=3.3GB sys=7.1GB
[INFO] [06-13|06:03:21.891] [7/15 Execution] Executed blocks         number=29043362 blk/s=12.7 tx/s=1821.4 Mgas/s=217.4 gasState=0.02 batch=23.9MB alloc=2.8GB sys=7.1GB
fylsan3 commented 1 year ago

[INFO] [06-14|01:21:53.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=29069105 skelMax=29069297 resp=857 respMin=29069105 respMax=29080865 dups=141426 [WARN] [06-14|01:22:08.273] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:22:13.836] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:22:13.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=724 respMin=29069105 respMax=29080871 dups=125823 [WARN] [06-14|01:22:23.718] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:22:23.761] [p2p] GoodPeers eth66=66 eth67=139 eth68=12 [INFO] [06-14|01:22:33.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:22:33.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=788 respMin=29069105 respMax=29080878 dups=129321 [WARN] [06-14|01:22:39.154] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:22:53.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:22:53.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=29069105 skelMax=29069297 resp=879 respMin=29069105 respMax=29080885 dups=136863 [WARN] [06-14|01:22:54.594] [txpool] flush: sender address not found by ID senderID=1189111 [WARN] [06-14|01:23:10.030] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:23:13.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:23:13.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=720 respMin=29069105 respMax=29080891 dups=126010 [WARN] [06-14|01:23:25.476] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:23:33.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:23:33.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=773 respMin=29069105 respMax=29080898 dups=125870 [WARN] [06-14|01:23:40.914] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:23:53.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:23:53.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=29069105 skelMax=29069297 resp=799 respMin=29069105 respMax=29080905 dups=135447 [WARN] [06-14|01:23:56.349] [txpool] flush: sender address not found by ID senderID=1189111 [WARN] [06-14|01:24:11.790] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:24:13.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:24:13.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=737 respMin=29069105 respMax=29080911 dups=127173 [INFO] [06-14|01:24:23.761] [p2p] GoodPeers eth67=139 eth66=66 eth68=12 [WARN] [06-14|01:24:27.234] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:24:33.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:24:33.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=29069105 skelMax=29069297 resp=681 respMin=29069105 respMax=29080918 dups=125397 [WARN] [06-14|01:24:42.671] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:24:53.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:24:53.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=797 respMin=29069105 respMax=29080925 dups=134679 [WARN] [06-14|01:24:58.108] [txpool] flush: sender address not found by ID senderID=1189111 [WARN] [06-14|01:25:13.546] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:25:13.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:25:13.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=705 respMin=29069105 respMax=29080931 dups=125420

fylsan3 commented 1 year ago

[INFO] [06-14|01:21:53.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=29069105 skelMax=29069297 resp=857 respMin=29069105 respMax=29080865 dups=141426 [WARN] [06-14|01:22:08.273] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:22:13.836] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:22:13.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=724 respMin=29069105 respMax=29080871 dups=125823 [WARN] [06-14|01:22:23.718] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:22:23.761] [p2p] GoodPeers eth66=66 eth67=139 eth68=12 [INFO] [06-14|01:22:33.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:22:33.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=788 respMin=29069105 respMax=29080878 dups=129321 [WARN] [06-14|01:22:39.154] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:22:53.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:22:53.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=29069105 skelMax=29069297 resp=879 respMin=29069105 respMax=29080885 dups=136863 [WARN] [06-14|01:22:54.594] [txpool] flush: sender address not found by ID senderID=1189111 [WARN] [06-14|01:23:10.030] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:23:13.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:23:13.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=720 respMin=29069105 respMax=29080891 dups=126010 [WARN] [06-14|01:23:25.476] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:23:33.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:23:33.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=773 respMin=29069105 respMax=29080898 dups=125870 [WARN] [06-14|01:23:40.914] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:23:53.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:23:53.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=29069105 skelMax=29069297 resp=799 respMin=29069105 respMax=29080905 dups=135447 [WARN] [06-14|01:23:56.349] [txpool] flush: sender address not found by ID senderID=1189111 [WARN] [06-14|01:24:11.790] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:24:13.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:24:13.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=737 respMin=29069105 respMax=29080911 dups=127173 [INFO] [06-14|01:24:23.761] [p2p] GoodPeers eth67=139 eth66=66 eth68=12 [WARN] [06-14|01:24:27.234] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:24:33.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:24:33.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=29069105 skelMax=29069297 resp=681 respMin=29069105 respMax=29080918 dups=125397 [WARN] [06-14|01:24:42.671] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:24:53.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:24:53.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=797 respMin=29069105 respMax=29080925 dups=134679 [WARN] [06-14|01:24:58.108] [txpool] flush: sender address not found by ID senderID=1189111 [WARN] [06-14|01:25:13.546] [txpool] flush: sender address not found by ID senderID=1189111 [INFO] [06-14|01:25:13.837] [2/15 Headers] No block headers to write in this log period block number=29069106 [INFO] [06-14|01:25:13.837] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=29069105 skelMax=29069297 resp=705 respMin=29069105 respMax=29080931 dups=125420

昨天重启后今天又遇到这种状况了。

Zorato commented 1 year ago

And again this night 😞

Doc-Pixel commented 1 year ago

I see this happen somewhere between a couple of times a day to once in a couple of days on my BSC mainnet box as well. Restart takes care of it.

0x1un commented 1 year ago

I'm having the same problem in v1.1.1

du5 commented 1 year ago

I'm having the same problem in v1.1.4

blxdyx commented 1 year ago

You can try our latest commit. It's been working fine for a week now