Channels stuck on wainting_close_channels but final txs have been confirmed.

[sebareca]

Background

I closed some channels a long time ago but they are stuck on waiting_close_channels
and the "unlocked" funds don't appear as unconfirmed or confirmed balance in the lnd wallet.
The corresponding final transactions have been confirmed a long time ago.

Your environment

• version of lnd= 0.6.0-beta
• operating system = Linux ip-10-2-11-182 4.15.0-1035-aws Light-152 multihop routing #37-Ubuntu SMP Mon Mar 18 16:15:14 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
• bitcoind = v0.16.0.0-g4b4d7eb255

Steps to reproduce

Close some channels.

Expected behaviour

eventually i should see the local balance of each closed channel as wallet balance and
lnd should stop waiting for the final transactions.

Actual behaviour

Response of pendingchannels:

{
    "total_limbo_balance": "68930941",
    "pending_open_channels": [
    ],
    "pending_closing_channels": [
    ],
    "pending_force_closing_channels": [
    ],
    "waiting_close_channels": [
        {
            "channel": {
                "remote_node_pub": "021c97a90a411ff2b10dc2a8e32de2f29d2fa49d41bfbb52bd416e460db0747d0d",
                "channel_point": "67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0",
                "capacity": "16777215",
                "local_balance": "16761438",
                "remote_balance": "0"
            },
            "limbo_balance": "16761438"
        },
        {
            "channel": {
                "remote_node_pub": "02bebaf15c038fa52a59eb5870cd3b6cb3af6b38b91c316243805df8a2dbd20d3c",
                "channel_point": "81ea221e0ddad70d5046946e89a0e5ba1b2c0b2cbd779afa676013d2181ec291:0",
                "capacity": "16777215",
                "local_balance": "16755285",
                "remote_balance": "0"
            },
            "limbo_balance": "16755285"
        },
        {
            "channel": {
                "remote_node_pub": "0330f0afe893e809d8790b26b40d9353f586ef0894d4ae704d06be24538c030457",
                "channel_point": "b852772aef9d648510978e3ad01a8ed0808dc27e34e426e90337a4f326827e31:1",
                "capacity": "16777215",
                "local_balance": "16764873",
                "remote_balance": "0"
            },
            "limbo_balance": "16764873"
        },
        {
            "channel": {
                "remote_node_pub": "0390b5d4492dc2f5318e5233ab2cebf6d48914881a33ef6a9c6bcdbb433ad986d0",
                "channel_point": "3c7cb2e054fb54a257503d1027c4d5a0ff2b42a25fa1132b1f62960838630b33:0",
                "capacity": "1900000",
                "local_balance": "1882271",
                "remote_balance": "0"
            },
            "limbo_balance": "1882271"
        },
        {
            "channel": {
                "remote_node_pub": "03df3f0a2fd6bea5429a596461ce784c922b2981ada1af89cfefcd9ccfb16c16a7",
                "channel_point": "c84288de1860aae9f18a68482e16e65a0eb1289d4c4151acea6d06101d54da3f:0",
                "capacity": "16777215",
                "local_balance": "16767074",
                "remote_balance": "0"
            },
            "limbo_balance": "16767074"
        }
    ]
}

this is one of the peding channels.

  {
            "channel": {
                "remote_node_pub": "021c97a90a411ff2b10dc2a8e32de2f29d2fa49d41bfbb52bd416e460db0747d0d",
                "channel_point": "67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0",
                "capacity": "16777215",
                "local_balance": "16761438",
                "remote_balance": "0"
            },
            "limbo_balance": "16761438"
        },

the funding tx: https://www.blockchain.com/btc/tx/67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48

The closing tx:
https://www.blockchain.com/btc/tx/b02e9b0be768627bec12755daf649284d6dd153e83e71bc957cdadb311e3a9fd

the final tx description from listchaintxs:

{
            "tx_hash": "b02e9b0be768627bec12755daf649284d6dd153e83e71bc957cdadb311e3a9fd",
            "amount": "0",
            "num_confirmations": 1177,
            "block_hash": "00000000000000000013e444271bf52065cf4a87bc5b4fd09957e7a4d4282910",
            "block_height": 572773,
            "time_stamp": "1555948944",
            "total_fees": "0",
            "dest_addresses": [
                "bc1q4turnl6sv0qwk02mh30cldjuwx89k7h0ue3k7q",
                "bc1qvqzfqe4l4rff3pgs9s8h585ussl8h3zg4q5du68qqeq3adp4cagqyehggy"
            ]
        },

[Roasbeef]

How long ago? What version were you running when you closed them? Is your bitcoind properly connected, on restart, do you see any relevant logs?

[sebareca]

• the channel 67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0 was closed on Monday, April 22, 2019 4:02:24 PM GTM
• I was running lnd v0.6-beta
• The bitcoind is fully synchronized and i don't see any relevant logs.
• These are lnd logs for that particular channel

2019-05-01 14:43:09.231 [DBG] CNCT: Stopping ChannelArbitrator(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0)
2019-05-01 15:14:30.665 [DBG] CHBU: Crafting backup for ChannelPoint(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0)
2019-05-01 15:14:32.801 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0)
2019-05-01 15:14:32.802 [DBG] CNCT: Starting chain watcher for ChannelPoint(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0)
2019-05-01 15:14:32.802 [DBG] NTFN: Using height hint 574097 retrieved from cache for outpoint=67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0 instead of 570077
2019-05-01 15:14:32.802 [INF] NTFN: New spend subscription: spend_id=7, outpoint=67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0, height_hint=574097
2019-05-01 15:14:32.802 [DBG] NTFN: Dispatching historical spend rescan for outpoint=67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0
2019-05-01 15:14:32.895 [INF] CNCT: Close observer for ChannelPoint(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0) active
2019-05-01 15:14:33.514 [DBG] CNCT: Starting ChannelArbitrator(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0), htlc_set=(contractcourt.htlcSet) {
2019-05-01 15:14:33.514 [INF] CNCT: ChannelArbitrator(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0): starting state=StateCommitmentBroadcasted
2019-05-01 15:14:33.775 [INF] CNCT: ChannelArbitrator(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0): noop trigger chainTrigger
2019-05-01 15:14:38.073 [DBG] LNWL: ChannelPoint(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0), starting local commitment: (*lnwallet.commitment)(0xc000f86240)({
    PreviousOutPoint: (wire.OutPoint) 67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0,
2019-05-01 15:14:38.078 [DBG] LNWL: ChannelPoint(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0), starting remote commitment: (*lnwallet.commitment)(0xc0026e6cc0)({
    PreviousOutPoint: (wire.OutPoint) 67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0,
2019-05-01 15:14:38.079 [INF] PEER: NodeKey(021c97a90a411ff2b10dc2a8e32de2f29d2fa49d41bfbb52bd416e460db0747d0d) loading ChannelPoint(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0)
2019-05-01 15:14:38.079 [WRN] PEER: ChannelPoint(67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0) has status ChanStatusDefault|ChanStatusBorked|ChanStatusCommitBroadcasted, won't start.

[wpaulino]

2019-05-01 15:14:32.802 [DBG] NTFN: Using height hint 574097 retrieved from cache for outpoint=67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48:0 instead of 570077

Looks like the cache stored a value (574097) past the spending height (572773).

[wpaulino]

@sebareca to help narrow it down, I'd like to know if we missed the spend while we were online or offline. Do you see the log message New block: height=572773 within your logs? If you don't, what's the earliest height you see?

[sebareca]

Our server erased all the logs :S. I will try to reproduce the problem once again.

[wpaulino]

It might not be so easy to reproduce considering this is the first report of its kind on something that's done quite often within lnd. If you're comfortable with compiling from source, you can use the following patch to use the right height in order to detect the spend and proceed to sweep the channel:

diff --git a/chainntnfs/txnotifier.go b/chainntnfs/txnotifier.go
index 919c08d8..8791c779 100644
--- a/chainntnfs/txnotifier.go
+++ b/chainntnfs/txnotifier.go
@@ -853,6 +853,15 @@ func (n *TxNotifier) RegisterSpend(ntfn *SpendNtfn) (*HistoricalSpendDispatch,
 			ntfn.SpendRequest, err)
 	}
 
+	hash, err := chainhash.NewHashFromStr("67db75d7700d2a2db8ffddd11441193cb9416b6ae8229e06ac8f5c97adc42a48")
+	if err != nil {
+		return nil, 0, err
+	}
+	op := wire.OutPoint{Hash: *hash, Index: 0}
+	if ntfn.OutPoint == op {
+		startHeight = 572773
+	}
+
 	n.Lock()
 	defer n.Unlock()
 

[astuteguy]

I think it would be great if we can add option of rescanning blockchain if wallet fails to confirm transaction status and give option of revealing seed phrase so that even if wallet doesn't rescan or picks up the true status, user can delete all data and reinstall the wallet.