Remote node returns error about exceeding max pending channels while no pending channels

[cryptomeow]

Background

I am trying to open a channel with the OpenNode lnd node, with which I used to have a channel in the past but after some time it got forced closed for some reason.
I then discovered that there was a ghost inbound channel from OpenNode for which the TX was never broadcasted. I force-closed all of them and waited till the locktime was over.

Now when I try to open a channel with the same node I get an error about max pending channels.
I contacted the João from OpenNode and there are no pending channels with my node (meanwhile he managed to open a channel to my node just fine).

It seems like there's something got out-of-sync around the pending channels.

All this happened before both of us upgrade to 0.5.1+ so the migrations didn't help. I still get the same remote error about max pending channels.

If the issue with ghost channels (i.e. creating channels by spending already-spent outputs) is fixed, the might not happen again, but it would be nice if there was a way to fix past out-of-sync state.

Your environment

• lnd 4da1c86
• OS: Ubuntu 16.04 LTS 4.4.0-119-generic
• bitcoind 0.16.3

Steps to reproduce

Difficult to reproduce. Maybe, with maxpendingchannels=1, have NodeA creating somehow a ghost channel with NodeB. NodeB force-closing that ghost channel, then NodeB trying to open a channel with NodeA. (or NodeB force-closing that ghost channel as well)

lncli openchannel 03abf6f44c355dec0d5aa155bdbdd6e0c8fefe318eff402de65c6eb2e1be55dc3e 5217000
[lncli] rpc error: code = Code(101) desc = Number of pending channels exceed maximum

lnd logs

2018-11-25 15:57:40.837 [INF] HSWC: ChannelPoint(f794f34a4bfbb5ef81259194399a819a71e20523412c863c0ad2b814923e4b38:0): updating commit fee to 9023 sat/kw
2018-11-25 15:57:41.460 [INF] FNDG: Initiating fundingRequest(localAmt=0.05217 BTC, remoteAmt=0 mSAT, capacity=0.05217 BTC, chainhash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, peer=03abf6f44c355dec0d5aa155bdbdd6e0c8fefe318eff402de65c6eb2e1be55dc3e, dustLimit=0.00000573 BTC, min_confs=1)
2018-11-25 15:57:41.461 [INF] LNWL: Performing funding tx coin selection using 4816 sat/kw as fee rate
2018-11-25 15:57:41.472 [INF] FNDG: Target commit tx sat/kw for pendingID(cd1de988128bdabd7b7e2396892f333d1f147fdfb5602cc01cab98a4cd3d62c0): 9023
2018-11-25 15:57:41.472 [INF] FNDG: Starting funding workflow with 52.15.79.245:60446 for pendingID(cd1de988128bdabd7b7e2396892f333d1f147fdfb5602cc01cab98a4cd3d62c0)
2018-11-25 15:57:41.571 [INF] FNDG: Cancelling funding reservation for node_key=03abf6f44c355dec0d5aa155bdbdd6e0c8fefe318eff402de65c6eb2e1be55dc3e, chan_id=cd1de988128bdabd7b7e2396892f333d1f147fdfb5602cc01cab98a4cd3d62c0
2018-11-25 15:57:41.571 [ERR] FNDG: Received funding error from 03abf6f44c355dec0d5aa155bdbdd6e0c8fefe318eff402de65c6eb2e1be55dc3e: 
2018-11-25 15:57:41.571 [ERR] RPCS: unable to open channel to NodeKey(03abf6f44c355dec0d5aa155bdbdd6e0c8fefe318eff402de65c6eb2e1be55dc3e): rpc error: code = Code(101) desc = Number of pending channels exceed maximum

Expected behaviour

Opening channels without faulty/ghost past channels counting as pending.

[Roasbeef]

Who initiated the last channel between y'all? Has 288 blocks passed since that channel was created? If the funding transaction was never broadcast, then the responder will forget the channel. However, we don't as the initiator, since we need to double-spend the inputs used in order to invalidate the original funding transaction.

Related to #386

[wpaulino]

Considering our wallet issues in the past, I'd say it's more likely that the funding transaction is invalid by attempting to double spend an input. This is something that we don't currently detect at the moment. If this is the case, I would suggest using the AbandonChannel RPC on a debug build of lnd.

note added: abandonchannel is a dangerous command and can lead to loss of funds if used incorrectly - ask in the LND slack channel if unsure

[cryptomeow]

Unless I'm mistaken the ghost channel was initiated from the OpenNode side and the final channel (which is fine and still active) was also initiated from OpenNode. Also it's been more than 288 blocks since any of the channels were created.

Here's the full history of the closed channels my node has involving OpenNode.

[redacted]

I don't see the ghost channel on the closedchannels probably because force-closing those isn't fully successfully so they are not recorded.

When OpenNode force-closed the ghost channel it returned the following:

2018-11-26 12:06:06.476 [INF] LNWL: Inserting unconfirmed transaction fa4e6a6d1dc8f96def00366ba603e967704c7b8bacf5caf0d30253b79fa72199
2018-11-26 12:06:06.489 [ERR] CNCT: ChannelArbitrator(cc7a059a5b690dad03b3d93a47f1af93a0a382a801111f618255f1825ad4134e:0): unable to broadcast close tx: Transaction rejected: output already spent
2018-11-26 12:06:06.510 [INF] CNCT: ChannelArbitrator(cc7a059a5b690dad03b3d93a47f1af93a0a382a801111f618255f1825ad4134e:0): noop trigger userTrigger
2018-11-26 12:06:06.510 [ERR] CNCT: Unable to disable channel cc7a059a5b690dad03b3d93a47f1af93a0a382a801111f618255f1825ad4134e:0 on close: edge not found
2018-11-26 12:06:06.510 [INF] PEER: Waiting for confirmation of cooperative close of ChannelPoint(cc7a059a5b690dad03b3d93a47f1af93a0a382a801111f618255f1825ad4134e:0) with txid: fa4e6a6d1dc8f96def00366ba603e967704c7b8bacf5caf0d30253b79fa72199
2018-11-26 12:06:06.510 [INF] NTFN: New confirmation subscription: txid=fa4e6a6d1dc8f96def00366ba603e967704c7b8bacf5caf0d30253b79fa72199, numconfs=1

Here are the logs of the OpenNode node when I try now to open the channel to them:

2018-11-26 20:59:46.339 [INF] FNDG: Cancelling funding reservation for node_key=02529db69fd2ebd3126fb66fafa234fc3544477a23d509fe93ed229bb0e92e4fb8, chan_id=d87ea08248474f4bd37b89c71e87df2daa589a60e9c4be3e4f7012ecf69dfc44
2018-11-26 20:59:46.339 [ERR] FNDG: unable to cancel reservation: no active reservations for peer(02529db69fd2ebd3126fb66fafa234fc3544477a23d509fe93ed229bb0e92e4fb8)

I shared the issue link with João who manages the OpenNode node, so he might be able to share any info you need from his side.

[joaodealmeida]

I'm running on "0.5.1-beta commit=v0.5.1-beta-rc2-dirty".

I forced closed the channel that was pending (due to spent outputs, that were fixed after I've updated to master and did a birthday rescan) and it disappeared from the list. However, my node is not accepting the party funding reserve for some reason.

[wpaulino]

I forced closed the channel that was pending (due to spent outputs

@cryptagoras in this case, it should be safe to just use the abandonchannel command on a debug build to remove that lingering channel.

[cryptomeow]

@wpaulino afaik we both have just the one working & active channel. The ghost channels involving our nodes are gone from pendingchannels.
I tried it on my side where, like Joao, I forced-closed the ghost channel and trying to abandon it fails:
[lncli] rpc error: code = Unknown desc = unable to find channel.

There were some people on IRC suggesting force-closing ghost channels, but maybe it apparently still retains some artifacts that cause the use of pending channels count.

Also, Joao restarted his node after all these, which didn't help either.

[joaodealmeida]

@wpaulino afaik we both have just the one working & active channel. The ghost channels involving our nodes are gone from pendingchannels.

Correct. The 'bad' channels are gone. The only channel we have is active and working correctly.

[wpaulino]

I forced closed the channel that was pending (due to spent outputs, that were fixed after I've updated to master and did a birthday rescan) and it disappeared from the list. However, my node is not accepting the party funding reserve for some reason.

Force closing an invalid channel (due to already spent outputs) is actually not the correct thing to do here, instead the AbandonChannel RPC should be used. Otherwise, we'll proceed with the force close logic, which will just broadcast the invalid commitment transaction (due to already spent outputs).

I noticed that there's a small bug that causes some channels to not show up if they never confirmed and were attempted to be force closed (like in this case).

@cryptagoras and @joaodealmeida, could you both try running the following patch locally and see if the channel shows up again within waiting_close_channels in pendingchannels?

index e36dcf84..60840b48 100644
--- a/channeldb/db.go
+++ b/channeldb/db.go
@@ -511,7 +511,11 @@ func fetchChannels(d *DB, pending, waitingClose bool) ([]*OpenChannel, error) {
 						"node_key=%x: %v", chainHash[:], k, err)
 				}
 				for _, channel := range nodeChans {
-					if channel.IsPending != pending {
+					if !waitingClose && channel.IsPending != pending {
 						continue
 					}
 

[cryptomeow]

@wpaulino indeed I see several more compared to pre-patch (+2 pending_force_closing_channels and +4 waiting_close_channels).
One of the waiting_close_channels ones being with @joaodealmeida

    {
        "channel": {
            "remote_node_pub": "03abf6f44c355dec0d5aa155bdbdd6e0c8fefe318eff402de65c6eb2e1be55dc3e",
            "channel_point": "cc7a059a5b690dad03b3d93a47f1af93a0a382a801111f618255f1825ad4134e:0",
            "capacity": "10000000",
            "local_balance": "0",
            "remote_balance": "0"
        },
        "limbo_balance": "0"
    }

[wpaulino]

Cool! I'll be putting up the patch as a PR to address the cosmetic issue.

As for the pending channels, there's no good way of cleaning them up at the moment. If you'd like to open more channels to @joaodealmeida, I'd suggest setting maxpendingchannels > 1. Note that this must be set by the party accepting the channel (not the initiator).

[cryptomeow]

@wpaulino cool, btw I just saw that with the patch the two new pending_force_closing_channels that showed up (and both had big negative blocks_til_maturity) were claimed with the patch :)

The two claimed pending_force_closing_channels right after the patch was applied:

        {
            "channel": {
                "remote_node_pub": "032a2d053e2f13f5d7103f8a4c561743eb1db201550c02c953ce2e51b8321f4e03",
                "channel_point": "3ada56362178462bec7c96ffb8ab15d51edeedb2138a63d3011ff00244ea9658:0",
                "capacity": "666000",
                "local_balance": "665638",
                "remote_balance": "0"
            },
            "closing_txid": "ef75d91390a80e626be7c562b8615b6668ea3e70363602acda23640267749ee2",
            "limbo_balance": "665638",
            "maturity_height": 540039,
            "blocks_til_maturity": -11947,
            "recovered_balance": "0",
            "pending_htlcs": [
            ] 
        },
        {
            "channel": {
                "remote_node_pub": "02fe9469e1d7da69539e365c9b2a64d277ed5589622cb314dc8b3060f3c55f79e6",
                "channel_point": "d812d5fa9910cd97a4873145e9b807609debe83b4dda019482eff09d5c514f61:0",
                "capacity": "1666999",
                "local_balance": "1664780",
                "remote_balance": "0"
            },
            "closing_txid": "e3f3547b3c9a296ad16c1091bbda7ce719e15fc3e193747db83368b0ab7f32df",
            "limbo_balance": "1664780",
            "maturity_height": 540090,
            "blocks_til_maturity": -11896,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },

[wpaulino]

@cryptagoras it looks like those channels have been successfully swept on-chain. If you restart your node with debuglevel=CNCT=debug, what do the logs show for those channels?

[cryptomeow]

@wpaulino sure. It's a busy node so I removed quite a few parts about other channels etc. but I can provide more extensive logs if you want.

When it boots:

[redacted]

and when shutting down the daemon it logs the following:

2018-12-01 00:45:48.251 [ERR] CNCT: ChannelArbitrator(4c1fe5fffae98afffcf52990d9dd6827fc980e64736b52943c63116784eed5f0:0): unable to progress resolver: quitting
---
2018-12-01 00:45:48.251 [ERR] CNCT: ChannelArbitrator(f3f7749934dc79359f45e965f09998e6e8c672a2ac20101ce96ddb807c5baf8b:1): unable to progress resolver: quitting

[joaodealmeida]

Cool! I'll be putting up the patch as a PR to address the cosmetic issue.

As for the pending channels, there's no good way of cleaning them up at the moment. If you'd like to open more channels to @joaodealmeida, I'd suggest setting maxpendingchannels > 1. Note that this must be set by the party accepting the channel (not the initiator).

I'm not sure what's the default but I've had more than 4 pending channels, so I'm sure the limit is bigger than 1. If there's a lncli command that allows to change it, let me know.

I can't apply the patch cause it's a production environment node.