Open H-Fren opened 1 year ago
Great bug report!! Thanks
OK, there are some weird things here!
Firstly, it looks like you specified a specific destination address to shutdown to? Because the funds are going to "bc1pqfr7s3hdd4ey703kgsaadzppqn0n4us07lylvquu5nuhqjk7kl8smrcv4g" which is a taproot address which we wouldn't generate ourselves. That seems ok though.
The logs talk about a "fee 547" and outputs "1598535sat/157727518sat", but the channel is 1.59326054BTC, so trying to close 1.57727518 & 0.01597988 means a 548 sat fee. It's possible this is a rounding issue, but I can't see the actual sig to check.
Can you re-try connecting, adding "log-level:io:02f1a8c87607f415c"? That will produce a lot of spewage, but it will show ALL the messages we receive? That will include the signature, and I can grind it if it's signing something close to what we expect?
OK, so I have created a new channel:
lightning-cli -k fundchannel id=02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69 amount=all feerate=urgent announce=false reserve=20000sat
this time without the close_to
argument, I waited for more than 6 confirmations, and then I closed the channel:
lightning-cli -k close id=785220x1516x0 feerange='["normal", "urgent"]'
The negotiation process was stuck after sending and receiving fees 10 times, Kraken always offered a fee lower than "normal". During the negotiation period I was not connected to the node and an attempt to connect resulted in the usual disconnection. The log can be found here: https://pastebin.com/Hq7Rbj9t
So I have stopped the node and restarted it, the difference is that looks like this time the closing process succeeded, the channel is now in CLOSINGD_COMPLETE
state with the message CLOSINGD_SIGEXCHANGE:We agreed on a closing fee of 378 satoshi
and everything seems fine, maybe except for the fact that this is below the acceptable minimum of 685 sat.
And yet another try.
lightning-cli -k fundchannel id=02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69 amount=all feerate=urgent announce=false reserve=20000sat close_to=bc1p3zc4499jaj4xru20ymnp9n8t8ueprtyux2vt6dkdxqzwm8wyt75sdrj3zj
.lightning-cli -k close id=785243x1074x0 destination=bc1p5fcew9lu5t0wykumnlfgzuap4nfq2m9slzz7mq297ezt5f7n3uyqw5ma40 feerange='[21000, 25000]'
but I got a reply { "code": -32602, "message": "Destination address 512088b15a94b2ecaa61f14f26e612cceb3f3211ac9c3298bd36cd3004ed9dc45fa9 does not match previous shutdown script 5120a2719717fca2dee25b9b9fd28173a1acd2056cb0f885ed8145f644ba27d38f08" }
.lightning-cli -k close id=785243x1074x0 feerange='[21000, 25000]'
.Sending closing fee offer 3447sat, with range 3447sat-3447sat Received closing fee offer 407sat, without range Sending closing fee offer 3447sat, with range 3447sat-3447sat Sending closing fee offer 3447sat, with range 3447sat-3447sat Sending closing fee offer 3447sat, with range 3447sat-3447sat Sending closing fee offer 3447sat, with range 3447sat-3447sat Sending closing fee offer 3447sat, with range 3447sat-3447sat Sending closing fee offer 3447sat, with range 3447sat-3447sat Sending closing fee offer 3447sat, with range 3447sat-3447sat
i encountered this issue aswell (4 times already) all on cln 23.02: i put in the log-level=io for the peer and after restart and connectig to the peer i get (filtering log output by peer id i hope thats good enough):
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-connectd: Connected out, starting crypto
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-connectd: Connect OUT
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-connectd: peer_out WIRE_INIT
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-connectd: peer_in WIRE_INIT
Apr 15 17:15:18 lightningd[503186]: INFO 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-chan#543: Peer transient failure in CLOSINGD_SIGEXCHANGE: Disconnected
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-connectd: Handed peer, entering loop
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-chan#543: Peer has reconnected, state CLOSINGD_SIGEXCHANGE: connecting subd
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: pid 503547, msgfd 151
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-chan#543: Already have funding locked in (and ready to announce)
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-chan#543: attempting update blockheight 45d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d2
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: option_static_remotekey = 1, option_anchor_outputs = 0
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: init LOCAL: remote_per_commit = 026325bbf123c3d286f8401e8eba82499e4207f411f5c639803f802579e0f0ed2c, old_remote_per_commit = 022f1469a82d9bda16fc8c3adf041bbffcfa95d82d05ae5361e0f2567b7fc22b97 next_idx_local = 41581 next_idx_remote = 41522 revocations_received = 41521 feerates { SENT_ADD_ACK_REVOCATION:864 } range 278-55303 blockheights { SENT_ADD_ACK_REVOCATION:0 }, our current 785537
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
Apr 15 17:15:18 lightningd[503186]: 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: [OUT] 008845d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d2000000000000a26d000000000000a23110944a804eef5cb1510ccc92a192a331ae8a35f2e6154ef4696420c1a16190aa026325bbf123c3d286f8401e8eba82499e4207f411f5c639803f802579e0f0ed2c
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: billboard: Sent reestablish, waiting for theirs
Apr 15 17:15:18 lightningd[503186]: 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: [IN] 008845d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d2000000000000a232000000000000a26cd15a292fd2741990c5b47acf98fa985ce76747f803f118b36970ccf927dc59fa022f1469a82d9bda16fc8c3adf041bbffcfa95d82d05ae5361e0f2567b7fc22b97
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: Got reestablish commit=41522 revoke=41580
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: next_revocation_number = 41580
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: option_static_remotekey: fields are correct
Apr 15 17:15:18 lightningd[503186]: 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: [OUT] 002645d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d200160014180f8b50c2f7ae42d56b32f7b4f50f8f3099c0d6
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: billboard: Channel ready for use. They need our announcement signatures. Shutdown messages exchanged.
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: billboard perm: Reconnected, and reestablished.
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: billboard: Channel ready for use. They need our announcement signatures. Shutdown messages exchanged.
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: pid 503548, msgfd 89
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-channeld-chan#543: Status closed, but not exited. Killing
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: Expected closing weight = 724, fee 401sat (min 201sat, max 625sat)
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: out = 14849565sat/4084338sat
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: dustlimit = 546sat
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-hsmd: Got WIRE_HSMD_SIGN_MUTUAL_CLOSE_TX
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: fee = 401sat
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: fee negotiation step = 50%
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: billboard perm: Negotiating closing fee between 201sat and 625sat satoshi (ideal 401sat) using step 50%
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: Making close tx at = 14849565sat/4084338sat fee 401sat
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: sending fee offer 401sat
Apr 15 17:15:18 lightningd[503186]: 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: [OUT] 002745d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d20000000000000191422750eb83450c59e95569ecfa93cfb068d2647bf719fa987fae6358d7f7cd9b4ad47b800329c0f0c5588656e8125e336f83b698ecbdba6d37cb26e35c1693d1011000000000000000c90000000000000271
Apr 15 17:15:18 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: billboard: Waiting for their initial closing fee offer: ours was 401sat
Apr 15 17:15:18 lightningd[503186]: 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: [IN] 002645d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d2002251204a89ab406bf1dc5582e41a3049b16494a0e08b4fdc020932f2a464699a57cdea
Apr 15 17:15:19 lightningd[503186]: 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: [IN] 002745d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d200000000000000e7e57bd037143e15a474514ed9c2450326d47c3ed66687b2ba7f8a5e0b4ead8a0121f1a067591d18674abc8dfa1711e29f986c1f67fa0eaafd7d07dd00424a0f9b
Apr 15 17:15:19 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: Making close tx at = 14849565sat/4084338sat fee 231sat
Apr 15 17:15:19 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: Making close tx at = 14849565sat/0sat fee 231sat
Apr 15 17:15:19 lightningd[503186]: 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: [OUT] 000145d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d201d642616420636c6f73696e675f7369676e6564207369676e617475726520666f7220303230303030303030313435643162626161356563633638373137636234623539643038383138393238303833393837373362363631366233616536633366333566643664363037643130333030303030303030666666666666666630323732353233653030303030303030303032323531323061613262666635643033663563303664653966323862613162316633306530373163353935663730323537646434623938323133666462326134663064323366333639356532303030303030303030303136303031343138306638623530633266376165343264353662333266376234663530663866333039396330643630303030303030302028616e64207472696d6d65642076657273696f6e20303230303030303030313435643162626161356563633638373137636234623539643038383138393238303833393837373362363631366233616536633366333566643664363037643130333030303030303030666666666666666630313336393565323030303030303030303031363030313431383066386235306332663761653432643536623332663762346635306638663330393963306436303030303030303029
Apr 15 17:15:19 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-lightningd: peer_disconnect_done
Apr 15 17:15:19 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-lightningd: Will try reconnect in 192 seconds
Apr 15 17:15:19 lightningd[503186]: DEBUG 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-closingd-chan#543: billboard perm: Bad closing_signed signature for 020000000145d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d10300000000ffffffff0272523e0000000000225120aa2bff5d03f5c06de9f28ba1b1f30e071c595f70257dd4b98213fdb2a4f0d23f3695e20000000000160014180f8b50c2f7ae42d56b32f7b4f50f8f3099c0d600000000 (and trimmed version 020000000145d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d10300000000ffffffff013695e20000000000160014180f8b50c2f7ae42d56b32f7b4f50f8f3099c0d600000000)
Apr 15 17:15:19 lightningd[503186]: DEBUG plugin-funder: Cleaning up inflights for peer id 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3
Apr 15 17:15:19 lightningd[503186]: INFO 0326e692c455dd554c709bbb470b0ca7e0bb04152f777d1445fd0bf3709a2833a3-chan#543: Peer transient failure in CLOSINGD_SIGEXCHANGE: closingd WARNING: Bad closing_signed signature for 020000000145d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d10300000000ffffffff0272523e0000000000225120aa2bff5d03f5c06de9f28ba1b1f30e071c595f70257dd4b98213fdb2a4f0d23f3695e20000000000160014180f8b50c2f7ae42d56b32f7b4f50f8f3099c0d600000000 (and trimmed version 020000000145d1bbaa5ecc68717cb4b59d0881892808398773b6616b3ae6c3f35fd6d607d10300000000ffffffff013695e20000000000160014180f8b50c2f7ae42d56b32f7b4f50f8f3099c0d600000000)
still happening on 23.05 btw.
Issue and Steps to Reproduce
I can't close channels I have on the Kraken node. During the fee negotiation stage Kraken does not negotiate, it just sends the offered fee once and the whole process is stuck and I can't connect to the Kraken node anymore because c-li keeps disconnecting. I don't want to wait for forcible closure every time I want to close a channel, because the coins will be timelocked for 2016 blocks.
lightning-cli -k close id=784312x957x0 feerange='["normal", "urgent"]'
. The peer will offer a low fee and the process will be stuck (the peer will not be answering) and you'll be disconnected from the node.lightning-cli connect 02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69@52.13.118.208:9735
. It will look fine but you'll be disconnected immediately. See the log.getinfo
output{ "id": "02cf431a604bbb133069f538477a5d038d21af99c333eac1a4ee8fceb6bd1a7d51", "alias": "LOUDANALYST", "color": "02cf43", "num_peers": 1, "num_pending_channels": 0, "num_active_channels": 3, "num_inactive_channels": 3, "address": [], "binding": [ { "type": "ipv6", "address": "::", "port": 9735 }, { "type": "ipv4", "address": "0.0.0.0", "port": 9735 } ], "version": "23.02.2", "blockheight": 784477, "network": "bitcoin", "msatoshi_fees_collected": 604416, "fees_collected_msat": "604416msat", "lightning-dir": "/home/user/.lightning/bitcoin", "our_features": { "init": "08a000080a69a2", "node": "88a000080a69a2", "channel": "", "invoice": "02000000024100" } }
Debug logs: