BTC Wallet Sync Issues

[martonp]

There are multiple issues when syncing a BTC SPV wallet, especially one that was initialized with an old seed where the birthday will be Jun 2021.

1. During the initial sync (the wallet was never restarted), the CFilters will be fetched one at a time. I have seen each CFilter taking 0.5 - 1 second to arrive. This call is happening over here: https://github.com/lightninglabs/neutrino/blob/a50a92ab8271ea441ef3894fb669ca95be7fa40d/rescan.go#L960.
   This process should be done in larger batches and parallelized.
2. If the wallet is restarted, the CFilters will be fetched in batches of 1000, but this is still extremely slow. Each batch of 1000 takes between 1.5 mins - 3.5 mins to arrive. There is a TODO in btcwallet about parallelizing this process that would probably fix this: https://github.com/btcsuite/btcwallet/blob/db3a4a2543bdc7ebc1e992b2f7fd01e4abd257a3/wallet/wallet.go#L834
3. When the wallet is restarted, it cannot be shut down until the sync has completed. This issue does not happen if this is the initial sync in which the wallet was never restarted. The reason for this is that the long running process in which Cfilters are requested 1000 at a time is unmanaged. A context needs to be passed into recoverScopedAddresses (see link in wallet.go above) that kills this.

[buck54321]

btcsuite/btcwallet#944 fixes 3

[matthawkins90]

Wow, nice job finding these issues, as well as @buck54321 already fixing 3.

[JoeGruffins]

Adding to this, a couple more problems recently:

1. btc sync status suddenly becoming not 100%. I saw it once and has been reported on matrix by one person I know of. After this sync never seems to recover.
2. during initial sync we can't find a block. The block appears to be random. It happens very often for me. Sync may recover or it may not restarting the client.

[JoeGruffins]

I will look into the cannot find a block thing.

[dreacot]

BTC: Unable to synchronize wallet to chain, trying again in 5s: unable to perform wallet recovery: failed to store sync information

i'm unable to rescan once i get this error

[norwnd]

With Bitcoin SPV I've ran into an issue of sync being stuck at 0.0% even though I have all 8 peers right after Bison wallet start (I also can't place trades involving BTC as it says btc still syncing. progress = 0.00%):

One hour later nothing changed, restart resolved it for me, attaching also relevant logs from erroneous run (note, there is no mention of Wallet synced for asset btc):

2024-12-24 08:24:37.323 [DBG] CORE[btc][SPV]: Starting neutrino chain service...
2024-12-24 08:24:37.372 [INF] CORE[btc][SPV]: Synchronizing wallet with network...
2024-12-24 08:24:37.691 [TRC] CORE[btc]: Retrieved fee rate from external API: 5
2024-12-24 08:24:37.693 [TRC] CORE[btc]: capping fee rate 5 retrieved from external API at user-configured limit of 1
2024-12-24 08:24:37.694 [INF] CORE[btc]: Connected wallet with current best block 000000000000000000013de92977d2b33330705c648262da0734e5c0a8c40e98 (876093)
2024-12-24 08:24:37.695 [DBG] CORE[btc]: Using tx history db at /Users/norwnd/Library/Application Support/Dexc/mainnet/assetdb/btc/mainnet/txhistorydb-47cc7da9f57d813f7dcf8dca767144f3576a01d7
2024-12-24 08:24:37.713 [TRC] CORE[btc]: All 1 tables opened in 0s

2024-12-24 08:24:37.718 [TRC] CORE[btc]: Replaying file id: 0 at offset: 370077

2024-12-24 08:24:37.720 [TRC] CORE[btc]: Replay took: 1.5085ms

2024-12-24 08:24:37.722 [TRC] CORE[btc]: Value log discard stats empty
2024-12-24 08:24:37.725 [TRC] CORE: New peer count for asset btc: 2
2024-12-24 08:24:37.725 [TRC] CORE[btc]: tip change: 876093 (000000000000000000013de92977d2b33330705c648262da0734e5c0a8c40e98) => 876093 (000000000000000000013de92977d2b33330705c648262da0734e5c0a8c40e98)
2024-12-24 08:24:37.725 [TRC] CORE: Processing tip change for btc
2024-12-24 08:24:37.725 [TRC] CORE[btc]: Retrieved fee rate from external API: 5
2024-12-24 08:24:37.725 [TRC] CORE[btc]: capping fee rate 5 retrieved from external API at user-configured limit of 1
2024-12-24 08:24:37.726 [TRC] CORE[btc][SPV]: Bals: spendable = 0.******** BTC (0.******** BTC trusted, 0 BTC untrusted, 0 BTC assumed locked), immature = 0 BTC
2024-12-24 08:24:37.726 [TRC] CORE[btc][SPV]: Bals: spendable = 0.******** BTC (0.******** BTC trusted, 0 BTC untrusted, 0 BTC assumed locked), immature = 0 BTC
...
2024-12-24 08:25:57.725 [TRC] CORE: New peer count for asset btc: 8
2024-12-24 08:26:09.221 [ERR] WEB: error placing order: btc still syncing. progress = 0.00%
...
2024-12-24 08:26:42.724 [TRC] CORE: New peer count for asset btc: 7
2024-12-24 08:26:47.725 [TRC] CORE: New peer count for asset btc: 8
...
2024-12-24 08:28:07.725 [TRC] CORE: New peer count for asset btc: 7
...
2024-12-24 08:30:37.723 [TRC] CORE: New peer count for asset btc: 8
...
2024-12-24 09:22:22.480 [TRC] CORE: New peer count for asset btc: 8

the only suspicious thing I can see ^ is CORE[btc]: tip change: 876093 (000000000000000000013de92977d2b33330705c648262da0734e5c0a8c40e98) => 876093 (000000000000000000013de92977d2b33330705c648262da0734e5c0a8c40e98) which raises 2 questions:

• is tip change from X to same X expected thing / fine ?
• there is no tip changes for BTC wallet after that (even though we keep seeing logs of the form New peer count for asset btc), that doesn't seem right - block 000000000000000000013de92977d2b33330705c648262da0734e5c0a8c40e98 is ~10h old

looks very much like a deadlock (or something) prevents us from receiving those new tip updates (I run without pprof though, can't provide go-routine dump)