search

lightningnetwork / lnd

Lightning Network Daemon ⚡️
MIT License
7.67k stars 2.07k forks source link

[bug]: LNWL: Unable to synchronize wallet to chain, trying again in 5s: -8: Block height out of range #8468

Closed rockstardev closed 8 months ago

rockstardev commented 8 months ago

Background

Following the upgrade to LND 0.17.4-beta, I've encountered an issue where I can't initiate tests in regtest mode, as LND fails to complete its startup process. This problem is specific to this version; I did not experience this with the earlier LND 0.17.4-beta-rc1. It suggests that certain changes introduced in the final release are causing a regression.

Your environment

restlisten=merchant_lnd:8080 rpclisten=127.0.0.1:10008 rpclisten=merchant_lnd:10009 bitcoin.node=bitcoind bitcoind.rpchost=bitcoind:43782 bitcoind.rpcuser=ceiwHEbqWI83 bitcoind.rpcpass=DwubwWsoo3 bitcoind.zmqpubrawblock=tcp://bitcoind:28332 bitcoind.zmqpubrawtx=tcp://bitcoind:28333 externalip=merchant_lnd:9735 bitcoin.defaultchanconfs=1 no-macaroons=1 debuglevel=debug trickledelay=1000 no-rest-tls=1

Steps to reproduce

Just start LND 0.17.4 container in regtest, mine 101 blocks and unlock wallet.

image

Logs:

2024-02-07 21:28:12.584 [INF] LNWL: Opened wallet
2024-02-07 21:28:12.584 [INF] CHRE: Primary chain is set to: bitcoin
{}2024-02-07 21:28:12.604 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on 172.24.0.4:28332
2024-02-07 21:28:12.604 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on 172.24.0.4:283332024-02-07 21:28:13.138 [INF] LNWL: The wallet has been unlocked without a time limit
2024-02-07 21:28:13.144 [INF] CHRE: LightningWallet opened
2024-02-07 21:28:13.144 [DBG] LNWL: Birthday block has already been verified: height=101, hash=3fd65ed144030c53b0df295a3298918e8f418b608a3202742410b68d9dacc05d
2024-02-07 21:28:13.150 [ERR] LNWL: Unable to synchronize wallet to chain, trying again in 5s: -8: Block height out of range
2024-02-07 21:28:13.155 [INF] HSWC: Cleaning circuits from disk for closed channels
2024-02-07 21:28:13.155 [DBG] HSWC: Found 0 closed channels
2024-02-07 21:28:13.155 [INF] HSWC: Finished cleaning: no closed channels found, no actions taken.
2024-02-07 21:28:13.155 [INF] HSWC: Restoring in-memory circuit state from disk
2024-02-07 21:28:13.158 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2024-02-07 21:28:13.164 [DBG] CRTR: Instantiating mission control with config: maximum history: 1000, minimum failure relax interval: 1m0s, estimator type: apriori, penalty halflife time: 1h0m0s, apriori hop probability: 0.6, apriori weight: 0.5, previous success probability: 0.95, capacity fraction: 0.9999
2024-02-07 21:28:13.167 [DBG] CRTR: Mission control state reconstruction started
2024-02-07 21:28:13.167 [DBG] CRTR: Mission control state reconstruction finished: n=0, time=4.916µs
2024-02-07 21:28:13.167 [DBG] SRVR: Instantiating payment session source with config: AttemptCost=100 + 0.1%, MinRouteProbability=0.01
2024-02-07 21:28:13.169 [DBG] SRVR: Sweeper batch window duration: 30s
2024-02-07 21:28:13.172 [INF] LTND: Channel backup proxy channel notifier starting
2024-02-07 21:28:13.172 [INF] ATPL: Instantiating autopilot with active=false, max_channels=5, allocation=0.600000, min_chan_size=20000, max_chan_size=16777215, private=false, min_confs=1, conf_target=3
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: SignRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: WalletKitRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: AutopilotRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: ChainRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: InvoicesRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: PeersRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: NeutrinoKitRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: RouterRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: WatchtowerRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: WatchtowerClientRPC
2024-02-07 21:28:13.172 [DBG] LTND: Populating dependencies for sub RPC server: DevRPC
2024-02-07 21:28:13.172 [DBG] RPCS: Starting sub RPC server: WalletKitRPC
2024-02-07 21:28:13.172 [DBG] RPCS: Starting sub RPC server: RouterRPC
2024-02-07 21:28:13.172 [DBG] RPCS: Starting sub RPC server: ChainRPC
2024-02-07 21:28:13.172 [DBG] RPCS: Starting sub RPC server: InvoicesRPC
2024-02-07 21:28:13.172 [DBG] RPCS: Starting sub RPC server: VersionRPC
2024-02-07 21:28:13.172 [DBG] RPCS: Starting sub RPC server: WatchtowerRPC
2024-02-07 21:28:13.172 [DBG] RPCS: Starting sub RPC server: WatchtowerClientRPC
2024-02-07 21:28:13.172 [DBG] RPCS: Starting sub RPC server: SignRPC
2024-02-07 21:28:13.172 [INF] LTND: We're not running within systemd or the service type is not 'notify'
2024-02-07 21:28:13.173 [INF] LTND: Waiting for chain backend to finish sync, start_height=294
2024-02-07 21:28:13.174 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:14.179 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:15.185 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:16.187 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:17.190 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:18.152 [ERR] LNWL: Unable to synchronize wallet to chain, trying again in 5s: -8: Block height out of range
2024-02-07 21:28:18.194 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:19.197 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:20.201 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:21.205 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:22.211 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:23.155 [ERR] LNWL: Unable to synchronize wallet to chain, trying again in 5s: -8: Block height out of range
2024-02-07 21:28:23.214 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:24.218 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:25.222 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:26.226 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:27.230 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:28.157 [ERR] LNWL: Unable to synchronize wallet to chain, trying again in 5s: -8: Block height out of range
2024-02-07 21:28:28.233 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:29.236 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:30.238 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:31.240 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:32.243 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:33.159 [ERR] LNWL: Unable to synchronize wallet to chain, trying again in 5s: -8: Block height out of range
2024-02-07 21:28:33.246 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:34.251 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:35.253 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:36.256 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false
2024-02-07 21:28:37.258 [DBG] LTND: Syncing to block timestamp: 2024-02-01 21:53:17 +0000 UTC, is synced=false

Expected behaviour

Initial syncing should finish and LND should start (this is what happens for me with LND 0.17.4-rc1)

image

Logs:

2024-02-07 21:44:35.420 [INF] LNWL: Opened wallet
2024-02-07 21:44:35.420 [INF] CHRE: Primary chain is set to: bitcoin
{"admin_macaroon":""}2024-02-07 21:44:35.442 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on 172.26.0.5:28332
2024-02-07 21:44:35.442 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on 172.26.0.5:28333
2024-02-07 21:44:36.023 [INF] LNWL: The wallet has been unlocked without a time limit
2024-02-07 21:44:36.069 [INF] CHRE: LightningWallet opened
2024-02-07 21:44:36.071 [DBG] LNWL: Locating suitable block for birthday 2024-02-05 18:15:05 +0000 UTC between blocks 0-101
2024-02-07 21:44:36.074 [DBG] LNWL: Checking candidate block: height=50, hash=0612d62d86fb8701c69a29c7457ef209263547261004fadbb9224c2a760038f8, timestamp=2024-02-07 21:44:44 +0000 UTC
2024-02-07 21:44:36.078 [DBG] LNWL: Checking candidate block: height=25, hash=74278e646e2d0033c6abe595ebb7a793c4656b4a2a61d5bea7ff9c44baebe274, timestamp=2024-02-07 21:44:39 +0000 UTC
2024-02-07 21:44:36.080 [DBG] LNWL: Checking candidate block: height=12, hash=69b31d2abd58d5271efc6a1f7a6330f769255e4e4c4ce03f2657d0b4b57a0af8, timestamp=2024-02-07 21:44:37 +0000 UTC
2024-02-07 21:44:36.083 [DBG] LNWL: Checking candidate block: height=6, hash=30df2750dd412ef7e72da0f066da068e22ac66902e9bef0279f93f4d10568418, timestamp=2024-02-07 21:44:36 +0000 UTC
2024-02-07 21:44:36.085 [DBG] LNWL: Checking candidate block: height=3, hash=06523ba32b84c50ea04e4749552b079ff1fe07c44b4977763d191a24ca2447f5, timestamp=2024-02-07 21:44:35 +0000 UTC
2024-02-07 21:44:36.086 [INF] HSWC: Cleaning circuits from disk for closed channels
2024-02-07 21:44:36.086 [DBG] HSWC: Found 0 closed channels
2024-02-07 21:44:36.086 [INF] HSWC: Finished cleaning: no closed channels found, no actions taken.
2024-02-07 21:44:36.086 [INF] HSWC: Restoring in-memory circuit state from disk
2024-02-07 21:44:36.088 [DBG] LNWL: Checking candidate block: height=1, hash=42e7bfc33907014e0e3a014fab8616fd6e486d4e8ba79a697f7c230a7cf3d24b, timestamp=2024-02-07 21:44:34 +0000 UTC
2024-02-07 21:44:36.089 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2024-02-07 21:44:36.090 [DBG] LNWL: Checking candidate block: height=0, hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, timestamp=2011-02-02 23:16:42 +0000 UTC
2024-02-07 21:44:36.090 [DBG] LNWL: Found birthday block: height=0, hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, timestamp=2011-02-02 23:16:42 +0000 UTC
2024-02-07 21:44:36.121 [INF] LNWL: Started rescan from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (height 0) for 0 addresses
2024-02-07 21:44:36.122 [DBG] CRTR: Instantiating mission control with config: maximum history: 1000, minimum failure relax interval: 1m0s, estimator type: apriori, penalty halflife time: 1h0m0s, apriori hop probability: 0.6, apriori weight: 0.5, previous success probability: 0.95, capacity fraction: 0.9999
2024-02-07 21:44:36.128 [DBG] CRTR: Mission control state reconstruction started
2024-02-07 21:44:36.128 [DBG] CRTR: Mission control state reconstruction finished: n=0, time=9.271µs
2024-02-07 21:44:36.128 [DBG] SRVR: Instantiating payment session source with config: AttemptCost=100 + 0.1%, MinRouteProbability=0.01
2024-02-07 21:44:36.128 [INF] LNWL: Catching up block hashes to height 1, this might take a while
2024-02-07 21:44:36.136 [DBG] SRVR: Sweeper batch window duration: 30s
2024-02-07 21:44:36.136 [INF] SWPR: Migrating UTXO nursery finalized TXIDs
2024-02-07 21:44:36.144 [INF] LNWL: Done catching up block hashes
2024-02-07 21:44:36.144 [INF] LNWL: Rescanned through block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (height 1)
2024-02-07 21:44:36.148 [INF] LTND: Channel backup proxy channel notifier starting
2024-02-07 21:44:36.148 [INF] ATPL: Instantiating autopilot with active=false, max_channels=5, allocation=0.600000, min_chan_size=20000, max_chan_size=16777215, private=false, min_confs=1, conf_target=3
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: SignRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: WalletKitRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: AutopilotRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: ChainRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: InvoicesRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: PeersRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: NeutrinoKitRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: RouterRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: WatchtowerRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: WatchtowerClientRPC
2024-02-07 21:44:36.148 [DBG] LTND: Populating dependencies for sub RPC server: DevRPC
2024-02-07 21:44:36.148 [DBG] RPCS: Starting sub RPC server: InvoicesRPC
2024-02-07 21:44:36.148 [DBG] RPCS: Starting sub RPC server: VersionRPC
2024-02-07 21:44:36.148 [DBG] RPCS: Starting sub RPC server: WatchtowerRPC
2024-02-07 21:44:36.148 [DBG] RPCS: Starting sub RPC server: WatchtowerClientRPC
2024-02-07 21:44:36.148 [DBG] RPCS: Starting sub RPC server: SignRPC
2024-02-07 21:44:36.148 [DBG] RPCS: Starting sub RPC server: WalletKitRPC
2024-02-07 21:44:36.148 [DBG] RPCS: Starting sub RPC server: RouterRPC
2024-02-07 21:44:36.148 [DBG] RPCS: Starting sub RPC server: ChainRPC
2024-02-07 21:44:36.148 [INF] LTND: We're not running within systemd or the service type is not 'notify'
2024-02-07 21:44:36.149 [INF] LTND: Waiting for chain backend to finish sync, start_height=101
2024-02-07 21:44:36.154 [DBG] LTND: Syncing to block timestamp: 2024-02-07 21:44:52 +0000 UTC, is synced=false
2024-02-07 21:44:37.080 [INF] LNWL: Catching up block hashes to height 101, this might take a while
2024-02-07 21:44:37.086 [INF] LNWL: Done catching up block hashes
2024-02-07 21:44:37.086 [INF] LNWL: Finished rescan for 0 addresses (synced to block 0ef2255dc8195984a9bfd8c45b902fefd5af8eec8a6b725d8a44b6bdfbfc8882, height 101)
2024-02-07 21:44:37.158 [DBG] LTND: Syncing to block timestamp: 2024-02-07 21:44:52 +0000 UTC, is synced=true
2024-02-07 21:44:37.159 [INF] LTND: Chain backend is fully synced (end_height=101)!
2024-02-07 21:44:37.159 [WRN] HLCK: check: disk space configured with 0 attempts, skipping it
2024-02-07 21:44:37.159 [WRN] HLCK: check: tls configured with 0 attempts, skipping it
2024-02-07 21:44:37.159 [INF] LNWL: SigPool starting
2024-02-07 21:44:37.159 [DBG] HLCK: Monitoring: chain backend
2024-02-07 21:44:37.164 [INF] CHNF: ChannelNotifier starting
2024-02-07 21:44:37.164 [INF] PRNF: PeerNotifier starting
2024-02-07 21:44:37.164 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.164 [INF] BTCN: Broadcaster now active
2024-02-07 21:44:37.164 [INF] HSWC: HtlcNotifier starting
2024-02-07 21:44:37.164 [INF] SWPR: Sweeper starting
2024-02-07 21:44:37.164 [INF] UTXN: UTXO nursery starting
2024-02-07 21:44:37.164 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.165 [INF] BRAR: Breach arbiter starting
2024-02-07 21:44:37.165 [DBG] BRAR: Found 0 closing channels, 0 retribution records
2024-02-07 21:44:37.165 [INF] FNDG: Funding manager starting
2024-02-07 21:44:37.165 [INF] HSWC: HTLC Switch starting
2024-02-07 21:44:37.165 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.165 [INF] BRAR: Starting contract observer, watching for breaches.
2024-02-07 21:44:37.166 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.166 [INF] CNCT: ChainArbitrator starting
2024-02-07 21:44:37.166 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.166 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.166 [INF] DISC: Authenticated Gossiper starting
2024-02-07 21:44:37.166 [DBG] HSWC: InterceptableSwitch running: height=101, requireInterceptor=false
2024-02-07 21:44:37.166 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.168 [INF] CRTR: Channel Router starting
2024-02-07 21:44:37.168 [DBG] DISC: New block: height=101, hash=0ef2255dc8195984a9bfd8c45b902fefd5af8eec8a6b725d8a44b6bdfbfc8882
2024-02-07 21:44:37.179 [DBG] CHDB: Pruned graph, cache now has num_node_features=0, num_nodes=0, num_channels=0
2024-02-07 21:44:37.179 [INF] CRTR: FilteredChainView starting
2024-02-07 21:44:37.184 [INF] CRTR: Filtering chain using 0 channels active
2024-02-07 21:44:37.186 [INF] CRTR: Prune tip for Channel Graph: height=101, hash=0ef2255dc8195984a9bfd8c45b902fefd5af8eec8a6b725d8a44b6bdfbfc8882
2024-02-07 21:44:37.188 [DBG] CRTR: Cleaning network result store.
2024-02-07 21:44:37.199 [INF] INVC: InvoiceRegistry starting
2024-02-07 21:44:37.199 [DBG] INVC: Adding 0 pending invoices to the expiry watcher
2024-02-07 21:44:37.199 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.199 [INF] HSWC: Onion processor starting
2024-02-07 21:44:37.216 [INF] NANN: Channel Status Manager starting
2024-02-07 21:44:37.216 [INF] CHFT: ChannelEventStore starting
2024-02-07 21:44:37.216 [INF] NTFN: New block epoch subscription
2024-02-07 21:44:37.216 [INF] CHFT: Adding 0 channels to event store
2024-02-07 21:44:37.216 [INF] CHBU: chanbackup.SubSwapper starting
2024-02-07 21:44:37.221 [INF] CHBU: Updating backup file at /root/.lnd/data/chain/bitcoin/regtest/channel.backup
2024-02-07 21:44:37.226 [INF] CHBU: Swapping old multi backup file from /root/.lnd/data/chain/bitcoin/regtest/temp-dont-use.backup to /root/.lnd/data/chain/bitcoin/regtest/channel.backup
2024-02-07 21:44:37.226 [DBG] CRTR: New graph topology client subscription, client 1
2024-02-07 21:44:37.226 [DBG] CHBU: SubSwapper's backupUpdater is active!
2024-02-07 21:44:37.226 [DBG] SRVR: Establishing 0 persistent connections on start
2024-02-07 21:44:37.226 [INF] SRVR: Auto peer bootstrapping is disabled
2024-02-07 21:44:37.226 [INF] CMGR: Server listening on [::]:9735
djkazic commented 8 months ago

Saw this, I just tried to repro this on my local regtest but could not, using 0.17.4-beta

ellemouton commented 8 months ago

@rockstardev - did you first encounter this on mainnet & then reproduce on regtest or did you only try on regtest? if the later, then is it possible that you had an old lnd data folder lying around but with a fresh regtest set-up with a new bitcoin node?

guggero commented 8 months ago

I usually get this error locally if I started lnd on one version of a regtest chain, then delete the chain but keep the old lnd wallet. Meaning you probably had some left-over state in your lnd wallet from a previous run?

djkazic commented 8 months ago

Was able to help him resolve the issue by tearing down the docker network and bitcoind

saubyk commented 8 months ago

Closing this issue based on the comments above. feel free to re-open if there is anything else which has been unaddressed. thanks.