lightning icon indicating copy to clipboard operation
lightning copied to clipboard

Dual-funded channel opens successfully but peer then seems near-permanently offline/log shows "update_fee 253 unaffordable"

Open CeruleanRat opened this issue 2 years ago • 3 comments

I set up a new node and tried to get some inbound liquidity using dual funding, but the channels I open appear to be useless and the peers show as offline almost constantly, although I don't think they really are. "lightning-cli invoice" nearly always gives a warning "Insufficient incoming capacity, once offline peers were excluded" and paying the generated invoice always fails.

I am running v0.10.2 on Ubuntu 20.04.4 on x86-64.

getinfo shows:

{
   "id": "xxxx",
   "alias": "xxxx",
   "color": "xxxx",
   "num_peers": 2,
   "num_pending_channels": 0,
   "num_active_channels": 2,
   "num_inactive_channels": 0,
   "address": [
      {
         "type": "torv3",
         "address": "xxxx.onion",
         "port": 9735
      }
   ],
   "binding": [
      {
         "type": "ipv4",
         "address": "127.0.0.1",
         "port": 9736
      }
   ],
   "version": "v0.10.2",
   "blockheight": 733379,
   "network": "bitcoin",
   "msatoshi_fees_collected": 0,
   "fees_collected_msat": "0msat",
   "lightning-dir": "/home/lightning/.lightning/bitcoin"
}

My config file is:

proxy=127.0.0.1:9050
bind-addr=127.0.0.1:9736
addr=statictor:127.0.0.1:9051
always-use-proxy=true
bitcoin-rpcuser=xxxx
bitcoin-rpcpassword=xxxx
log-file=xxxx/lightning.log
experimental-dual-fund
plugin=xxxx/summary.py

I opened a new channel by executing:

lightning-cli connect 038fe1bd966b5cb0545963490c631eaa1924e2c4c0ea4e7dcb5d4582a1e7f2f1a5 xtdo5qvvfwcjaruj6z4acdcw4azagn6tdgac4ajnekjdn4ghr6qw2nqd.onion 9735
lightning-cli -k fundchannel announce=false  id=038fe1bd966b5cb0545963490c631eaa1924e2c4c0ea4e7dcb5d4582a1e7f2f1a5 amount=10000sat request_amt=3000000sat compact_lease=029a00140000000001f4

This succeeded, but the peer almost always shows as offline when I use the summary plugin. Once in a while the summary plugin shows the peer is not offline, but this almost always reverts back to offline if I recheck the status straight after.

I thought this was a problem with this specific peer at first, but I have subsequently tried this again with a different peer and had the same behaviour - the connect succeeds and then the node appears to be nearly-permanently offline straight afterwards. Maybe I'm just selecting bad peers of course.

The log shows a lot of entries like this:

INFO    xxxx-chan#3: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: warning channel yyyy: update_fee 253 unaffordable
INFO    xxxx-chan#3: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: warning channel yyyy: update_fee 253 unaffordable
INFO    xxxx-chan#3: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: warning channel yyyy: update_fee 253 unaffordable
INFO    xxxx-chan#3: Peer connection lost
INFO    xxxx-chan#3: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)

The node has on-chain funds (as shown under "utxo_amount" in the summary output) of over 100000 sats.

Am I doing something wrong or is this just bad luck with my peers?

The above is all factual, the following is just conjecture on my part in case it's helpful: I've been doing my best to figure this out and I'm suspecting that I've accidentally put too little liquidity in the channel on my side and my node can't therefore promise the peer that it will be able to pay for a cooperative close even at the minimum feerate of 253. If this is the case, it would be nice if the channel had failed to open rather than opening in a useless state.

If you need any more information please let me know. Thanks!

CeruleanRat avatar Apr 24 '22 20:04 CeruleanRat

Hey, sorry to hear you're having troubles with channels that you leased.

This isn't a problem I've run into before, but looking at the amount you committed to the channel, I have a guess about what's going on.

It looks like you committed 10k sats to the channel. Since you opened the channel, your node must cover all of the fees for the closing transaction. This log line about the update_fee 253 unaffordable is an indication to me that the amount of funds the opener has on their side of the channel (that's probably your node) isn't enough to cover the commitment transaction, which is resulting in temporary errors etc and general instability.

INFO    xxxx-chan#3: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: warning channel yyyy: update_fee 253 unaffordable

This might be difficult to do w/ an unstable channel, but if it's possible for you to push/rebalance some of the peer's inbound capacity to your side, that should resolve these issues you're seeing.

In the future, you might try committing more of your own capital at the start of the open, as the opener's balance limits the number of HTLCs that can reasonably be in-flight at any given time.

The reason this impacts dual-funded channel opens (and not other "bought channel" situations) is that dual-funded channels are the first time that the non-opener can commit funds to a channel open -- all other "bought channels" the side committing the capital initiates the open (and since the funds are all on their side at start, there's no problem with fees)

niftynei avatar Apr 29 '22 18:04 niftynei

Thanks for getting back to me!

I was never able to push any funds into that channel and it eventually got closed automatically. That specific peer seemed to stop offering dual-funding support, but I have subsequently been able to open another dual-funded channel with another peer with more capital on my side to start with and it worked fine.

It would be nice if the channel had refused to open when I didn't put enough liquidity on my side but I appreciate this may not be something that can be automatically detected. At least I know to avoid doing this in the future, so thanks again.

CeruleanRat avatar May 06 '22 02:05 CeruleanRat

Just in case it's helpful... I got bitten by this again (opened a larger channel than I was used to and forgot to increase the amount I put into the channel, I think). As I was unable to use the channel I initiated a co-operative close, and for a few days now it seems to be stuck. The log shows lots of "update_fee 253 unaffordable" warnings:

2022-06-28T12:53:49.099Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable
2022-06-28T12:54:52.432Z INFO    xxx-channeld-chan#1: Peer connection lost
2022-06-28T12:54:52.433Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld: Owning subdaemon channeld died (62208)
2022-06-28T12:54:56.800Z INFO    xxx-channeld-chan#1: Peer connection lost
2022-06-28T12:54:56.800Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld: Owning subdaemon channeld died (62208)
2022-06-28T12:55:00.654Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable
2022-06-28T12:56:15.195Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable
2022-06-28T12:57:20.821Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable
2022-06-28T12:58:30.857Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable
2022-06-28T12:59:40.680Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable
2022-06-28T13:00:48.358Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable
2022-06-28T13:02:06.226Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable
2022-06-28T13:03:13.320Z INFO    xxx-chan#1: Peer transient failure in CHANNELD_SHUTTING_DOWN: channeld WARNING: warning channel yyy: update_fee 253 unaffordable

Based on past experience this will resolve itself eventually (in the form of a unilateral close? just guessing as I don't remember) but I thought it might be useful to add this to this issue.

CeruleanRat avatar Jun 28 '22 17:06 CeruleanRat

I just ran into this issue as well, "version": "v0.12.1".

somebody tried to buy from me, in the log it showed something broken, but somehow it went thru, and when we try to connect, it disconnects with "channeld WARNING: update_fee 253 unaffordable":

2022xx23:01:21.957Z INFO    03xxx-chan#22695: State changed from DUALOPEND_OPEN_INIT to DUALOPEND_AWAITING_LOCKIN
2022xx23:41:56.006Z INFO    03xxx-chan#22695: State changed from DUALOPEND_AWAITING_LOCKIN to CHANNELD_NORMAL
2022xx23:41:56.625Z **BROKEN** 03xxx-channeld-chan#22695: FATAL SIGNAL 6 (version v0.12.1)
2022xx23:41:56.626Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: common/daemon.c:38 (send_backtrace) 0x55a1a7730821
2022xx23:41:56.626Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: common/daemon.c:46 (crashdump) 0x55a1a7730870
2022xx23:41:56.626Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f183e8df
2022xx23:41:56.627Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f188e36c
2022xx23:41:56.627Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f183e837
2022xx23:41:56.628Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f1828534
2022xx23:41:56.628Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f182845b
2022xx23:41:56.628Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f1837365
2022xx23:41:56.629Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: channeld/channeld.c:1620 (handle_peer_commit_sig) 0x55a1a771a887
2022xx23:41:56.629Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: channeld/channeld.c:2249 (peer_in) 0x55a1a771c7a9
2022xx23:41:56.629Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: channeld/channeld.c:4101 (main) 0x55a1a7720bca
2022xx23:41:56.630Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f182928f
2022xx23:41:56.630Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f1829349
2022xx23:41:56.630Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: ../sysdeps/x86_64/start.S:115 ((null)) 0x55a1a77168e4
2022xx23:41:56.631Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0xffffffffffffffff
2022xx23:41:56.631Z **BROKEN** 03xxx-channeld-chan#22695: FATAL SIGNAL (version v0.12.1)
2022xx23:41:56.631Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: common/daemon.c:38 (send_backtrace) 0x55a1a7730821
2022xx23:41:56.632Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: common/status.c:221 (status_failed) 0x55a1a7744100
2022xx23:41:56.632Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: common/subdaemon.c:18 (status_backtrace_exit) 0x55a1a774445d
2022xx23:41:56.632Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: common/daemon.c:49 (crashdump) 0x55a1a7730879
2022xx23:41:56.633Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f183e8df
2022xx23:41:56.633Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f188e36c
2022xx23:41:56.633Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f183e837
2022xx23:41:56.634Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f1828534
2022xx23:41:56.634Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f182845b
2022xx23:41:56.634Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f1837365
2022xx23:41:56.635Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: channeld/channeld.c:1620 (handle_peer_commit_sig) 0x55a1a771a887
2022xx23:41:56.635Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: channeld/channeld.c:2249 (peer_in) 0x55a1a771c7a9
2022xx23:41:56.636Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: channeld/channeld.c:4101 (main) 0x55a1a7720bca
2022xx23:41:56.636Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f182928f
2022xx23:41:56.636Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0x7fb3f1829349
2022xx23:41:56.637Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: ../sysdeps/x86_64/start.S:115 ((null)) 0x55a1a77168e4
2022xx23:41:56.637Z **BROKEN** 03xxx-channeld-chan#22695: backtrace: (null):0 ((null)) 0xffffffffffffffff
2022xx23:41:56.637Z **BROKEN** 03xxx-channeld-chan#22695: STATUS_FAIL_INTERNAL_ERROR: FATAL SIGNAL
2022xx23:41:56.637Z INFO    03xxx-chan#22695: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (61952)
2022xx23:54:23.174Z INFO    03xxx-chan#22695: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022xx23:54:29.000Z INFO    03xxx-chan#22695: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: update_fee 253 unaffordable
2022xx23:54:35.036Z **BROKEN** 03xxx-connectd: Peer did not close, forcing close
2022xx23:55:22.210Z INFO    03xxx-chan#22695: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022xx23:55:25.378Z INFO    03xxx-chan#22695: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: update_fee 253 unaffordable
2022xx23:55:34.001Z INFO    03xxx-chan#22695: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022xx23:55:36.906Z INFO    03xxx-chan#22695: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: update_fee 253 unaffordable
2022xx23:55:48.404Z INFO    03xxx-chan#22695: Peer transient failure in CHANNELD_NORMAL: Disconnected

listpeers shows:

{
   "peers": [
      {
         "id": "03x",
         "connected": false,
         "channels": [
            {
               "state": "CHANNELD_NORMAL",
               "scratch_txid": "yyyyy",
               "last_tx_fee_msat": "284000msat",
               "feerate": {
                  "perkw": 253,
                  "perkb": 1012
               },
               "short_channel_id": "76x2x0",
               "direction": 0,
               "channel_id": "zzzz",
               "funding_txid": "lllll",
               "funding_outnum": 0,
               "close_to_addr": "bc1asdf",
               "close_to": "0asdfasdf",
               "private": false,
               "opener": "remote",
               "alias": {
                  "local": "1x1x5"
               },
               "features": [
                  "option_static_remotekey",
                  "option_anchor_outputs"
               ],
               "funding": {
                  "local_msat": "10015668000msat",
                  "remote_msat": "20000000msat",
                  "pushed_msat": "15668000msat",
                  "remote_funds_msat": "35668000msat",
                  "local_funds_msat": "10000000000msat",
                  "fee_rcvd_msat": "15668000msat"
               },
               "msatoshi_to_us": 10015668000,
               "to_us_msat": "10015668000msat",
               "msatoshi_to_us_min": 10015668000,
               "min_to_us_msat": "10015668000msat",
               "msatoshi_to_us_max": 10015668000,
               "max_to_us_msat": "10015668000msat",
               "msatoshi_total": 10035668000,
               "total_msat": "10035668000msat",
               "fee_base_msat": "0msat",
               "fee_proportional_millionths": 3000,
               "dust_limit_satoshis": 546,
               "dust_limit_msat": "546000msat",
               "max_htlc_value_in_flight_msat": 18446744073709551615,
               "max_total_htlc_in_msat": "18446744073709551615msat",
               "their_channel_reserve_satoshis": 100356,
               "their_reserve_msat": "100356000msat",
               "our_channel_reserve_satoshis": 100356,
               "our_reserve_msat": "100356000msat",
               "spendable_msatoshi": 4294967295,
               "spendable_msat": "4294967295msat",
               "receivable_msatoshi": 0,
               "receivable_msat": "0msat",
               "htlc_minimum_msat": 0,
               "minimum_htlc_in_msat": "0msat",
               "minimum_htlc_out_msat": "0msat",
               "maximum_htlc_out_msat": "9935312000msat",
               "their_to_self_delay": 144,
               "our_to_self_delay": 144,
               "max_accepted_htlcs": 30,
               "state_changes": [
                  {
                     "timestamp": "2022-xxx",
                     "old_state": "DUALOPEND_OPEN_INIT",
                     "new_state": "DUALOPEND_AWAITING_LOCKIN",
                     "cause": "remote",
                     "message": "Sigs exchanged, waiting for lock-in"
                  },
                  {
                     "timestamp": "2022-yyy",
                     "old_state": "DUALOPEND_AWAITING_LOCKIN",
                     "new_state": "CHANNELD_NORMAL",
                     "cause": "remote",
                     "message": "Lockin complete"
                  }
               ],
               "status": [
                  "CHANNELD_NORMAL:update_fee 253 unaffordable",
                  "CHANNELD_NORMAL:Funding transaction locked. Waiting for their announcement signatures."
               ],
               "in_payments_offered": 0,
               "in_msatoshi_offered": 0,
               "in_offered_msat": "0msat",
               "in_payments_fulfilled": 0,
               "in_msatoshi_fulfilled": 0,
               "in_fulfilled_msat": "0msat",
               "out_payments_offered": 0,
               "out_msatoshi_offered": 0,
               "out_offered_msat": "0msat",
               "out_payments_fulfilled": 0,
               "out_msatoshi_fulfilled": 0,
               "out_fulfilled_msat": "0msat",
               "htlcs": []
            }
         ]
      }
   ]
}

Then I tried to close but it's saying:

"message": "Peer leased this channel from us, we shouldn't close until lease has expired (lease expires block 766799, current block 762792)"

Great, now I have 10M locked up. Can this be used as an attack ? Who paid for the funding tx fee ?

btweenthebars avatar Nov 12 '22 01:11 btweenthebars

Can this be used as an attack ? Who paid for the funding tx fee ?

This is happening because the peer didn't put enough balance on their side at start. They need to fund the channel with enough sats to cover the fees for the commitment transaction but failed to do so (that error message means their balance can't afford the commitment tx at the lowest possible feerate.) This is a bit of a UX bug in the current API for liquidity buys, and I should def add a warning/fix it so that buyer's don't under cut themselves. The buyer is really the one that loses out here as they can't make use of the inbound liquidity they just paid for, as the channel is effectively inoperable.

Good news for you is that while noisy the rest of your node should be unaffected and your funds are safe. The 10m sats is locked up/inaccessible until the lease expires, but you've been compensated for that lockup. You just wont get access to the fees you've been paid by the opening peer until the lease expires and you can close the channel.

Note that they paid both to open the channel as well as covered some of your on-chain costs and a fee for the lock-up of your capital. While it sucks that you won't be able to earn routing fees from this channel, as far as your node is concerned you've been compensated for the lockup of the funds for the duration of the lease (and you'll be able to close it as soon as the lease expires).

Alternatively, they can close the channel.

niftynei avatar Nov 14 '22 16:11 niftynei

Hm though it looks like they have 35,668 sats on their side which should be enough to cover a basic close, though maybe the reserve requirement is interfering. Plus this shouldn't be giving you a crash backlog.

I'll look into it, thanks for the report.

niftynei avatar Nov 14 '22 16:11 niftynei

shouldn't the seller side also reject a buy request if it's going to cause trouble ? As when the UX is fixed but buyer might still be on a CLN old version

btweenthebars avatar Nov 16 '22 00:11 btweenthebars