openchannel failed due to mempool min fee not met leads to weird behavior

[sangaman]

Background

I tried to open a channel but got an error due to mempool min fee not met. My node's balance then went to zero, and the funding transaction was broadcast upon restarting lnd. I'm currently unable to connect to the remote node and my channel is stuck at inactive.

Your environment

• 0.4.2-beta commit=7cf5ebe2650b6798182e10be198c7ffc1f1d6e19
• Linux raspnode 4.14.34-v7+ # 1110 SMP Mon Apr 16 15:18:51 BST 2018 armv7l GNU/Linux
• bitcoind 0.16
• bitcoind is running with maxmempool set to 10 MB, a low limit, as I'm running in a limited memory environment and am not interested in holding on to unconfirmed transactions.

Steps to reproduce

tl;dr version: Attempt to open a channel with sat_per_byte set to 1 while the mempool is full.

Longer version: I attempted to open my first channel with sat_per_byte set to 1 on a mainnet node, but I got the mempool min fee not met error which I believe was passed along from bitcoind. Since I'm running with a low maxmempool setting I didn't think too much of it, although it looks like the mempool should've been near empty at the time so that's odd.

I came back a couple of hours later to try to open the channel again running the same call as before, and got an error that I didn't have any inputs available to craft the funding transaction. walletbalance and channelbalance returned zeros for both confirmed and unconfirmed balances. I tried restarting lnd and calling openchannel again and got an error that I wasn't connected to the other node (I hadn't manually connected like I did before trying to open the channel the first time). I then checked my wallet balances again and now my pending channel balance was non-zero.

I couldn't retrieve the output from all the calls unfortunately but I did grab the output below while the channel was pending.

lncli pendingchannels
{
    "total_limbo_balance": "0",
    "pending_open_channels": [
        {
            "channel": {
                "remote_node_pub": "03a9d79bcfab7feb0f24c3cd61a57f0f00de2225b6d31bce0bc4564efa3b1b5aa
f",
                "channel_point": "..."
,
                "capacity": "...",
                "local_balance": "..
                "remote_balance": "0"
            },
            "confirmation_height": 0,
            "commit_fee": "181",
            "commit_weight": "600",
            "fee_per_kw": "250"
        }
    ],
    "pending_closing_channels": [
    ],
    "pending_force_closing_channels": [
    ],
    "waiting_close_channels": [
    ]
}

lncli walletbalance
{
    "total_balance": "0",
    "confirmed_balance": "0",
    "unconfirmed_balance": "0"
}

lncli channelbalance
{
    "balance": "0",
    "pending_open_balance": "[non-zero balance equal to local_balance above]"
}

Currently, after the funding transaction has confirmed, both walletbalance and channelbalance report the expected values and listchannels shows the channel. However, I'm not able to connect to the remote node and the channel is therefore stuck as inactive. The lnd output shows a successful connection attempt yet the remote node never shows up in listpeers and the channel remains inactive.

lncli connect 03a9d79bcfab7feb0f24c3cd61a57f0f00de2225b6d31bce0bc4564efa3b1b5aaf@13.92.254.226:9735
{

}

2018-05-31 20:30:31.056 [DBG] SRVR: Connecting to 03a9d79bcfab7feb0f24c3cd61a57f0f00de2225b6d31bce0bc4564efa3b1b5aaf@13.92.254.226:9735
2018-05-31 20:30:31.143 [INF] SRVR: Established connection to: 13.92.254.226:9735
2018-05-31 20:30:31.144 [DBG] PEER: Sending Init to 13.92.254.226:9735
2018-05-31 20:30:31.174 [DBG] RPCS: Connected to peer: 03a9d79bcfab7feb0f24c3cd61a57f0f00de2225b6d31bce0bc4564efa3b1b5aaf@13.92.254.226:9735

I have not tried to reproduce yet from fresh but will update this issue if I'm able to reproduce on testnet.

Expected behaviour

If openchannel fails due to the mempool being full and the fee being too low, the funding transaction should be discarded and the available walletbalance should not change.

Actual behaviour

The input used for attempting the openchannel call disappears from lnd. Funding transaction is preserved and able to be broadcast upon restarting lnd.

[Roasbeef]

However, I'm not able to connect to the remote node and the channel is therefore stuck as inactive.

You aren't able to connect? The channel existing or not shouldn't affect the ability for your node to connect. If it's the case that a few days has passed and the funding transaction was confirmed, then the remote node will "forget" the channel. As a result, it's likely failing to send out the chan sync message we expect on start up.

[sangaman]

It hasn't been a few days - this all happened earlier today. I was able to connect earlier in the day before attempting to open the channel. I'm wondering if the remote node is fully aware that the channel exists because the opening process was interrupted. I figure the initial commitment transactions were signed, but then the broadcast of the funding transaction failed and resulted in some unexpected limbo state.

I don't know what else to try in terms of connecting, I realize it should be independent of the existence of any channels but it's not working and the remote node does appear to be online. Let me know if you have any ideas.

[Roasbeef]

Do you control the remote node? If so you can check to see why it disconnects.

[sangaman]

I don't unfortunately, it's the coinpanic.com node so I could probably ask to see if they can share what it looks from their side.

[Horndev]

I'm the owner of coinpanic.com and I see the channel open on my node, but can't connect to it.

Edit - I don't see anything in the info log.

Edit2: I upped the debug level, this is what I see:

2018-06-01 23:39:16.763 [DBG] SRVR: Connecting to 038118e0490f8d3df07b6bdc5e7034dee90d769012764d31bfeb167269866824f0@75.75.58.83:9735
2018-06-01 23:39:16.830 [DBG] SRVR: Ignoring connection, peer already scheduled
2018-06-01 23:39:16.830 [DBG] RPCS: Connected to peer: 038118e0490f8d3df07b6bdc5e7034dee90d769012764d31bfeb167269866824f0@75.75.58.83:9735

But the channel doesn't go active.

[sangaman]

Thanks a lot for taking a look at this. Do you think you could try connecting one more ? My raspi went down for a bit a little while ago, so I want to make sure that didn't interfere. I'm running from a fresh reboot now too, fwiw.

Here's my output from listchannels:

lncli listchannels
{
    "channels": [
        {
            "active": false,
            "remote_pubkey": "03a9d79bcfab7feb0f24c3cd61a57f0f00de2225b6d31bce0bc4564efa3b1b5aaf",
            "channel_point": "5805c720e546121f84f86f0b86e7d977b08e42f89e090c8a45c740bd1f6caf97:0",
            "chan_id": "0",
            "capacity": "3002000",
            "local_balance": "3001819",
            "remote_balance": "0",
            "commit_fee": "181",
            "commit_weight": "600",
            "fee_per_kw": "250",
            "unsettled_balance": "0",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "0",
            "pending_htlcs": [
            ],
            "csv_delay": 360,
            "private": false
        }
    ]
}

Good to know that the channel is recognized on the other end, problem now just seems to be the connection.

[Horndev]

Tried again. Same problem. It looks like I do connect, but the channel is not going active.

[sangaman]

Does my node show up under listpeers? I get debug output as if the connection was successful as well but it never shows up in listpeers for me.

Looking a bit through the code, it looks like this connection is "scheduled" to occur automatically, perhaps because we have a channel and we establish connections for peers with channels automatically, but it's never actually happening.

	// If we already have a valid connection that is scheduled to take
	// precedence once the prior peer has finished disconnecting, we'll
	// ignore this connection.
	if _, ok := s.scheduledPeerConnection[pubStr]; ok {
		srvrLog.Debugf("Ignoring connection, peer already scheduled")
		conn.Close()
		return
	}

Edit: Here's what I get if I try to disconnect:

lncli disconnect 03a9d79bcfab7feb0f24c3cd61a57f0f00de2225b6d31bce0bc4564efa3b1b5aaf
[lncli] rpc error: code = Unknown desc = cannot disconnect from peer(03a9d79bcfab7feb0f24c3cd61a57f0f00de2225b6d31bce0bc4564efa3b1b5aaf), all active channels with the peer need to be closed first

[sangaman]

@Horndev I'm curious, have you restarted your node at all in the past 4 days? I'm wondering if that might clear this connection issue up.

[sangaman]

Oddly, this channel is now active. I took no actions, just left my node up and running.

[sangaman]

Just FYI, I suspect that the original cause of the issue - the funding transaction seemingly disappearing from lnd when it's rejected due to a full mempool - still probably exists. It at least seems to resolve itself given some restarts and time, though. It might be worth leaving this issue open to at least keep track of it or in case others experience the same.

[chevdor]

I realize this is an ancient issue but the above did help me and I ran into the same issue.
Due to an offline peer, my node initiated a closing of the channel, soon followed by a force close. The fee was low and my bitcoin node did not bother keeping it in its mempool so no chance to resend it. After increasing my maxmempool with -maxmempool=2000 (the current mempool is around 1600 MB, we are in 2024 now :))) I could finally get the rawtx, resend it and bump its fee, which unlocked the problem for me. Thanks for documenting on the way folks !