Skip to content

Currently waiting on previous splice command to finish #6656

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
Sjors opened this issue Sep 8, 2023 · 8 comments · Fixed by #6677
Closed

Currently waiting on previous splice command to finish #6656

Sjors opened this issue Sep 8, 2023 · 8 comments · Fixed by #6677
Assignees
@ddustin

Comments

@Sjors
Copy link
Contributor

Sjors commented Sep 8, 2023 •
edited
Loading

Using CLN v23.08.

I opened a channel with another CLN v23.08 peer, using funds from another wallet (fundchannel_start, fundchannel_complete). waited for it to lock in and then tried to splice out 1 sat.

lightning-cli splice_init -k channel_id=... relative_amount=-1

This returned a (v2) psbt. I then passed that into splice_update. This command didn't return immedidately. After a minute or so I interrupted it.

However subsequent calls to either splice_update and splice_signed (with the signed version) result in Currently waiting on previous splice command to finish (code 355, SPLICE_BUSY_ERROR).

How long should I wait? Is there an RPC that tells me what's going on? Should I reboot? :-)

Happy to provide more details, but not sure how to do that without doxxing a bit too much.
@Sjors
Copy link
Contributor Author

Sjors commented Sep 8, 2023

Some splice messages:

2023-09-08T18:27:09.652Z DEBUG   xxxxxx-channeld-chan#13916: peer_out WIRE_SPLICE
2023-09-08T18:27:09.740Z DEBUG   xxxxxx-channeld-chan#13916: peer_in WIRE_SPLICE_ACK
2023-09-08T18:27:09.740Z DEBUG   xxxxxx-channeld-chan#13916: splice_initiator peer->stfu_wait_single_msg: 0
2023-09-08T18:27:09.741Z DEBUG   xxxxxx-channeld-chan#13916: just added funding w/ outpoint index set to 0, value in psbt input 1 is: 0, and value in psbt input 2 is: 0
2023-09-08T18:27:09.741Z DEBUG   xxxxxx-channeld-chan#13916: Sending master 7208
2023-09-08T18:27:09.741Z DEBUG   xxxxxx-channeld-chan#13916: ... , awaiting 7209
2023-09-08T18:27:09.741Z DEBUG   xxxxxx-channeld-chan#13916: Got it!
2023-09-08T18:27:09.741Z DEBUG   xxxxxx-channeld-chan#13916: peer_out WIRE_TX_ADD_INPUT
2023-09-08T18:27:09.831Z DEBUG   xxxxxx-channeld-chan#13916: peer_in WIRE_TX_COMPLETE
2023-09-08T18:27:09.831Z DEBUG   xxxxxx-channeld-chan#13916: peer_out WIRE_TX_ADD_OUTPUT
2023-09-08T18:27:09.917Z DEBUG   xxxxxx-channeld-chan#13916: peer_in WIRE_TX_COMPLETE

@Sjors
Copy link
Contributor Author

Sjors commented Sep 8, 2023

After restarting the node, I also tried splicing out more than the dust limit, with the same peer:

2023-09-08T19:20:31.897Z DEBUG   lightningd: splice_update input PSBT version 2
2023-09-08T19:20:31.898Z DEBUG   xxxxxx-channeld-chan#13916: splice_update start with, current psbt version: 2, desired: 2.
2023-09-08T19:20:31.898Z DEBUG   xxxxxx-channeld-chan#13916: peer_out WIRE_TX_COMPLETE
2023-09-08T19:20:31.898Z DEBUG   xxxxxx-channeld-chan#13916: peer_out WIRE_WARNING
2023-09-08T19:20:31.898Z DEBUG   xxxxxx-channeld-chan#13916: billboard perm: Unable to sub opener funding from out amnt.
2023-09-08T19:20:31.898Z DEBUG   connectd: drain_peer
2023-09-08T19:20:31.898Z DEBUG   connectd: drain_peer draining subd!
2023-09-08T19:20:31.899Z INFO    xxxxxx-chan#13916: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: Unable to sub opener funding from out amnt.

@Sjors
Copy link
Contributor Author

Sjors commented Sep 8, 2023

I also tried splicing in. Because fund_psbt doesn't have coin selection, I had Bitcoin Core make the PSBT, pointing to one of my CLN wallet UTXOs with about 1000 sats:

bitcoin-cli createpsbt '[{"txid": "....", "vout": 0}]' '[]'

(using the v2 support PR bitcoin/bitcoin#21283).

And then: lightning-cli splice_init ... 600 the_psbt

This ended up stuck. From the log:

2023-09-08T19:31:25.572Z DEBUG   lightningd: splice_init input PSBT version 2
2023-09-08T19:31:25.572Z DEBUG   xxxxxx-channeld-chan#13916: Getting handle_splice_init psbt version 2
2023-09-08T19:31:25.572Z DEBUG   xxxxxx-channeld-chan#13916: Sending peer that we want to STFU.
2023-09-08T19:31:25.572Z DEBUG   xxxxxx-channeld-chan#13916: peer_out WIRE_STFU
2023-09-08T19:31:25.663Z DEBUG   xxxxxx-channeld-chan#13916: peer_in WIRE_STFU
2023-09-08T19:31:25.664Z DEBUG   xxxxxx-channeld-chan#13916: STFU initiator local.
2023-09-08T19:31:25.664Z UNUSUAL xxxxxx-channeld-chan#13916: STFU complete: we are quiescent
2023-09-08T19:31:25.664Z UNUSUAL xxxxxx-channeld-chan#13916: STFU complete: setting stfu_wait_single_msg = true
2023-09-08T19:31:25.664Z DEBUG   xxxxxx-channeld-chan#13916: peer_out WIRE_SPLICE
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: peer_in WIRE_SPLICE_ACK
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: splice_initiator peer->stfu_wait_single_msg: 0
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: just added funding w/ outpoint index set to 0, value in psbt input 1 is: 0, and value in psbt input 2 is: 0
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: Sending master 7208
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: ... , awaiting 7209
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: Got it!
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: peer_out WIRE_WARNING
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: billboard perm: Interactive splicing_ack error: interactivetx ADD_INPUT PSBT needs the previous transaction set.
2023-09-08T19:31:25.752Z INFO    xxxxxx-chan#13916: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: Interactive splicing_ack error: interactivetx ADD_INPUT PSBT needs the previous transaction set.
2023-09-08T19:31:25.752Z DEBUG   xxxxxx-channeld-chan#13916: Status closed, but not exited. Killing
2023-09-08T19:31:25.753Z DEBUG   connectd: drain_peer
2023-09-08T19:31:25.753Z DEBUG   connectd: drain_peer draining subd!
2023-09-08T19:31:25.753Z DEBUG   hsmd: Client: Received message 3 from client
2023-09-08T19:31:25.753Z DEBUG   xxxxxx-lightningd: peer_disconnect_done
2023-09-08T19:31:25.753Z DEBUG   xxxxxx-lightningd: Will try reconnect in 2 seconds

@Sjors
Copy link
Contributor Author

Sjors commented Sep 8, 2023 •
edited
Loading

That last action seems to have resulted in a unilateral close from their end, which they deny having done themselves :-):

"channeld: received ERROR error channel xxx: Interactive splicing error: They sent a warning: warning channel xxxx: Interactive splicing_ack error: interactivetx ADD_INPUT PSBT needs the previous transaction set."

...

 "status": [
    "ONCHAIN:Tracking their unilateral close",
    "ONCHAIN:All outputs resolved: waiting 96 more blocks before forgetting channel"
  ],

@Sjors
Copy link
Contributor Author

Sjors commented Sep 8, 2023 •
edited
Loading

Logs from their end (running v23.08):

Sep 08 14:18:52 mempool lightningd[1336491]: 2023-09-08T18:18:52.245Z INFO    xxxxxx-chan#1776: State changed from CHANNELD_AWAITING_LOCKIN to CHANNELD_NORMAL
Sep 08 14:27:09 mempool lightningd[1336491]: 2023-09-08T18:27:09.609Z UNUSUAL xxxxxx-channeld-chan#1776: STFU complete: we are quiescent
Sep 08 14:27:09 mempool lightningd[1336491]: 2023-09-08T18:27:09.609Z UNUSUAL xxxxxx-channeld-chan#1776: STFU complete: setting stfu_wait_single_msg = true
Sep 08 14:38:44 mempool lightningd[1336491]: 2023-09-08T18:38:44.417Z INFO    xxxxxx-chan#1776: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: Unable to sub opener funding from out amnt.
Sep 08 14:38:46 mempool lightningd[1336491]: 2023-09-08T18:38:46.614Z INFO    xxxxxx-channeld-chan#1776: Peer connection lost
Sep 08 14:38:46 mempool lightningd[1336491]: 2023-09-08T18:38:46.614Z INFO    xxxxxx-chan#1776: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
Sep 08 15:13:49 mempool lightningd[1336491]: 2023-09-08T19:13:49.190Z INFO    xxxxxx-channeld-chan#1776: Peer connection lost
Sep 08 15:13:49 mempool lightningd[1336491]: 2023-09-08T19:13:49.190Z INFO    xxxxxx-chan#1776: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
Sep 08 15:17:39 mempool lightningd[1336491]: 2023-09-08T19:17:39.954Z INFO    xxxxxx-channeld-chan#1776: Peer connection lost
Sep 08 15:17:39 mempool lightningd[1336491]: 2023-09-08T19:17:39.955Z INFO    xxxxxx-chan#1776: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
Sep 08 15:20:04 mempool lightningd[1336491]: 2023-09-08T19:20:04.654Z UNUSUAL xxxxxx-channeld-chan#1776: STFU complete: we are quiescent
Sep 08 15:20:04 mempool lightningd[1336491]: 2023-09-08T19:20:04.654Z UNUSUAL xxxxxx-channeld-chan#1776: STFU complete: setting stfu_wait_single_msg = true
Sep 08 15:20:31 mempool lightningd[1336491]: 2023-09-08T19:20:31.955Z INFO    xxxxxx-chan#1776: Peer transient failure in CHANNELD_NORMAL: channeld WARNING: Unable to sub opener funding from out amnt.
Sep 08 15:25:20 mempool lightningd[1336491]: 2023-09-08T19:25:20.847Z INFO    xxxxxx-channeld-chan#1776: Peer connection lost
Sep 08 15:25:20 mempool lightningd[1336491]: 2023-09-08T19:25:20.848Z INFO    xxxxxx-chan#1776: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
Sep 08 15:31:25 mempool lightningd[1336491]: 2023-09-08T19:31:25.619Z UNUSUAL xxxxxx-channeld-chan#1776: STFU complete: we are quiescent
Sep 08 15:31:25 mempool lightningd[1336491]: 2023-09-08T19:31:25.619Z UNUSUAL xxxxxx-channeld-chan#1776: STFU complete: setting stfu_wait_single_msg = true
Sep 08 15:31:25 mempool lightningd[1336491]: 2023-09-08T19:31:25.799Z UNUSUAL xxxxxx-chan#1776: Peer permanent failure in CHANNELD_NORMAL: channeld: sent ERROR Interactive splicing error: They sent a warning: warning channe>
Sep 08 15:31:25 mempool lightningd[1336491]: 2023-09-08T19:31:25.800Z INFO    xxxxxx-chan#1776: State changed from CHANNELD_NORMAL to AWAITING_UNILATERAL
Sep 08 15:33:25 mempool lightningd[1336491]: 2023-09-08T19:33:25.265Z UNUSUAL xxxxxx-chan#1776: Peer permanent failure in AWAITING_UNILATERAL: Funding transaction spent
Sep 08 15:33:25 mempool lightningd[1336491]: 2023-09-08T19:33:25.266Z INFO    xxxxxx-chan#1776: State changed from AWAITING_UNILATERAL to FUNDING_SPEND_SEEN
Sep 08 15:33:25 mempool lightningd[1336491]: 2023-09-08T19:33:25.339Z INFO    xxxxxx-chan#1776: State changed from FUNDING_SPEND_SEEN to ONCHAIN

@Sjors
Copy link
Contributor Author

Sjors commented Sep 8, 2023

cc @ddustin

@ddustin
Copy link
Collaborator

ddustin commented Sep 8, 2023

I believe this may be caused because the PSBT didn't provide an output to receive the outgoing funds and the error handling around that isn't giving the appropriate error 👀. Going to investigate this possibility.

@ddustin
Copy link
Collaborator

ddustin commented Sep 12, 2023 •
edited
Loading

Thanks again for the report!

  • Validate check_balances on splice_out, both,
    • with a corresponding output, and, [Add Test]
    • with corresponding output missing [Add Test]
  • Add clear RPC error message to that balance calculation failed due to missing corresponding output
  • Validate purposeful check_balances failure to abort splice mid-way
    • Add test for above ^

@ddustin ddustin self-assigned this Sep 12, 2023
This was referenced Sep 13, 2023
Merged
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ddustin ddustin

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Splice-out Regression and Restart Fixes ddustin/lightning
3 participants
@Sjors @ddustin and others