Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[bug]: channel stuck in waiting_close_channels #8560

Closed
wereHamster opened this issue Mar 17, 2024 · 5 comments
Closed

[bug]: channel stuck in waiting_close_channels #8560

wereHamster opened this issue Mar 17, 2024 · 5 comments
Labels
bug Unintended code behaviour needs triage

Comments

@wereHamster
Copy link
Contributor

Background

I have a LND node on testnet which has one channel in waiting_close_channels. Though when I look at the on-chain transactions, the channel has been (force) closed by the other node.

I suspect this was the sequence of actions:

  1. Remote node initiates close ("initiator": "INITIATOR_REMOTE").
  2. My node does not process this in time (maybe it was offline), remote node becomes impatient and initiates a force close.
  3. The force close transaction has been accepted by the chain a long time ago, but my node is not becoming aware of it.

I tried restarting LND with a full rescan, but that did not help.

AFAICS there was no local balance on my side, the close transaction yielded coins only to the remote node.

It's also interesting that the committment local_txid (see below) can not be found in the mempool.

        {
            "channel": {
                "remote_node_pub": "038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9",
                "channel_point": "5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0",
                "capacity": "16776923",
                "local_balance": "0",
                "remote_balance": "16776740",
                "local_chan_reserve_sat": "167769",
                "remote_chan_reserve_sat": "167769",
                "initiator": "INITIATOR_REMOTE",
                "commitment_type": "STATIC_REMOTE_KEY",
                "num_forwarding_packages": "0",
                "chan_status_flags": "ChanStatusCoopBroadcasted|ChanStatusLocalCloseInitiator",
                "private": false,
                "memo": ""
            },
            "limbo_balance": "0",
            "commitments": {
                "local_txid": "42a6fba91adf0e78cd6305f3c2854cbfde3bd5e9a1ad26f3428da53b71ee121a",
                "remote_txid": "9d82dcc2eec62a43cb0e4fe6a02a4c3dccc30ee9acd4fc9591ccbaa327fb45b3",
                "remote_pending_txid": "",
                "local_commit_fee_sat": "183",
                "remote_commit_fee_sat": "183",
                "remote_pending_commit_fee_sat": "0"
            },
            "closing_txid": ""
        }

Your environment

  • version of lnd: lnd version 0.17.4-beta
  • which operating system (uname -a on *Nix): Darwin Kernel Version 22.2.0
  • version of btcd, bitcoind, or other backend: bitcoind in neutrino mode
  • any other relevant environment details

Steps to reproduce

This has happened a while ago, but I can provide any information you want. The node is on testnet and I'm trying to shut it down, so has no funds anymore.

Expected behaviour

LND notices the force channel close and clears the channel from its local database.

Actual behaviour

Channel is stuck in waiting_close_channels forever, even after a full chain rescan.

@wereHamster wereHamster added bug Unintended code behaviour needs triage labels Mar 17, 2024
@ziggie1984
Copy link
Collaborator

Thanks for submitting this issue.

It's also interesting that the committment local_txid (see below) can not be found in the mempool.

The remote commitment got confirmed see: 9d82dcc2eec62a43cb0e4fe6a02a4c3dccc30ee9acd4fc9591ccbaa327fb45b3, that's why you cannot see the local one somewhere.

So find out why your LND did not recognize the spent of the channel point, can you

  1. Switch subsystem CNCT to debug
  2. Check for the following log lines during restart:
  • Starting chain watcher for ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0)

  • New spend subscription: spend_id=???, outpoint= 5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0, script=???, height_hint=???

  1. After obtaining the logs try restarting lnd with:

height-hint-cache-query-disable=true

@wereHamster
Copy link
Contributor Author

Both lines appear in the log. After restarting with height-hint-cache-query-disable=true the channel is still pending.

2024-03-17 23:00:44.475 [INF] LTND: Version: 0.17.4-beta commit=, build=production, logging=default, debuglevel=CNCT=debug
2024-03-17 23:00:44.475 [INF] LTND: Active chain: Bitcoin (network=testnet)
2024-03-17 23:00:44.476 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2024-03-17 23:00:44.478 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2024-03-17 23:00:44.478 [INF] LTND: Opening the main database, this might take a few minutes...
2024-03-17 23:00:44.478 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false
2024-03-17 23:00:44.503 [INF] LTND: Creating local graph and channel state DB instances
2024-03-17 23:00:44.554 [INF] CHDB: Checking for schema update: latest_version=31, db_version=31
2024-03-17 23:00:44.554 [INF] CHDB: Checking for optional update: prune_revocation_log=false, db_version=empty
2024-03-17 23:00:44.554 [INF] LTND: Database(s) now open (time_to_open=75.503416ms)!
2024-03-17 23:00:44.659 [INF] BTCN: Loaded 161 addresses from file '<lnddir>/data/chain/bitcoin/testnet/peers.json'
2024-03-17 23:00:44.659 [INF] BTCN: Registering block subscription: id=1
2024-03-17 23:00:44.659 [INF] BTCN: Broadcaster now active
2024-03-17 23:00:44.659 [INF] LTND: Attempting automatic wallet unlock with password provided in file
2024-03-17 23:00:44.864 [INF] BTCN: Waiting for more block headers, then will start cfheaders sync from height 2582417...
2024-03-17 23:00:44.864 [INF] BTCN: New valid peer bitcoind:18333 (outbound) (/Satoshi:26.0.0/)
2024-03-17 23:00:44.864 [INF] BTCN: Starting cfheaders sync from (block_height=2582417, block_hash=00000000009909f1d3de8ffd268782a906316d5bbfe62bc2d113390a8e3aa7b4) to (block_height=2582417, block_hash=00000000009909f1d3de8ffd268782a906316d5bbfe62bc2d113390a8e3aa7b4)
2024-03-17 23:00:44.864 [INF] BTCN: Starting cfheaders sync for filter_type=0
2024-03-17 23:00:44.864 [INF] BTCN: Syncing to block height 2582417 from peer bitcoind:18333
2024-03-17 23:00:44.864 [INF] BTCN: Fetching set of headers from tip (height=2582417) from peer bitcoind:18333
2024-03-17 23:00:44.931 [INF] CMGR: 1 addresses found from DNS seed x49.testnet-seed.bitcoin.jonasschnelli.ch
2024-03-17 23:00:44.931 [INF] CMGR: 1 addresses found from DNS seed testnet-seed.bluematt.me
2024-03-17 23:00:44.931 [INF] CMGR: DNS discovery failed on seed testnet-seed.bitcoin.schildbach.de: tor host is unreachable
2024-03-17 23:00:44.931 [INF] CMGR: 1 addresses found from DNS seed x49.seed.tbtc.petertodd.net
2024-03-17 23:00:45.136 [INF] LNWL: Opened wallet
2024-03-17 23:00:45.183 [INF] BTCN: Fetching set of checkpointed cfheaders filters from height=2582417, hash=62668889a950793a9907e0b4dbb6ec8d593eb8981c226a9c4839a28d10e1d465
2024-03-17 23:00:45.183 [INF] BTCN: Starting to query for cfheaders from checkpoint_interval=2582, checkpoints=2582
2024-03-17 23:00:45.189 [INF] BTCN: Fully caught up with cfheaders at height 2582417, waiting at tip for new blocks
2024-03-17 23:00:45.208 [INF] CHRE: Primary chain is set to: bitcoin
2024-03-17 23:00:45.702 [INF] LNWL: The wallet has been unlocked without a time limit
2024-03-17 23:00:45.720 [INF] CHRE: LightningWallet opened
2024-03-17 23:00:45.736 [INF] SRVR: Onion services are accessible via Tor! NOTE: Traffic to clearnet services is not routed via Tor.
2024-03-17 23:00:45.736 [INF] TORC: Starting tor controller
2024-03-17 23:00:45.766 [INF] HSWC: Cleaning circuits from disk for closed channels
2024-03-17 23:00:45.783 [INF] HSWC: Finished cleaning: num_closed_channel=10, num_circuits=0, num_keystone=0
2024-03-17 23:00:45.783 [INF] HSWC: Restoring in-memory circuit state from disk
2024-03-17 23:00:45.797 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2024-03-17 23:00:45.854 [INF] LTND: Channel backup proxy channel notifier starting
2024-03-17 23:00:45.854 [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-03-17 23:00:45.854 [INF] LTND: We're not running within systemd or the service type is not 'notify'
2024-03-17 23:00:45.854 [INF] LTND: Waiting for chain backend to finish sync, start_height=2582417
2024-03-17 23:00:46.734 [INF] BTCN: Registering block subscription: id=2
2024-03-17 23:00:46.912 [INF] LNWL: Started rescan from block 00000000009909f1d3de8ffd268782a906316d5bbfe62bc2d113390a8e3aa7b4 (height 2582417) for 53 addresses
2024-03-17 23:00:46.912 [INF] BTCN: Canceling block subscription: id=2
2024-03-17 23:00:46.912 [INF] LNWL: Catching up block hashes to height 2582417, this might take a while
2024-03-17 23:00:46.912 [INF] BTCN: Registering block subscription: id=3
2024-03-17 23:00:46.926 [INF] LNWL: Done catching up block hashes
2024-03-17 23:00:46.926 [INF] LNWL: Finished rescan for 53 addresses (synced to block 00000000009909f1d3de8ffd268782a906316d5bbfe62bc2d113390a8e3aa7b4, height 2582417)
2024-03-17 23:00:47.857 [INF] LTND: Chain backend is fully synced (end_height=2582417)!
2024-03-17 23:00:47.857 [WRN] HLCK: check: disk space configured with 0 attempts, skipping it
2024-03-17 23:00:47.857 [WRN] HLCK: check: tls configured with 0 attempts, skipping it
2024-03-17 23:00:47.857 [WRN] HLCK: check: tor connection configured with 0 attempts, skipping it
2024-03-17 23:00:47.857 [INF] LNWL: SigPool starting
2024-03-17 23:00:47.857 [INF] CHNF: ChannelNotifier starting
2024-03-17 23:00:47.858 [INF] PRNF: PeerNotifier starting
2024-03-17 23:00:47.858 [INF] HSWC: HtlcNotifier starting
2024-03-17 23:00:47.858 [INF] SWPR: Sweeper starting
2024-03-17 23:00:47.858 [INF] UTXN: UTXO nursery starting
2024-03-17 23:00:47.858 [INF] BTCN: Registering block subscription: id=4
2024-03-17 23:00:47.858 [INF] NTFN: New block epoch subscription
2024-03-17 23:00:47.862 [INF] NTFN: New block epoch subscription
2024-03-17 23:00:47.862 [INF] BRAR: Breach arbiter starting
2024-03-17 23:00:47.866 [INF] FNDG: Funding manager starting
2024-03-17 23:00:47.866 [INF] BRAR: Starting contract observer, watching for breaches.
2024-03-17 23:00:47.867 [INF] HSWC: HTLC Switch starting
2024-03-17 23:00:47.867 [INF] NTFN: New block epoch subscription
2024-03-17 23:00:47.867 [INF] CNCT: ChainArbitrator starting
2024-03-17 23:00:47.867 [INF] NTFN: New block epoch subscription
2024-03-17 23:00:47.868 [INF] CNCT: Creating ChannelArbitrators for 1 active channels
2024-03-17 23:00:47.868 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0)
2024-03-17 23:00:47.868 [WRN] CNCT: Channel 5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0 is in state ChanStatusCoopBroadcasted, but no coop closing tx to re-publish...
2024-03-17 23:00:47.872 [DBG] CNCT: Starting chain watcher for ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0)
2024-03-17 23:00:47.872 [INF] NTFN: New spend subscription: spend_id=1, outpoint=5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0, script=0 f8e1428d0f5e35190c44e0965aa921dde27ce1c22b47788fbd9ad8ca01bb920c, height_hint=2469360
2024-03-17 23:00:47.872 [INF] NTFN: Dispatching historical spend rescan for outpoint=5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0, script=0 f8e1428d0f5e35190c44e0965aa921dde27ce1c22b47788fbd9ad8ca01bb920c, start=2469360, end=2582417
2024-03-17 23:00:47.872 [INF] CNCT: Close observer for ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0) active
2024-03-17 23:00:47.872 [DBG] CNCT: Starting ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0), htlc_set=(map[contractcourt.HtlcSetKey]contractcourt.htlcSet) (len=2) {
 (contractcourt.HtlcSetKey) LocalHtlcSet: (contractcourt.htlcSet) {
  incomingHTLCs: (map[uint64]channeldb.HTLC) {
  },
  outgoingHTLCs: (map[uint64]channeldb.HTLC) {
  }
 },
 (contractcourt.HtlcSetKey) RemoteHtlcSet: (contractcourt.htlcSet) {
  incomingHTLCs: (map[uint64]channeldb.HTLC) {
  },
  outgoingHTLCs: (map[uint64]channeldb.HTLC) {
  }
 }
}
, state=StateDefault
2024-03-17 23:00:47.872 [INF] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): starting state=StateDefault, trigger=chainTrigger, triggerHeight=2582417
2024-03-17 23:00:47.872 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): attempting state step with trigger=chainTrigger from state=StateDefault
2024-03-17 23:00:47.872 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): new block (height=2582417) examining active HTLC's
2024-03-17 23:00:47.872 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): checking commit chain actions at height=2582417, in_htlc_count=0, out_htlc_count=0
2024-03-17 23:00:47.872 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): no actions for chain trigger, terminating
2024-03-17 23:00:47.872 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): terminating at state=StateDefault
2024-03-17 23:00:47.873 [INF] DISC: Authenticated Gossiper starting
2024-03-17 23:00:47.873 [INF] NTFN: New block epoch subscription
2024-03-17 23:00:47.873 [INF] NTFN: New block epoch subscription
2024-03-17 23:00:47.873 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): attempting state step with trigger=chainTrigger from state=StateDefault
2024-03-17 23:00:47.873 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): new block (height=2582417) examining active HTLC's
2024-03-17 23:00:47.873 [INF] CRTR: Channel Router starting
2024-03-17 23:00:47.873 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): checking commit chain actions at height=2582417, in_htlc_count=0, out_htlc_count=0
2024-03-17 23:00:47.873 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): no actions for chain trigger, terminating
2024-03-17 23:00:47.873 [DBG] CNCT: ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): terminating at state=StateDefault
2024-03-17 23:00:47.890 [INF] INVC: InvoiceRegistry starting
2024-03-17 23:00:47.891 [INF] NTFN: New block epoch subscription
2024-03-17 23:00:47.891 [INF] HSWC: Onion processor starting
2024-03-17 23:00:47.904 [INF] NANN: Channel Status Manager starting
2024-03-17 23:00:47.904 [INF] NTFN: New block epoch subscription
2024-03-17 23:00:47.904 [INF] CHFT: ChannelEventStore starting
2024-03-17 23:00:47.905 [INF] CHFT: Adding 0 channels to event store
2024-03-17 23:00:47.905 [INF] CHBU: chanbackup.SubSwapper starting
2024-03-17 23:00:47.934 [WRN] CHBU: Replacing disk backup for ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0) w/ newer version
2024-03-17 23:00:47.947 [INF] CHBU: Updating backup file at <lnddir>/data/chain/bitcoin/testnet/channel.backup
2024-03-17 23:00:47.957 [INF] CHBU: Swapping old multi backup file from <lnddir>/data/chain/bitcoin/testnet/temp-dont-use.backup to <lnddir>/data/chain/bitcoin/testnet/channel.backup
2024-03-17 23:00:48.032 [INF] CMGR: Server listening on [::]:9735
2024-03-17 23:00:48.033 [INF] SRVR: Initializing peer network bootstrappers!
2024-03-17 23:00:48.033 [INF] SRVR: Creating DNS peer bootstrapper with seeds: [[test.nodes.lightning.directory soa.nodes.lightning.directory]]
2024-03-17 23:00:48.033 [INF] DISC: Attempting to bootstrap with: BOLT-0010 DNS Seed: [[test.nodes.lightning.directory soa.nodes.lightning.directory]]
2024-03-17 23:00:51.524 [ERR] DISC: Unable to query bootstrapper BOLT-0010 DNS Seed: [[test.nodes.lightning.directory soa.nodes.lightning.directory]]: tor host is unreachable
2024-03-17 23:00:51.524 [INF] DISC: Attempting to bootstrap with: Authenticated Channel Graph
2024-03-17 23:00:51.531 [INF] DISC: Obtained 3 addrs to bootstrap network with
2024-03-17 23:00:56.533 [INF] DISC: Attempting to bootstrap with: Authenticated Channel Graph
2024-03-17 23:00:56.546 [INF] DISC: Obtained 3 addrs to bootstrap network with
2024-03-17 23:00:56.684 [ERR] SRVR: Unable to connect to 02da40a9da7d1355747d3468a6db99fa0f5300e1a5473dc1bde128fa60ec69da15@34.205.78.66:9735: dial proxy failed: dial tcp 34.205.78.66:9735: connect: connection refused
2024-03-17 23:00:56.684 [ERR] SRVR: Unable to connect to 02da40a9da7d1355747d3468a6db99fa0f5300e1a5473dc1bde128fa60ec69da15@34.205.78.66:9735: dial proxy failed: dial tcp 34.205.78.66:9735: connect: connection refused
2024-03-17 23:01:03.548 [INF] DISC: Attempting to bootstrap with: BOLT-0010 DNS Seed: [[test.nodes.lightning.directory soa.nodes.lightning.directory]]
2024-03-17 23:01:07.453 [INF] DISC: Obtained 3 addrs to bootstrap network with
2024-03-17 23:01:07.634 [INF] SRVR: Established connection to: 039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713@13.69.130.216:9735
2024-03-17 23:01:07.634 [INF] SRVR: Finalizing connection to 039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713@13.69.130.216:9735, inbound=false
2024-03-17 23:01:07.717 [INF] PEER: Peer(039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713): Negotiated chan series queries
2024-03-17 23:01:07.717 [INF] DISC: Creating new GossipSyncer for peer=039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713
2024-03-17 23:01:07.717 [INF] NTFN: New block epoch subscription
2024-03-17 23:01:07.719 [INF] DISC: GossipSyncer(039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713): requesting new chans from height=0 and 2582417 blocks after
2024-03-17 23:01:07.747 [INF] SRVR: Established connection to: 028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f@34.138.237.159:9735
2024-03-17 23:01:07.747 [INF] SRVR: Finalizing connection to 028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f@34.138.237.159:9735, inbound=false
2024-03-17 23:01:07.778 [INF] SRVR: Established connection to: 030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2@52.22.139.174:9734
2024-03-17 23:01:07.778 [INF] SRVR: Finalizing connection to 030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2@52.22.139.174:9734, inbound=false
2024-03-17 23:01:07.896 [INF] PEER: Peer(028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f): Negotiated chan series queries
2024-03-17 23:01:07.896 [INF] NTFN: New block epoch subscription
2024-03-17 23:01:07.896 [INF] DISC: Creating new GossipSyncer for peer=028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f
2024-03-17 23:01:07.923 [INF] NTFN: New block epoch subscription
2024-03-17 23:01:07.923 [INF] PEER: Peer(030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2): Negotiated chan series queries
2024-03-17 23:01:07.929 [INF] DISC: Creating new GossipSyncer for peer=030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2
2024-03-17 23:01:07.972 [INF] DISC: GossipSyncer(039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713): buffering chan range reply of size=6340
2024-03-17 23:01:07.972 [INF] DISC: GossipSyncer(039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713): filtering through 6340 chans
2024-03-17 23:01:07.979 [INF] DISC: GossipSyncer(039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713): remote peer has no new chans
2024-03-17 23:01:07.979 [INF] DISC: GossipSyncer(039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713): applying gossipFilter(start=2024-03-17 23:01:07.979825 +0100 CET m=+23.533300542, end=2160-04-24 06:29:22.979825 +0200 CEST)
2024-03-17 23:01:07.993 [INF] DISC: GossipSyncer(028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f): applying gossipFilter(start=2024-03-17 23:01:07.99303 +0100 CET m=+23.546504209, end=2160-04-24 06:29:22.99303 +0200 CEST)
2024-03-17 23:01:07.993 [INF] DISC: GossipSyncer(030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2): applying gossipFilter(start=2024-03-17 23:01:07.993088 +0100 CET m=+23.546562876, end=2160-04-24 06:29:22.993088 +0200 CEST)
2024-03-17 23:01:08.733 [INF] SRVR: Established connection to: 038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9@203.132.94.196:9735
2024-03-17 23:01:08.733 [INF] SRVR: Finalizing connection to 038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9@203.132.94.196:9735, inbound=false
2024-03-17 23:01:09.188 [INF] PEER: Peer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): Loading ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0), isPending=false
2024-03-17 23:01:09.188 [WRN] PEER: Peer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0) has status ChanStatusCoopBroadcasted|ChanStatusLocalCloseInitiator, won't start.
2024-03-17 23:01:09.229 [INF] PEER: Peer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): Delivery addr for channel close: tb1plxn293la59mq44r3haxvmzuynqyymqtjqd6sd6w6dp77wz6pplzqxjmfun
2024-03-17 23:01:09.230 [INF] CHCL: ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): initiating shutdown
2024-03-17 23:01:09.269 [INF] CHCL: ChannelPoint(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0): sending shutdown message
2024-03-17 23:01:09.269 [INF] PEER: Peer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): Sending 2 channel sync messages to peer after loading active channels
2024-03-17 23:01:09.270 [INF] PEER: Peer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): Negotiated chan series queries
2024-03-17 23:01:09.270 [INF] DISC: Creating new GossipSyncer for peer=038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9
2024-03-17 23:01:09.270 [INF] NTFN: New block epoch subscription
2024-03-17 23:01:09.695 [ERR] PEER: Peer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): resend failed: unable to fetch channel sync messages for peer 038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9@203.132.94.196:9735: unable to find closed channel summary
2024-03-17 23:01:11.326 [ERR] SRVR: Unable to connect to 028ff9e9260023b08cdafb798dadb7463c88e839e1e1ac3c3e1d2bd2ba60487407@mspmb3oxowyav757znjs7lnt3pkyhq3o4d36rqztpwcnaufdzdmu5uyd.onion:9735: dial proxy failed: socks connect tcp 127.0.0.1:9050->mspmb3oxowyav757znjs7lnt3pkyhq3o4d36rqztpwcnaufdzdmu5uyd.onion:9735: unknown error host unreachable
2024-03-17 23:01:11.649 [ERR] SRVR: Unable to connect to 02da23cbe5659151d1db415dbfcff973bc213b979be52a8e86690d02cefa927dfe@qsavfakwq3hbvi4x73y5afhapqttew422dgfvmv3e3yhvmi4xld3m4ad.onion:9735: dial proxy failed: socks connect tcp 127.0.0.1:9050->qsavfakwq3hbvi4x73y5afhapqttew422dgfvmv3e3yhvmi4xld3m4ad.onion:9735: unknown error host unreachable
2024-03-17 23:01:17.875 [INF] CRTR: Initial zombie prune starting
2024-03-17 23:01:17.875 [INF] CRTR: Examining channel graph for zombie channels
2024-03-17 23:01:17.878 [INF] CRTR: Pruning 0 zombie channels
2024-03-17 23:01:40.899 [ERR] SRVR: Unable to connect to 02555da2675be850dae70ff0ff2d33a63c014b8425df22b2137f5f33797ee0324e@gkq5l4viwbchl3tm6z66jwz2pehvucqdihxyktfopdlqg4uglfaroeyd.onion:9735: dial proxy failed: socks connect tcp 127.0.0.1:9050->gkq5l4viwbchl3tm6z66jwz2pehvucqdihxyktfopdlqg4uglfaroeyd.onion:9735: unknown error host unreachable
2024-03-17 23:02:06.534 [ERR] SRVR: Unable to connect to 02da1a4fe9b0188ea755142af430ffbf4fca26ee8b2d735d6a1c83f1a8ad47b8e7@52.166.88.225:9735: dial proxy failed: dial tcp 52.166.88.225:9735: connect: operation timed out
2024-03-17 23:02:11.550 [ERR] SRVR: Unable to connect to 02c541782a86b82f21026f0ce0f1cb445f5ec5d7de2005d3965c84bc7b3592518d@73.241.202.154:9735: dial proxy failed: dial tcp 73.241.202.154:9735: connect: operation timed out
2024-03-17 23:02:36.140 [INF] LTND: Received shutdown request.
2024-03-17 23:02:36.140 [INF] LTND: Shutting down...
2024-03-17 23:02:36.143 [INF] LTND: Gracefully shutting down.
2024-03-17 23:02:36.143 [INF] NANN: Channel Status Manager shutting down
2024-03-17 23:02:36.143 [INF] HSWC: HTLC Switch shutting down
2024-03-17 23:02:36.143 [INF] NTFN: Cancelling epoch notification, epoch_id=3
2024-03-17 23:02:36.143 [INF] HSWC: Onion processor shutting down
2024-03-17 23:02:36.143 [INF] HSWC: Decaying hash log received shutdown request
2024-03-17 23:02:36.143 [INF] NTFN: Cancelling epoch notification, epoch_id=8
2024-03-17 23:02:36.143 [INF] INVC: InvoiceRegistry shutting down
2024-03-17 23:02:36.143 [INF] NTFN: Cancelling epoch notification, epoch_id=7
2024-03-17 23:02:36.143 [INF] CRTR: Channel Router shutting down
2024-03-17 23:02:36.143 [INF] CNCT: ChainArbitrator shutting down
2024-03-17 23:02:36.143 [DBG] CNCT: Stopping ChannelArbitrator(5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0)
2024-03-17 23:02:36.143 [INF] NTFN: Cancelling epoch notification, epoch_id=5
2024-03-17 23:02:36.143 [INF] FNDG: Funding manager shutting down
2024-03-17 23:02:36.143 [INF] BRAR: Breach arbiter shutting down
2024-03-17 23:02:36.143 [INF] UTXN: UTXO nursery shutting down
2024-03-17 23:02:36.143 [INF] NTFN: Cancelling epoch notification, epoch_id=2
2024-03-17 23:02:36.143 [INF] DISC: Authenticated gossiper shutting down
2024-03-17 23:02:36.143 [INF] DISC: Authenticated Gossiper is stopping
2024-03-17 23:02:36.143 [INF] NTFN: Cancelling epoch notification, epoch_id=6
2024-03-17 23:02:36.143 [INF] DISC: Authenticated Gossiper stopped
2024-03-17 23:02:36.143 [INF] SWPR: Sweeper shutting down
2024-03-17 23:02:36.144 [INF] NTFN: Cancelling epoch notification, epoch_id=1
2024-03-17 23:02:36.144 [INF] CHNF: ChannelNotifier shutting down
2024-03-17 23:02:36.144 [INF] PRNF: PeerNotifier shutting down
2024-03-17 23:02:36.144 [INF] HSWC: HtlcNotifier shutting down
2024-03-17 23:02:36.144 [INF] CHBU: Stopping chanbackup.SubSwapper
2024-03-17 23:02:36.144 [INF] NTFN: neutrino notifier shutting down
2024-03-17 23:02:36.144 [ERR] NTFN: Failed getting UTXO: get utxo request cancelled
2024-03-17 23:02:36.144 [INF] CHFT: Stopping event store
2024-03-17 23:02:36.144 [INF] BTCN: Canceling block subscription: id=4
2024-03-17 23:02:36.144 [ERR] HSWC: InterceptableSwitch stopped: block epoch stream stopped
2024-03-17 23:02:36.155 [INF] SRVR: Disconnecting from 030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2@52.22.139.174:9734
2024-03-17 23:02:36.155 [INF] PEER: Peer(030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2): disconnecting 030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2@52.22.139.174:9734, reason: server: DisconnectPeer called
2024-03-17 23:02:36.155 [INF] PEER: Peer(030c5522b1cbbd874a1d14a0c1de921bb6f55be0047be83efbf7bc4111fa2ca7a2): unable to read message from peer: read next header: read tcp 172.20.10.10:50254->52.22.139.174:9734: use of closed network connection
2024-03-17 23:02:36.155 [INF] SRVR: Disconnecting from 038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9@203.132.94.196:9735
2024-03-17 23:02:36.155 [INF] PEER: Peer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): disconnecting 038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9@203.132.94.196:9735, reason: server: DisconnectPeer called
2024-03-17 23:02:36.155 [INF] PEER: Peer(038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9): unable to read message from peer: read next header: read tcp 172.20.10.10:50257->203.132.94.196:9735: use of closed network connection
2024-03-17 23:02:36.155 [INF] SRVR: Disconnecting from 039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713@13.69.130.216:9735
2024-03-17 23:02:36.155 [INF] PEER: Peer(039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713): disconnecting 039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713@13.69.130.216:9735, reason: server: DisconnectPeer called
2024-03-17 23:02:36.155 [INF] PEER: Peer(039ee4e3a1d7435b399aadaf3e096ddf85e5f17d4cda4491e589b9a9591c171713): unable to read message from peer: read next header: read tcp 172.20.10.10:50253->13.69.130.216:9735: use of closed network connection
2024-03-17 23:02:36.155 [INF] SRVR: Disconnecting from 028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f@34.138.237.159:9735
2024-03-17 23:02:36.162 [INF] PEER: Peer(028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f): disconnecting 028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f@34.138.237.159:9735, reason: server: DisconnectPeer called
2024-03-17 23:02:36.162 [INF] PEER: Peer(028c3640c57ffe47eb41db8225968833c5032f297aeba98672d6f7037090d59e3f): unable to read message from peer: read next header: read tcp 172.20.10.10:50252->34.138.237.159:9735: use of closed network connection
2024-03-17 23:02:36.162 [INF] HLCK: Health monitor shutting down
2024-03-17 23:02:36.264 [INF] RPCS: Stopping RPC Server
2024-03-17 23:02:36.264 [INF] RPCS: Stopping VersionRPC Sub-RPC Server
2024-03-17 23:02:36.264 [INF] RPCS: Stopping AutopilotRPC Sub-RPC Server
2024-03-17 23:02:36.264 [INF] RPCS: Stopping WatchtowerRPC Sub-RPC Server
2024-03-17 23:02:36.264 [INF] RPCS: Stopping InvoicesRPC Sub-RPC Server
2024-03-17 23:02:36.271 [INF] RPCS: Stopping RouterRPC Sub-RPC Server
2024-03-17 23:02:36.271 [INF] RPCS: Stopping WatchtowerClientRPC Sub-RPC Server
2024-03-17 23:02:36.271 [INF] RPCS: Stopping ChainRPC Sub-RPC Server
2024-03-17 23:02:36.271 [INF] RPCS: Stopping SignRPC Sub-RPC Server
2024-03-17 23:02:36.271 [INF] RPCS: Stopping WalletKitRPC Sub-RPC Server
2024-03-17 23:02:36.271 [INF] TORC: Stopping tor controller
2024-03-17 23:02:36.276 [INF] BTCN: Canceling block subscription: id=1
2024-03-17 23:02:36.297 [ERR] BTCN: utxo scan failed: neutrino shutting down
2024-03-17 23:02:36.327 [INF] BTCN: Block manager shutting down
2024-03-17 23:02:36.378 [INF] BTCN: Address manager shutting down
2024-03-17 23:02:36.380 [INF] LTND: Shutdown complete

@ziggie1984
Copy link
Collaborator

The rescan for the output might take a while don't stop the node:

2024-03-17 23:00:47.872 [INF] NTFN: Dispatching historical spend rescan for outpoint=5ab08b2c8f1e442821746736582dbb390757488e27946f7967c6d678d71381bc:0, script=0 f8e1428d0f5e35190c44e0965aa921dde27ce1c22b47788fbd9ad8ca01bb920c, start=2469360, end=2582417

normally it should be able to recognize the spend of the channel opening.

@wereHamster
Copy link
Contributor Author

Ah indeed, I let the node run for the night and now the channel is gone from waiting_close_channels.

What was the cause of this? did lnd miss a transaction at some point? Or is there a bug is some logic that height-hint-cache-query-disable=true works around?

@ziggie1984
Copy link
Collaborator

Yes I haven't been able to reproduce this edge case which happens sometime, where the height_hint cache has a wrong value in it.

We are aware of this behavior and track it here: #8120

Therefore I am closing this issue.

Feel free to reach out if you have further questions.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Unintended code behaviour needs triage
Projects
None yet
Development

No branches or pull requests

2 participants