search

ElementsProject / lightning

Core Lightning — Lightning Network implementation focusing on spec compliance and performance
Other
2.81k stars 887 forks source link

Dual-funded channel opening issues #6891

Open toneloc opened 9 months ago

toneloc commented 9 months ago

Issue and Steps to Reproduce

I am having difficulty opening dual-funded channels on v23.08.1. I am seeing spotty behavior that is difficult to pin down. At some times, the behavior appears to create a single-sided channel. Once, I was able to create a dual-funded channel successfully.

Maybe this behvior is related to : https://github.com/ElementsProject/lightning/commit/3190c26bc9003b250f466fd2d261b9fee4a4935b

I have debug logs from a specific error occurrence that I share below. With these logs, the "fundchannel" command simply hung for several minutes.

TL;DR the most relevant messages from the debug logs appears to be:

2023-11-22T16:44:06.067Z **BROKEN** ...
2023-11-22T16:44:06.069Z **BROKEN**-dualopend-chan#7: STATUS_FAIL_MASTER_IO: Error parsing 7011: ...
2023-11-22T16:44:06.069Z DEBUG   ...-dualopend-chan#7: Status closed, but not exited. Killing
2023-11-22T16:44:06.069Z INFO    ...-chan#7: Peer transient failure in DUALOPEND_OPEN_INIT: dualopend: Owning subdaemon dualopend died (61952)

Is there a version I can try to resolve this?

Here is more information:

I am trying to open a channel from LN Node 1 to LN Node 2.

I start LN Node 1 with:

lightningd --daemon --log-file=/home/ubuntu/cln.log --experimental-dual-fund --funder-policy=match --funder-policy-mod=100 --funder-min-their-funding=1000 --funder-per-channel-max=700000 --funder-fuzz-percent=0 --lease-fee-base-sat=2sat --lease-fee-basis=50 --experimental-splicing --experimental-offers --funder-lease-requests-only=false --log-level=debug

"funderupdate" on LN Node 1 returns:

{
   "summary": "match (100%)",
   "policy": "match",
   "policy_mod": 100,
   "leases_only": false,
   "min_their_funding_msat": 1000000,
   "max_their_funding_msat": 4294967295000,
   "per_channel_min_msat": 10000000,
   "per_channel_max_msat": 700000000,
   "reserve_tank_msat": 0,
   "fuzz_percent": 0,
   "fund_probability": 100,
   "lease_fee_base_msat": 2000,
   "lease_fee_basis": 50,
   "funding_weight": 666,
   "channel_fee_max_base_msat": 5000000,
   "channel_fee_max_proportional_thousandths": 100,
   "compact_lease": "029a00320064000000024c4b40"
}

I start LN Node 2 with:

lightningd --daemon --experimental-dual-fund --log-file=/home/ubuntu/cln2.log --lightning-dir=/home/ubuntu/.second-lightning --announce-addr=0.0.0.0:19736 --funder-policy=match --funder-policy-mod=100 --funder-min-their-funding=1000 --funder-per-channel-max=700000 --funder-fuzz-percent=0 --lease-fee-base-sat=2sat --lease-fee-basis=50 --experimental-splicing --experimental-offers --log-level=debug

"funderupdate" on LN Node 2 returns:

{
   "summary": "match (100%)",
   "policy": "match",
   "policy_mod": 100,
   "leases_only": false,
   "min_their_funding_msat": 1000000,
   "max_their_funding_msat": 4294967295000,
   "per_channel_min_msat": 10000000,
   "per_channel_max_msat": 700000000,
   "reserve_tank_msat": 0,
   "fuzz_percent": 0,
   "fund_probability": 100,
   "lease_fee_base_msat": 2000,
   "lease_fee_basis": 50,
   "funding_weight": 666,
   "channel_fee_max_base_msat": 5000000,
   "channel_fee_max_proportional_thousandths": 100,
   "compact_lease": "029a00320064000000024c4b40"
}

I then run lightning-cli fundchannel CHANNEL_ID 0.002...btc

Relevant (abridged) debug logs from LN Node 1:

2023-11-22T16:44:05.709Z DEBUG   plugin-spenderp: mfc 34: multiconnect.
2023-11-22T16:44:05.709Z DEBUG   plugin-spenderp: mfc 34, dest 0: connect ....
2023-11-22T16:44:05.709Z DEBUG   lightningd: Already connected via 
2023-11-22T16:44:05.709Z DEBUG   plugin-spenderp: mfc 34, dest 0: connect done.
2023-11-22T16:44:05.709Z DEBUG   plugin-spenderp: mfc 34: multiconnect done.
2023-11-22T16:44:05.709Z DEBUG   plugin-spenderp: mfc 34: 'parsefeerate' done
2023-11-22T16:44:05.709Z DEBUG   plugin-spenderp: mfc 34: fundpsbt.
2023-11-22T16:44:05.716Z DEBUG   hsmd: Client: Received message 28 from client
2023-11-22T16:44:05.718Z DEBUG   plugin-spenderp: mfc 34: fundpsbt done.
2023-11-22T16:44:05.718Z DEBUG   plugin-spenderp: mfc 34: fundchannel_start parallel with PSBT cHNidP8B .....
2023-11-22T16:44:05.719Z DEBUG   plugin-spenderp: mfc 34, dest 0: openchannel_init ....
2023-11-22T16:44:05.725Z DEBUG   ...-dualopend-chan#11: pid 967036, msgfd 71
2023-11-22T16:44:05.725Z DEBUG   hsmd: Client: Received message 30 from client
2023-11-22T16:44:05.725Z DEBUG   hsmd: Client: Received message 10 from client
2023-11-22T16:44:05.725Z DEBUG   hsmd: new_client: 11
2023-11-22T16:44:05.726Z DEBUG   ...-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2023-11-22T16:44:05.726Z DEBUG   hsmd: Client: Received message 18 from client
2023-11-22T16:44:05.726Z DEBUG   ..-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2023-11-22T16:44:05.726Z DEBUG   hsmd: Client: Received message 18 from client
2023-11-22T16:44:05.727Z DEBUG   ..-dualopend-chan#11: peer_out WIRE_OPEN_CHANNEL2
2023-11-22T16:44:05.727Z DEBUG   ..-dualopend-chan#11: billboard: channel open: offered, waiting for accept_channel2
2023-11-22T16:44:05.738Z DEBUG   ..-dualopend-chan#11: peer_in WIRE_ACCEPT_CHANNEL2
2023-11-22T16:44:05.738Z DEBUG   ..-dualopend-chan#11: peer_out WIRE_TX_ADD_INPUT
2023-11-22T16:44:05.740Z DEBUG   ..-dualopend-chan#11: peer_in WIRE_TX_ADD_INPUT
2023-11-22T16:44:05.740Z DEBUG   ..-dualopend-chan#11: peer_out WIRE_TX_ADD_OUTPUT
2023-11-22T16:44:05.747Z DEBUG   ..-dualopend-chan#11: peer_in WIRE_TX_COMPLETE
2023-11-22T16:44:05.747Z DEBUG   ..-dualopend-chan#11: peer_out WIRE_TX_ADD_OUTPUT
2023-11-22T16:44:05.754Z DEBUG   ...-dualopend-chan#11: peer_in WIRE_TX_COMPLETE
2023-11-22T16:44:05.759Z DEBUG   plugin-spenderp: mfc 34, dest 0: openchannel_init .. done.
2023-11-22T16:44:05.759Z DEBUG   plugin-spenderp: mfc 34: parallel channel starts done.
2023-11-22T16:44:05.759Z DEBUG   plugin-spenderp: mfc 34: Creating funding tx.
2023-11-22T16:44:05.760Z DEBUG   plugin-spenderp: mfc 34: parallel `openchannel_update`.
2023-11-22T16:44:05.760Z DEBUG   plugin-spenderp: mfc 34, dest 0: `openchannel_update`
2023-11-22T16:44:05.763Z DEBUG   ..-dualopend-chan#11: peer_out WIRE_TX_COMPLETE
2023-11-22T16:44:05.763Z DEBUG   ..-hsmd: Got WIRE_HSMD_READY_CHANNEL
2023-11-22T16:44:05.763Z DEBUG   hsmd: Client: Received message 31 from client
2023-11-22T16:44:05.774Z DEBUG   ..-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2023-11-22T16:44:05.774Z DEBUG   hsmd: Client: Received message 19 from client
2023-11-22T16:44:05.774Z DEBUG   ...-dualopend-chan#11: signature ... on tx ... using key ...
2023-11-22T16:44:05.774Z DEBUG   ...-dualopend-chan#11: peer_out WIRE_COMMITMENT_SIGNED
2023-11-22T16:44:05.775Z DEBUG   ...-dualopend-chan#11: billboard: channel open: commitment sent, waiting for reply

Relevant (abridged) debug logs from LN Node 2:

2023-11-22T16:44:05.727Z DEBUG   ...-connectd: Activating for message WIRE_OPEN_CHANNEL2
2023-11-22T16:44:05.730Z DEBUG   ...-dualopend-chan#7: pid 967037, msgfd 70
2023-11-22T16:44:05.730Z DEBUG   hsmd: Client: Received message 30 from client
2023-11-22T16:44:05.730Z DEBUG   hsmd: Client: Received message 10 from client
2023-11-22T16:44:05.730Z DEBUG   hsmd: new_client: 7
2023-11-22T16:44:05.731Z DEBUG   ...-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2023-11-22T16:44:05.731Z DEBUG   hsmd: Client: Received message 18 from client
2023-11-22T16:44:05.731Z DEBUG   ...-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2023-11-22T16:44:05.731Z DEBUG   hsmd: Client: Received message 18 from client
2023-11-22T16:44:05.731Z DEBUG   ....-dualopend-chan#7: peer_in WIRE_OPEN_CHANNEL2
2023-11-22T16:44:05.731Z DEBUG   lightningd: Calling openchannel2 hook of plugin funder
2023-11-22T16:44:05.732Z DEBUG   plugin-funder: Policy match (100%) returned funding amount of ...sat. 
2023-11-22T16:44:05.732Z DEBUG   plugin-funder: Funding channel ... with .. (their input ..)
2023-11-22T16:44:05.737Z DEBUG   lightningd: Plugin funder returned from openchannel2 hook call
2023-11-22T16:44:05.738Z DEBUG   ...-dualopend-chan#7: peer_out WIRE_ACCEPT_CHANNEL2
2023-11-22T16:44:05.738Z DEBUG   ...-dualopend-chan#7: billboard: channel open: accept sent, waiting for reply
2023-11-22T16:44:05.739Z DEBUG   ...-dualopend-chan#7: peer_in WIRE_TX_ADD_INPUT
2023-11-22T16:44:05.740Z DEBUG   ..-dualopend-chan#7: peer_out WIRE_TX_ADD_INPUT
2023-11-22T16:44:05.740Z DEBUG   ...-dualopend-chan#7: peer_in WIRE_TX_ADD_OUTPUT
2023-11-22T16:44:05.741Z DEBUG   lightningd: Calling openchannel2_changed hook of plugin funder
2023-11-22T16:44:05.744Z DEBUG   plugin-funder: openchannel_changed PSBT is cHNidP
2023-11-22T16:44:05.745Z DEBUG   lightningd: Plugin funder returned from openchannel2_changed hook call
2023-11-22T16:44:05.747Z DEBUG   ...-dualopend-chan#7: peer_out WIRE_TX_COMPLETE
2023-11-22T16:44:05.747Z DEBUG   ...-dualopend-chan#7: peer_in WIRE_TX_ADD_OUTPUT
2023-11-22T16:44:05.748Z DEBUG   lightningd: Calling openchannel2_changed hook of plugin funder
2023-11-22T16:44:05.750Z DEBUG   plugin-funder: openchannel_changed PSBT is cHNidP8...
2023-11-22T16:44:05.752Z DEBUG   lightningd: Plugin funder returned from openchannel2_changed hook call
2023-11-22T16:44:05.753Z DEBUG   ...-dualopend-chan#7: peer_out WIRE_TX_COMPLETE
2023-11-22T16:44:05.763Z DEBUG   ...-dualopend-chan#7: peer_in WIRE_TX_COMPLETE
2023-11-22T16:44:06.025Z DEBUG   ...-dualopend-chan#7: peer_in WIRE_COMMITMENT_SIGNED
2023-11-22T16:44:06.025Z DEBUG   ...-hsmd: Got WIRE_HSMD_READY_CHANNEL
2023-11-22T16:44:06.025Z DEBUG   hsmd: Client: Received message 31 from client
2023-11-22T16:44:06.026Z DEBUG   ...-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2023-11-22T16:44:06.026Z DEBUG   hsmd: Client: Received message 35 from client
2023-11-22T16:44:06.027Z DEBUG   ...-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2023-11-22T16:44:06.027Z DEBUG   hsmd: Client: Received message 19 from client
2023-11-22T16:44:06.031Z DEBUG   lightningd: Calling openchannel2_sign hook of plugin funder
2023-11-22T16:44:06.036Z DEBUG   hsmd: Client: Received message 28 from client
2023-11-22T16:44:06.038Z DEBUG   plugin-funder: openchannel_sign PSBT is cHN
2023-11-22T16:44:06.039Z DEBUG   plugin-funder: calling `signpsbt` for channel ... for 1 input
2023-11-22T16:44:06.060Z DEBUG   hsmd: Client: Received message 7 from client
2023-11-22T16:44:06.061Z DEBUG   plugin-funder: `signpsbt` done for channel ...
2023-11-22T16:44:06.066Z DEBUG   plugin-funder: Saved utxos for channel ([\"funder/...\"]) to datastore
2023-11-22T16:44:06.066Z DEBUG   lightningd: Plugin funder returned from openchannel2_sign hook call
2023-11-22T16:44:06.067Z **BROKEN** ....
2023-11-22T16:44:06.069Z **BROKEN**-dualopend-chan#7: STATUS_FAIL_MASTER_IO: Error parsing 7011: ...
2023-11-22T16:44:06.069Z DEBUG   ...-dualopend-chan#7: Status closed, but not exited. Killing
2023-11-22T16:44:06.069Z INFO    ...-chan#7: Peer transient failure in DUALOPEND_OPEN_INIT: dualopend: Owning subdaemon dualopend died (61952)

Please let me know what further information I can provide. Thank you.

niftynei commented 9 months ago

Yep that's definitely a bug, and a weird one at that.

Not exactly sure what's happening but lightningd is sending a message to another internal daemon (called dualopend) with the signatures it needs to finish the open. The message it's sending isn't in the format that dualopend is expecting, so it falls over.

Can you send me or post the info from the logline that says STATUS_FAIL_MASTER_IO: Error parsing 7011: .... The extra info it prints is the actual message that it failed to parse. Looking at that should help clue me into what went wrong.

Thanks for the report + your help tracking this down!

niftynei commented 9 months ago

Oh actually just looking at the code I found the problem. Sometimes the message we get back from lightningd is a failure message, instead of a success message.

We try to parse it as a success message, and fall over.

Would still love to see what the failure message is, but I think I can make a patch for this no problem.

Can you give me any info about the setup you've got that's causing this error? It'd be nice to be able to reproduce it before fixing it.

niftynei commented 9 months ago

Oh one more thing. What does this log line say?

2023-11-22T16:44:06.067Z **BROKEN** ....
toneloc commented 9 months ago

The line at "STATUS_FAIL_MASTER_IO: Error parsing 7011:" is:

-chan#7: STATUS_FAIL_MASTER_IO: Error parsing 7011: 1b5b50656572206572726f7220776974682050534254207369676e6174757265732e00

The line "2023-11-22T16:44:06.067Z BROKEN ...." says:

2023-11-22T16:44:06.067Z **BROKEN** PEER_ID-chan#7: Plugin must return a 'psbt' with signatures for their inputs

toneloc commented 9 months ago

Oh, and I am running this version of Ubuntu below, and I was trying to open this channel above on mainnet. 

LSB Version:    core-11.1.0ubuntu4-noarch:printing-11.1.0ubuntu4-noarch:security-11.1.0ubuntu4-noarch
Distributor ID: Ubuntu
Description:    Ubuntu 22.04.3 LTS
Release:    22.04
Codename:   jammy

Let me know anything else, and thanks for your help!

niftynei commented 9 months ago

Ah ok! Are you using the default funder plugin for this? I can fix the underlying broken patch but you're still going to have an issue with the "must return psbt" requirement that's currently failing.

On Wed, Nov 22, 2023 at 3:48 PM toneloc @.***> wrote:

Oh, and I am running this version of Ubuntu below, and I was trying to open this channel above on mainnet.

LSB Version: core-11.1.0ubuntu4-noarch:printing-11.1.0ubuntu4-noarch:security-11.1.0ubuntu4-noarch Distributor ID: Ubuntu Description: Ubuntu 22.04.3 LTS Release: 22.04 Codename: jammy

Let me know anything else, and thanks for your help!

— Reply to this email directly, view it on GitHub https://github.com/ElementsProject/lightning/issues/6891#issuecomment-1823552502, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAIMAKOLWI7VH5WAASQ3B2LYFZXJZAVCNFSM6AAAAAA7WSQD7SVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQMRTGU2TENJQGI . You are receiving this because you were assigned.Message ID: @.***>

toneloc commented 9 months ago

Are you using the default funder plugin for this?

I think so? :) This process is running: /usr/libexec/c-lightning/plugins/funder

I can fix the underlying broken patch but you're still going to have an issue with the "must return psbt" requirement that's currently failing.

I see, well maybe I can use a different version to get around this bug. I had dual-funding working on a much older version of CLN.

And the set-up that I documented in this issue did succeed in creating a dual-funded channel at least once.

What I want to do is open a balanced channel, and I don't really care about other lease-related settings. Any other suggestions, please let me know. Cheers.

niftynei commented 9 months ago

when you run listfunds on L2 what do you get?

toneloc commented 9 months ago

when you run listfunds on L2 what do you get?

Under outputs, I see two available outputs. These outputs were both "reserved" yesterday; today they are available.

I see one channel that says "DUALOPEND_OPEN_INIT" ... this is indeed the channel that I had documented above.

Should I try to close this "DUALOPEND_OPEN_INIT" channel?

L1 listfunds does not show this channel

toneloc commented 9 months ago

For what it's worth, I was able to open dual-funded channels, locally, with these same settings with no problems on version v23.05.2.

toneloc commented 9 months ago

when you run listfunds on L2 what do you get?

Under outputs, I see two available outputs. These outputs were both "reserved" yesterday; today they are available.

I see one channel that says "DUALOPEND_OPEN_INIT" ... this is indeed the channel that I had documented above.

Should I try to close this "DUALOPEND_OPEN_INIT" channel?

L1 listfunds does not show this channel

FYI, this status changed to "AWAITING_UNILATERAL" today ... when I tried to close this channel, CLN reported "Channel ID not found" ... well that makes sense.

I am going to withdraw all funds from these CLN instances, downgrade to 23.05.02, and try to run my dual-funds on that version, as it sounds like an upgrade will not solve these present issues.