[bug]: Newly generated wallet chain sync sometimes takes a very long time

[ViktorTigerstrom]

When initiating a new wallet from a new seed, lnd can sometime take a very long time to sync the wallet to chain.
We've seen this occur on both mainnet & regtest, so it's not network specific. We've also seen multiple different users be effected by this.

Normally lnd usually sets a birthday block for wallet that's a few days back, and then syncs the wallet within a minute or so. However, when the issue occurs, it can take an extensive amount of time (often 20mins+) to sync the wallet to chain.

My investigations so far seems to indicate that the reason why the wallet takes a lot of time to sync, is that requests to the chainbackend all of sudden seems to take a long time to process.

Both me & @Liongrass have experienced this when using bitcoind v27.0.0 as chainbackend, with lnd v0.18.2-beta. This can therefore potentially be an issue in bitcoind.

After a while after the issue has occured, the chainbackend requests starts being processed like normal and therefore the syncing progress also starts progressing like normal until the wallet is fully synced.

This issue is not easy to reproduce unfortunately, as it seems to only happen sporadically when creating a new wallet from a new seed. Once the issue occurs, both me and @Liongrass have experienced that the we can reproduce the issue multiple times consecutively for some time, until we all of a sudden can't reproduce it any-longer, without any change to the setup.

More technical details:

I'm adding some logs from @Liongrass who've experienced the issue in an integrated litd setting on mainnet here:
syncing_issue_litd_liongrass.log

Note that litd also makes repeated GetInfo requests while the wallet is syncing to chain, and those also times out repeatedly in his logs, due to this issue. In those logs, after waiting for 20mins, the syncing progress all of a suddenly functioned properly, and the wallet finally synced to chain.

I'm also adding some logs here from myself who when I experienced the issue in an lnd only setting on regtest:
lnd_only_syncing_issue.log

Note that it's not super clear in those logs, but after the log line:
2024-09-11 23:17:38.656 [DBG] LTND: Syncing to block timestamp: 2024-09-10 00:11:25 +0700 +07, is synced=false
The progress stalled and I hit the shutdown signal after 10 seconds. In a normal scenario, the above log line would be repeated roughly every second until the wallet has synced.

The investigation I managed to do while i could reproduce the issue, showed that the reason why the above log message doesn't get displayed every second, is that this call here blocks and doesn't get a response:

lnd/lnd.go

Line 674 in edd9ade

synced, ts, err := activeChainControl.Wallet.IsSynced()

Deeper down it was this request that never got a response:

lnd/lnwallet/btcwallet/btcwallet.go

Line 1737 in edd9ade

bestHash, bestHeight, err := b.cfg.ChainSource.GetBestBlock()

Which respecitvely in the btcwallet project frooze on this line:
https://github.com/btcsuite/btcwallet/blob/ffb143c77cc57602c812bf7498ef1d407ba41581/chain/bitcoind_client.go#L118

The reason why the syncing progress message kept being repeated over and over before freezing was that this returned false:

lnd/lnwallet/btcwallet/btcwallet.go

Line 1743 in edd9ade

if !b.wallet.ChainSynced() {

Note that the actual wallet syncing doesn't actually happen at the these code snippets, this only shows the progress for the user. I never managed to track where things stalled in the actual sycning progress.

I'm also adding some goroutine dumps from myself when the issue occured in case that's helpful. Note that these are from different startups which all faced the issue:

debug=2 dump:
debug2_dump.txt

debug=2 dump after shutdown triggered:
debug2_dump_after_shutdown.txt

debug=1 dump:
compact_dump.txt