SnapSync failed at: State Heal

[jerk188]

System information

Geth version: 1.1.18
OS & Version: Ubuntu 18.04.6 LTS
Commit hash : 03ff299

Backtrace

Hello, I use snapshots to resynchronize node data to save my disk space, but I find that I have not been able to synchronize the latest block height, and the currentBlock value queried using eth.syncing is catching up with the highestBlock every time The value will stop changing, which causes the currentBlock value and highestBlock value to always differ by 50-100 block heights. Unable to end the eth.syncing state, but the log information shows that the block height of the browser has been caught up.Through monitoring, it is found that the host hardware resources have not reached the bottleneck。

Console query details：

log screenshot：

t=2023-01-29T07:35:27+0000 lvl=info msg="Imported new block headers" count=1 elapsed="383.775µs" number=25,200,076 hash=0x5be3fcc16399bae2cc1b65622b6b10b25a1622de318bb6bf7dc935a2cc157c2c
t=2023-01-29T07:35:29+0000 lvl=info msg="State heal in progress" accounts=53880@2.90MiB slots=627,702@43.38MiB codes=93907@761.27MiB nodes=152,672,711@19.01GiB pending=1
t=2023-01-29T07:35:31+0000 lvl=info msg="Imported new block headers" count=1 elapsed="355.568µs" number=25,200,077 hash=0x199b002006efda7f326f0805bd37caeb94e5ab33d35d296a8142ed335b8c50aa
t=2023-01-29T07:35:34+0000 lvl=info msg="Imported new block headers" count=1 elapsed="341.353µs" number=25,200,078 hash=0x2d83beb7e2703b775110220dfa9b7269f645644721894f7423d05b7c54e39675
t=2023-01-29T07:35:37+0000 lvl=info msg="Imported new block headers" count=1 elapsed="347.128µs" number=25,200,079 hash=0xfd87f076eba44ed4ac8f76dfb76feb11ec4850cafb663814278260ab9ec6edb3
t=2023-01-29T07:35:41+0000 lvl=info msg="Imported new block headers" count=1 elapsed="341.706µs" number=25,200,080 hash=0xfed6d6085e7278a95e7c9633c44eeb134aa778869a91afc6c267c60185a70cde
t=2023-01-29T07:35:41+0000 lvl=info msg="Imported new block headers" count=1 elapsed="361.377µs" number=25,200,081 hash=0xdb5780b907de434a6ab5a1f3ce0102a2ba38f13d843f3693f52b86ba43569d46
t=2023-01-29T07:35:45+0000 lvl=info msg="Imported new block headers" count=1 elapsed="377.132µs" number=25,200,082 hash=0x69dcdd948c855ab85a41ed053e85ec422325085fd928933fedb37aafd3dfff5e
t=2023-01-29T07:35:48+0000 lvl=info msg="Imported new block headers" count=1 elapsed="343.96µs" number=25,200,083 hash=0xa8c55b610a676f5f8d91a30cc5ad873a0f3dfca494c3256a6871570a4adc0f9d
t=2023-01-29T07:35:51+0000 lvl=info msg="Imported new block headers" count=1 elapsed="844.661µs" number=25,200,084 hash=0x4007641a50b3e3b655d23d76cb9430f82b66934fbc6d08dc22c47b5cbc496293
t=2023-01-29T07:35:54+0000 lvl=info msg="Downloader queue stats" receiptTasks=0 blockTasks=0 itemSize="218.73 KiB" throttle=1199
t=2023-01-29T07:35:54+0000 lvl=warn msg="Pivot became stale, moving" old=25,199,942 new=25,200,010
t=2023-01-29T07:35:54+0000 lvl=info msg="Imported new block receipts" count=68 elapsed=68.086ms number=25,200,009 hash=0x0ff40eedc973a694c05637326ce1b4dc42d292169c7e52e914102a52547909d8 age=3m55s size="8.14 MiB"
t=2023-01-29T07:35:54+0000 lvl=info msg="State heal in progress" accounts=53880@2.90MiB slots=627,702@43.38MiB codes=93907@761.27MiB nodes=152,672,711@19.01GiB pending=1
t=2023-01-29T07:35:55+0000 lvl=info msg="Imported new block headers" count=1 elapsed="352.1µs" number=25,200,085 hash=0x01f86c1037a8fb62717346e1f2bcf777fbc7fcddee6e50b50348793992677e36
t=2023-01-29T07:35:58+0000 lvl=info msg="Imported new block headers" count=1 elapsed="364.409µs" number=25,200,086 hash=0x30653d157c9c88a3e4b2f02f49fdfa43b7e4005c00ba463a5558e9fff1d5cd75
t=2023-01-29T07:36:01+0000 lvl=info msg="Imported new block headers" count=1 elapsed="390.284µs" number=25,200,087 hash=0x15ecbf0b41cb0745cc6296afc363ff8a6911fcdc5a481b462f92777b5474e73f
t=2023-01-29T07:36:04+0000 lvl=info msg="State heal in progress" accounts=53880@2.90MiB slots=627,702@43.38MiB codes=93907@761.27MiB nodes=152,672,711@19.01GiB pending=1
t=2023-01-29T07:36:05+0000 lvl=info msg="Imported new block headers" count=1 elapsed="340.653µs" number=25,200,088 hash=0x994c63eabbc4c55ea0810bf22d8092c8b17a806fd7e0c05d99ae722ec8e2d3e4
t=2023-01-29T07:36:05+0000 lvl=info msg="Imported new block headers" count=1 elapsed="336.333µs" number=25,200,089 hash=0xf7313348e6c42673bb318986fd2a2e02f363bda651b6ce7b34efcc111d245087
t=2023-01-29T07:36:09+0000 lvl=info msg="Imported new block headers" count=1 elapsed="341.095µs" number=25,200,090 hash=0x0b96e1a477a4996e1e965067642235267b228eaf8ddb722f0183587318adfe28
t=2023-01-29T07:36:13+0000 lvl=info msg="Imported new block headers" count=1 elapsed="335.071µs" number=25,200,091 hash=0x3ed4dcfc50f6fb2d86e53cb85076d903ff598bbfd15aa592e3cb705ffd1c653e
t=2023-01-29T07:36:16+0000 lvl=info msg="State heal in progress" accounts=53880@2.90MiB slots=627,702@43.38MiB codes=93907@761.27MiB nodes=152,672,711@19.01GiB pending=1
t=2023-01-29T07:36:16+0000 lvl=info msg="Imported new block headers" count=1 elapsed="364.358µs" number=25,200,092 hash=0x47146e8c3f5041ae9e00b315010639d18b82231533e1a65ddbafc6318d091ed3
t=2023-01-29T07:36:20+0000 lvl=info msg="Imported new block headers" count=1 elapsed="347.381µs" number=25,200,093 hash=0x53b7e722711318c0d94ce4fd739f316c976401b3a9d3165350579bd21a052582
t=2023-01-29T07:36:23+0000 lvl=info msg="Imported new block headers" count=1 elapsed="335.533µs" number=25,200,094 hash=0x394441dcf8bedc581824e991d6a75831c9bd2868bde67319ed68ae1953c0d221
t=2023-01-29T07:36:24+0000 lvl=info msg="State heal in progress" accounts=53880@2.90MiB slots=627,702@43.38MiB codes=93907@761.27MiB nodes=152,672,711@19.01GiB pending=1
t=2023-01-29T07:36:26+0000 lvl=info msg="Imported new block headers" count=2 elapsed="502.222µs" number=25,200,096 hash=0x8a42817c85bc0c96a9fafe5b049ee31bf99c492215c991554c1bac0d6e44defa
t=2023-01-29T07:36:30+0000 lvl=info msg="Imported new block headers" count=1 elapsed="370.909µs" number=25,200,097 hash=0xa3d56206af183abfe1989a68b2d06824bca9f103fa0d828291adea60a7f93a74
t=2023-01-29T07:36:34+0000 lvl=info msg="Imported new block headers" count=1 elapsed="360.15µs" number=25,200,098 hash=0x9fefe8d98e65b94884ee0a84dce89b88a88f09a633971dbc11a053c6b734f35f
t=2023-01-29T07:36:35+0000 lvl=info msg="State heal in progress" accounts=53880@2.90MiB slots=627,702@43.38MiB codes=93907@761.27MiB nodes=152,672,720@19.01GiB pending=145
t=2023-01-29T07:36:37+0000 lvl=info msg="Imported new block headers" count=1 elapsed="363.75µs" number=25,200,099 hash=0x6fea5f87c3e886c7fcf84b436048f462397258ff83db59fe5788e6e466658447
t=2023-01-29T07:36:41+0000 lvl=info msg="Imported new block headers" count=2 elapsed="538.373µs" number=25,200,101 hash=0xfe4a3c1a213692f5db250e59304ea16a00a54a644c461cb759755007b2973615
t=2023-01-29T07:36:44+0000 lvl=info msg="Imported new block headers" count=1 elapsed="477.69µs" number=25,200,102 hash=0x0f1995fc70a5df2d9343029f251013b44963932993c51760228f6b5c0240084c
t=2023-01-29T07:36:48+0000 lvl=info msg="Imported new block headers" count=1 elapsed="415.049µs" number=25,200,103 hash=0x291d1050d4a6aace9c7b8b363ced4cd8169b4d6d643da3676674f4e18ea55dd5
t=2023-01-29T07:36:51+0000 lvl=info msg="Imported new block headers" count=1 elapsed="349.183µs" number=25,200,104 hash=0x408f69049887de22db95af4bc780a79150a3cc1e5a803955b88c09ea42e80bc9
t=2023-01-29T07:36:54+0000 lvl=info msg="Imported new block headers" count=1 elapsed="349.391µs" number=25,200,105 hash=0x653413618467cfa5b5f14fee112a5e1ab1d4ae0500261c4148ef929e2b8e3fa3
t=2023-01-29T07:36:55+0000 lvl=info msg="Downloader queue stats" receiptTasks=0 blockTasks=0 itemSize="225.69 KiB" throttle=1162
t=2023-01-29T07:36:58+0000 lvl=info msg="Imported new block headers" count=1 elapsed="362.206µs" number=25,200,106 hash=0x9b8561db080e330e7041494b0b4857bce433f809961dc83d9810427f0a0f501c
t=2023-01-29T07:37:01+0000 lvl=info msg="Imported new block headers" count=1 elapsed="341.286µs" number=25,200,107 hash=0x3fa59a4f980013b0251afe6b78b3b3f3490e8fe27d9ac5c87e8d55802e683da1
t=2023-01-29T07:37:04+0000 lvl=info msg="Imported new block headers" count=1 elapsed="359.133µs" number=25,200,108 hash=0x087075ab5011b5aa9bbb6b6ad026d637ee66e4ec2514a960a5c7c4ed60f11c61
t=2023-01-29T07:37:08+0000 lvl=info msg="Imported new block headers" count=1 elapsed="424.868µs" number=25,200,109 hash=0xd178abed0cb22d3bd3305620824dc7670b907600579539b2bfb215cf565814d1
t=2023-01-29T07:37:11+0000 lvl=info msg="State heal in progress" accounts=53880@2.90MiB slots=627,702@43.38MiB codes=93907@761.27MiB nodes=152,672,861@19.01GiB pending=2401
t=2023-01-29T07:37:11+0000 lvl=info msg="Imported new block headers" count=2 elapsed="595.69µs" number=25,200,111 hash=0xa933756deae3b5207525a80cb399e8b3414f0684874bb4a15e2f786eb2a9d15e
t=2023-01-29T07:37:14+0000 lvl=info msg="Imported new block headers" count=1 elapsed="457.113µs" number=25,200,112 hash=0x0e5b0d08b00b35d74588e9e5e800c543119e8b5457a5149d9b94e7157771cf85
t=2023-01-29T07:37:18+0000 lvl=info msg="Imported new block headers" count=1 elapsed="388.925µs" number=25,200,113 hash=0x26b0aad05320e2e4eb03c4f8d367527e636d1928aa2f67a1b2d6eb6c8e6f1a8f
t=2023-01-29T07:37:20+0000 lvl=info msg="State heal in progress" accounts=53880@2.90MiB slots=627,702@43.38MiB codes=93907@761.27MiB nodes=152,673,084@19.01GiB pending=5958
t=2023-01-29T07:37:21+0000 lvl=info msg="Imported new block headers" count=1 elapsed="478.489µs" number=25,200,114 hash=0x821c92a9a06e7691993d2746b4bdac58bfbef7bbb106a09d10a83a9d715ad7bf

[brilliant-lx]

1.first of all, let me do some clarification of the 2 concepts:
currentBlock: it is the head block from the local chain, e.g. its header/body are downloaded, verified and inserted.
highestBlock: the highest block number known when syncing started, it could be header downloaded, but its body is still missing.
2.currentBlock fall behind of highestBlock, can not catch up:
it could be similar to the issue: #1198
the state healing takes lots of time, it could be improved by this PR: #1226
3.but the log information shows that the block height of the browser has been caught up
May I know what is the browser here?

[jerk188]

Browser link : https://bscscan.com/

[brilliant-lx]

ok, then your log only shows the header is imported, but the block has not been imported yet.

[noizyman]

OS: Ubuntu 18.04.6 LTS (same)
Geth: v1.1.18 (same)
So this is the same problem, I guess:

support@bscnode1:~/node$ tail -f bsc.log
t=2023-01-31T13:46:14+0000 lvl=warn msg="Sanitizing invalid gasprice oracle ignore price" provided= updated=4
t=2023-01-31T13:46:14+0000 lvl=warn msg="Sanitizing invalid gasprice oracle max header history" provided=0 updated=1
t=2023-01-31T13:46:14+0000 lvl=warn msg="Sanitizing invalid gasprice oracle max block history" provided=0 updated=1
t=2023-01-31T13:46:14+0000 lvl=info msg="Starting peer-to-peer node" instance=Geth/v1.1.18-cb9e50bd/linux-amd64/go1.17.13
t=2023-01-31T13:46:14+0000 lvl=info msg="New local node record" seq=1,674,488,153,869 id=16ab5f3836a6969da57df5dddd13042f7ff35f8ad7af7b21babb63949c064754 ip=127.0.0.1 udp=30311 tcp=30311
t=2023-01-31T13:46:14+0000 lvl=info msg="Started P2P networking" self=enode://6f0c6adac1a17992c1dc0d0b03680b1cf09431400b0598b834386a5d90694a5694e5bb1b869f5dc78a038c060903fb7f3771f7aa7a94cf26e6abda0c50011058@127.0.0.1:30311
t=2023-01-31T13:46:14+0000 lvl=info msg="IPC endpoint opened" url=/home/support/node/geth.ipc
t=2023-01-31T13:46:14+0000 lvl=info msg="HTTP server started" endpoint=127.0.0.1:8545 prefix= cors= vhosts=*
t=2023-01-31T13:46:14+0000 lvl=info msg="WebSocket enabled" url=ws://[::]:8546
t=2023-01-31T13:46:24+0000 lvl=info msg="Block synchronisation started"
t=2023-01-31T13:47:24+0000 lvl=warn msg="Synchronisation failed, dropping peer" peer=aae0ed11c47b653fa4b1d6bdf1790fd22aba8c30d9daa3e280eee75b37d13372 err=timeout
t=2023-01-31T13:47:24+0000 lvl=info msg="Disabling direct-ancient mode" origin=25,263,506 ancient=20,688,919
t=2023-01-31T13:47:24+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1

---

t=2023-01-31T13:49:26+0000 lvl=warn msg="Rolled back chain segment" header=25263770->25261721 snap=25263506->25261721 block=0->0 reason="syncing canceled (requested)"
t=2023-01-31T13:49:26+0000 lvl=warn msg="Synchronisation failed, dropping peer" peer=a9df77686ca90699425b79acec2f4d7753dc87fbce9aa3c85745e8266a01cf4a err=timeout
t=2023-01-31T13:49:44+0000 lvl=info msg="Disabling direct-ancient mode" origin=25,261,721 ancient=20,688,919
t=2023-01-31T13:49:45+0000 lvl=info msg="Imported new block headers" count=192 elapsed=102.351ms number=25,261,913 hash=0x6ffdf932a01ddbc141b111b1c87b07dd7805601477e8bf1f49770f88af30ff1c age=1h36m44s
t=2023-01-31T13:49:47+0000 lvl=info msg="Imported new block headers" count=1536 elapsed=167.747ms number=25,263,449 hash=0x5aa0e005b818fc6b1f732101b63c98d3ceef3784be3007fd82bcb5febd6e274e age=17m32s
t=2023-01-31T13:49:47+0000 lvl=warn msg="Pivot seemingly stale, moving" old=25,262,887 new=25,262,951
t=2023-01-31T13:49:48+0000 lvl=info msg="Imported new block headers" count=80 elapsed=5.424ms number=25,263,529 hash=0x18c50a18d8f4bf2308f0258917b0e234969709d0a17f21ecb5be9807096e5792 age=13m9s
t=2023-01-31T13:50:15+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1
t=2023-01-31T13:50:42+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1
t=2023-01-31T13:51:04+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1
t=2023-01-31T13:51:46+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1
t=2023-01-31T13:51:46+0000 lvl=eror msg="Expired request does not exist" peer=3856d7a0620f40fa1a82acd5685a03e6d8a17acf32d5cd5e8ba23df4b6896932
t=2023-01-31T13:52:24+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1
t=2023-01-31T13:54:06+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1
t=2023-01-31T13:54:37+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1
t=2023-01-31T13:54:54+0000 lvl=info msg="State heal in progress" accounts=0@0.00B slots=0@0.00B codes=5267@42.73MiB nodes=37,137,888@7.62GiB pending=1

Maybe this is not exactly the problem, and node needs more time to sync. If you got this situation solved, please share info what did you do and/or how long did it took to sync properly?
How can I solve problem with dropping peer?

[zlacfzy]

It connects to a fast node, so it's state heal in progress and get noting. it's recommended to run a full node with full sync mode. You can refer this:
#1193
#875