decred
spv: Sync stops at 99.9%
On 15a67d7e7391b6924cd573192599f440f375d3ff
When syncing a new wallet it never finishes until a restart. Rescan never starts. If it is shut down once during sync it does not happen.
On testnet:
2024-10-22 21:57:14.917 [INF] SYNC: Connected 2000 blocks, new tip e2f7781bab37fe695ef7fb53d549cd993fa57140b9649e2dfdefa61dffd0bfca, height 1478000, date 2024-09-16 23:05:56 +0900 JST
2024-10-22 21:57:25.037 [INF] SYNC: Connected 2000 blocks, new tip 9646286534b9bc142934ceec4e648d3e177bb85fd5397b341f25e0ba6510ca62, height 1480000, date 2024-09-19 17:51:32 +0900 JST
2024-10-22 21:57:29.185 [INF] SYNC: Connected 2000 blocks, new tip cff22134e55c47a47f02a768da5f2fd6d48e70e02a01697b8528ed08684b37a1, height 1482000, date 2024-09-22 12:29:19 +0900 JST
2024-10-22 21:57:31.828 [INF] SYNC: Connected 2000 blocks, new tip 779a581c34f0609cd8a532d34c15471833598b2bfe6f4d9bffe3424a10f3eca7, height 1484000, date 2024-09-25 07:58:48 +0900 JST
2024-10-22 21:57:42.221 [INF] SYNC: Connected 2000 blocks, new tip bbdae6a5b41122d29fa69e98ec9564df11df74595c37d97aced6e24104e0e4d8, height 1486000, date 2024-09-29 05:14:03 +0900 JST
2024-10-22 21:57:44.829 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 21:57:44.900 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 21:57:45.091 [WRN] SYNC: spv.handleMixInvs([2001:41d0:801:2000::8b2]:19108): expiry is too far into future
2024-10-22 21:57:47.178 [INF] SYNC: Connected 2000 blocks, new tip ec4ff2afbdf06f8055e5091681cbd4487a8cd35bd3de80f471c323ebc1cb6b74, height 1488000, date 2024-10-02 20:07:49 +0900 JST
2024-10-22 21:57:50.724 [INF] SYNC: Connected 2000 blocks, new tip ee209e9dd8bbf59c499116e68240055f41c1bf095222ef00496218383342498d, height 1490000, date 2024-10-05 02:26:21 +0900 JST
2024-10-22 21:57:56.034 [INF] SYNC: Connected 2000 blocks, new tip f4ee2c8826a82c08799fc93a1cac016c4fee016063df966a6021ace24e14ce08, height 1492000, date 2024-10-07 10:16:59 +0900 JST
2024-10-22 21:57:58.961 [INF] SYNC: Connected 2000 blocks, new tip 259ffd470f83fc17f1a6b714476e1bbe731990118f24350d1c5282538baa80ff, height 1494000, date 2024-10-09 04:03:26 +0900 JST
2024-10-22 21:58:04.953 [INF] SYNC: Connected 2000 blocks, new tip af5a3844edf6b17eb67afc4e388501f150d817c219905174b75cd7d84cfd3d25, height 1496000, date 2024-10-11 22:48:34 +0900 JST
2024-10-22 21:58:06.425 [WRN] SYNC: spv.handleMixInvs(35.206.206.203:19108): expiry is too far into future
2024-10-22 21:58:06.588 [WRN] SYNC: spv.handleMixInvs([2001:41d0:801:2000::8b2]:19108): expiry is too far into future
2024-10-22 21:58:06.685 [WRN] SYNC: spv.handleMixInvs(140.82.59.244:19108): expiry is too far into future
2024-10-22 21:58:08.146 [INF] SYNC: Connected 2000 blocks, new tip d4c3794ce208c34229528af1e99f96fdca80e106dc0f4c50f97e2b3aa7d31b49, height 1498000, date 2024-10-14 17:26:22 +0900 JST
2024-10-22 21:58:15.188 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 21:58:15.231 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 21:58:15.915 [INF] SYNC: Connected 2000 blocks, new tip 759308be7fe20220c6e66543c1c139c420d4ecb6e8afb958c68c22efc71f1e6b, height 1500000, date 2024-10-17 12:04:03 +0900 JST
2024-10-22 21:58:19.422 [INF] SYNC: Connected 2000 blocks, new tip 7682fb877d686006bef0ddb37c15d66e975b66b353e4925f4ca0c6be2025eb70, height 1502000, date 2024-10-20 06:48:34 +0900 JST
2024-10-22 21:58:40.380 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 21:58:40.480 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 21:58:41.544 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 21:58:41.613 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 21:58:43.919 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 21:58:44.088 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 21:58:45.781 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 21:58:45.781 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 21:58:45.940 [WRN] SYNC: spv.handleMixInvs(51.68.214.224:19108): expiry is too far into future
2024-10-22 21:58:47.093 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
.......
2024-10-22 22:05:25.766 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 22:05:25.766 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 22:05:25.894 [WRN] SYNC: spv.handleMixInvs(140.82.59.244:19108): expiry is too far into future
2024-10-22 22:05:26.365 [WRN] SYNC: spv.handleMixInvs(51.68.214.224:19108): expiry is too far into future
2024-10-22 22:05:27.103 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 22:05:27.191 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 22:05:27.276 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 22:05:27.945 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 22:05:28.118 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 22:05:29.091 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 22:05:29.191 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 22:05:32.306 [WRN] SYNC: spv.handleMixInvs(99.121.115.244:19108): expiry is too far into future
2024-10-22 22:05:32.420 [WRN] SYNC: spv.handleMixInvs(96.92.233.221:19108): expiry is too far into future
2024-10-22 22:05:32.504 [WRN] SYNC: spv.handleMixInvs(140.82.59.244:19108): expiry is too far into future
2024-10-22 22:05:32.580 [WRN] SYNC: spv.handleMixInvs([2001:41d0:801:2000::8b2]:19108): expiry is too far into future
$dcrctl syncstatus
{
"synced": false,
"initialblockdownload": true,
"headersfetchprogress": 0.9987466
}
With logs on trace, get headers stops withough any warn or error logs:
2024-10-23 15:54:56.341 [DBG] PEER: getheaders -> 66.42.112.165:19108
2024-10-23 15:54:56.533 [DBG] PEER: headers <- 66.42.112.165:19108
2024-10-23 15:54:56.533 [TRC] SYNC: Skipping to next batch due to len(headers) == 0 from 66.42.112.165:19108
2024-10-23 15:54:56.533 [TRC] SYNC: Attempting next batch of headers from 96.92.233.221:19108
2024-10-23 15:54:56.533 [DBG] PEER: getheaders -> 96.92.233.221:19108
2024-10-23 15:54:56.732 [DBG] PEER: headers <- 96.92.233.221:19108
2024-10-23 15:54:56.732 [TRC] SYNC: Skipping to next batch due to len(headers) == 0 from 96.92.233.221:19108
2024-10-23 15:54:56.732 [TRC] SYNC: Attempting next batch of headers from 66.42.112.165:19108
2024-10-23 15:54:56.732 [DBG] PEER: getheaders -> 66.42.112.165:19108
2024-10-23 15:54:56.780 [DBG] PEER: inv <- [2001:41d0:801:2000::8b2]:19108
2024-10-23 15:54:56.780 [DBG] SYNC: Ignoring block invs from [2001:41d0:801:2000::8b2]:19108 before sendheaders is sent
2024-10-23 15:54:56.780 [DBG] PEER: inv <- 51.68.214.224:19108
2024-10-23 15:54:56.780 [DBG] SYNC: Ignoring block invs from 51.68.214.224:19108 before sendheaders is sent
2024-10-23 15:54:56.823 [DBG] PEER: inv <- [2001:19f0:5001:100:5400:3ff:fe88:6545]:19108
2024-10-23 15:54:56.823 [DBG] SYNC: Ignoring block invs from [2001:19f0:5001:100:5400:3ff:fe88:6545]:19108 before sendheaders is sent
2024-10-23 15:54:56.977 [DBG] PEER: inv <- [2001:19f0:5:33c5:5400:2ff:fee0:b1c3]:19108
2024-10-23 15:54:56.977 [DBG] SYNC: Ignoring block invs from [2001:19f0:5:33c5:5400:2ff:fee0:b1c3]:19108 before sendheaders is sent
2024-10-23 15:54:56.991 [DBG] PEER: inv <- 195.49.75.206:19108
2024-10-23 15:54:56.991 [DBG] SYNC: Ignoring block invs from 195.49.75.206:19108 before sendheaders is sent
2024-10-23 15:54:57.084 [DBG] PEER: inv <- [2001:19f0:5001:100:5400:3ff:fe88:6545]:19108
2024-10-23 15:54:57.108 [DBG] PEER: headers <- 66.42.112.165:19108
2024-10-23 15:54:57.108 [DBG] PEER: inv <- 66.42.112.165:19108
2024-10-23 15:54:57.108 [DBG] SYNC: Ignoring block invs from 66.42.112.165:19108 before sendheaders is sent
2024-10-23 15:54:57.121 [DBG] SYNC: Fetched 1 new header(s) ending at height 1504435 from 66.42.112.165:19108
2024-10-23 15:54:57.129 [DBG] PEER: inv <- 96.92.233.221:19108
2024-10-23 15:54:57.129 [DBG] SYNC: Ignoring block invs from 96.92.233.221:19108 before sendheaders is sent
2024-10-23 15:54:57.135 [DBG] PEER: inv <- [2001:19f0:5c01:1e39:5400:3ff:fe9a:80ff]:19108
2024-10-23 15:54:57.135 [DBG] SYNC: Ignoring block invs from [2001:19f0:5c01:1e39:5400:3ff:fe9a:80ff]:19108 before sendheaders is sent
Then there is lot of ignoring block inv
2024-10-23 15:54:59.840 [DBG] SYNC: Ignoring block invs from 96.92.233.221:19108 before sendheaders is sent
2024-10-23 15:54:59.852 [DBG] PEER: inv <- [2001:19f0:5:33c5:5400:2ff:fee0:b1c3]:19108
2024-10-23 15:54:59.852 [DBG] SYNC: Ignoring block invs from [2001:19f0:5:33c5:5400:2ff:fee0:b1c3]:19108 before sendheaders is sent
2024-10-23 15:54:59.852 [DBG] PEER: inv <- 66.42.112.165:19108
2024-10-23 15:54:59.852 [DBG] SYNC: Ignoring block invs from 66.42.112.165:19108 before sendheaders is sent
2024-10-23 15:54:59.975 [DBG] PEER: inv <- [2001:41d0:801:2000::8b2]:19108
2024-10-23 15:54:59.975 [DBG] SYNC: Ignoring block invs from [2001:41d0:801:2000::8b2]:19108 before sendheaders is sent
Mixed with lots of mixing logs.
I just ran a fresh sync and it completed without incident.
Are you seeing this behavior consistently?
I've done some investigating. In spv/backend.go getHeaders, when it happens, locatorHeight was stuck at height 1506485 while tipHeight was stuck at 1506000. rp.LastHeight() will be at various values at or below the tipHeight.
I've done some investigating. In
spv/backend.gogetHeaders, when it happens,locatorHeightwas stuck at height 1506485 whiletipHeightwas stuck at 1506000.rp.LastHeight()will be at various values at or below thetipHeight.
I have tested this today by naively starting 3 runs of creating and starting a new dcrwallet dcrwallet --testnet --nogrpc --spv
- run1 - synced to tip
- run2 - synced to 1508000 and seemed to be spinning with no peers sending acceptable INV Mix messages. syncs to tip after restart
- run3 - synced to tip
dcrwallet_run2.txt dcrwallet_run2_restarted.txt Sorry no trace .. was just naive random testing
Haven't tested this specifically yet, but I recall testnet having an issue some time ago due to difficulty to find appropriate peers (there were very few updated testnet peers presented by the peer relayer and they were sometimes unreachable/untried).
There may be some issue with peer selection on testnet specifically due to this low number of peers.
Have you observed this issue on mainnet?
We have had this issue when starting a new DCR SPV wallet (sometimes) from bisonw on mainnet. Did not notice it recently but wasn't really looking.
I will repeat a couple of tests with newly created mainnet dcrwallet wallets using CLI to see if it happens now with (I imagine) is most peers on latest update.
Have finished 3 runs to sync a newly created dcrwallet on mainnet .. all three synced to tip!
Seeing MIXP: Accepted message... almost all the time in logs ;-)
I also see on mainnet. For some reason I am able to hit it almost every time. My internet is awful which I'm sure plays a factor. I am unable to hit it if I use a local peer.
I think it's stalling in cfiltersV2FromNodes now. Maybe the headers would be fine if the tip updated.
If it took over six blocks for initial sync to get to the end of the chain, and peers have not changed, I guess it would hang here waitForRemote
Since headers always come before cfilters, can we just use the last header height instead of initial?