Keysend crashes

[evd0kim]

When writing a new plugin that could rely on keysend feature I've decided to try just keysend between 2 signet nodes with direct channel. It crashed the node, pay crashed the node too when xpay was enabled and when it was disabled, pay just hung.

"version": "v25.02-130-g97d562c-modded"

It looks like the root issue is the same as in #8270 so it could be only one issue.

Here is debug log:

+234.599903417 jsonrpc#79IO_IN: "cli:keysend#1204028/cln:keysend#172/keysend:sendonion#9"
+234.599919287 lightningdTRACE: Calling rpc_command hook of plugin cln-xpay
+234.599932641 plugin-cln-xpayIO_OUT: "cli:keysend#1204028/cln:keysend#172/keysend:sendonion#9/cln:rpc_command#180"
+234.600343823 plugin-cln-xpayIO_IN: 7b226a736f6e727063223a22322e30222c226964223a22636c693a6b657973656e6423313230343032382f636c6e3a6b657973656e64233137322f6b657973656e643a73656e646f6e696f6e23392f636c6e3a7270635f636f6d6d616e6423313830222c22726573756c74223a7b22726573756c74223a22636f6e74696e7565227d7d0a0a
+234.600362457 lightningdTRACE: Plugin cln-xpay returned from rpc_command hook call
+234.600546097 lightningdDEBUG: Selected channel 208812x12x0 (40925559msat) for selector 208812x12x0 (1000000msat)
+234.600577375 lightningdINFO: Sending 1000000msat in onion to deliver 1000000msat
+235.002731111 jsonrpc#79IO_OUT: 7b226a736f6e727063223a22322e30222c226964223a22636c693a6b657973656e6423313230343032382f636c6e3a6b657973656e64233137322f6b657973656e643a73656e646f6e696f6e2339222c22726573756c74223a7b226d657373616765223a224d6f6e69746f72207374617475732077697468206c69737470617973206f72207761697473656e64706179222c22637265617465645f696e646578223a32352c226964223a32352c227061796d656e745f68617368223a2230306137386433643963306264363833333539386662626164646262303135386665303230323235613631373161336366653538303839663765643765393831222c2267726f75706964223a302c2264657374696e6174696f6e223a22303332396562343165643932303432353533633930656564326664303837663234623631613465366337633938616161306439363333333666336161326433663835222c22616d6f756e745f6d736174223a313030303030302c22616d6f756e745f73656e745f6d736174223a313030303030302c22637265617465645f6174223a313734363532313337372c22737461747573223a2270656e64696e67227d7d0a0a
+235.002805890 plugin-cln-tvmIO_IN: 7b226a736f6e727063223a22322e30222c226d6574686f64223a226c6f67222c22706172616d73223a7b226c6576656c223a226465627567222c226d657373616765223a2272657573652069646c6520636f6e6e656374696f6e20666f7220285c2268747470735c222c20657874656e73696f6e2d6170692e62726f7875732e636f6d29227d7d0a0a
+235.002830656 plugin-cln-tvmDEBUG: reuse idle connection for (\"https\", extension-api.broxus.com)
+235.002889274 plugin-cln-ethIO_IN: 7b226a736f6e727063223a22322e30222c226d6574686f64223a226c6f67222c22706172616d73223a7b226c6576656c223a226465627567222c226d657373616765223a22576f726b6572206c6f6f7020736c65657073227d7d0a0a7b226a736f6e727063223a22322e30222c226d6574686f64223a226c6f67222c22706172616d73223a7b226c6576656c223a226465627567222c226d657373616765223a2272657573652069646c6520636f6e6e656374696f6e20666f7220285c2268747470735c222c20617262697472756d2d7365706f6c69612e696e667572612e696f29227d7d0a0a7b226a736f6e727063223a22322e30222c226d6574686f64223a226c6f67222c22706172616d73223a7b226c6576656c223a226465627567222c226d657373616765223a22666c757368656420323931206279746573227d7d0a0a
+235.002902258 plugin-cln-ethDEBUG: Worker loop sleeps
+235.002943805 plugin-cln-ethDEBUG: reuse idle connection for (\"https\", arbitrum-sepolia.infura.io)
+235.002974171 plugin-cln-ethDEBUG: flushed 291 bytes
+235.003036437 jsonrpc#79IO_IN: 7b226a736f6e727063223a22322e30222c226964223a22636c693a6b657973656e6423313230343032382f636c6e3a6b657973656e64233137322f6b657973656e643a7761697473656e64706179233130222c226d6574686f64223a227761697473656e64706179222c22706172616d73223a7b227061796d656e745f68617368223a2230306137386433643963306264363833333539386662626164646262303135386665303230323235613631373161336366653538303839663765643765393831222c22706172746964223a302c2267726f75706964223a307d7d0a0a
+235.003049120 jsonrpc#79IO_IN: "cli:keysend#1204028/cln:keysend#172/keysend:waitsendpay#10"
+235.003071412 lightningdTRACE: Calling rpc_command hook of plugin cln-xpay
+235.003081661 plugin-cln-xpayIO_OUT: "cli:keysend#1204028/cln:keysend#172/keysend:waitsendpay#10/cln:rpc_command#181"
+235.003199489 channeld-chan#2DEBUG: NEW:: HTLC LOCAL 16 = SENT_ADD_HTLC/RCVD_ADD_HTLC 
+235.003238801 channeld-chan#2DEBUG: Adding HTLC 16 amount=1000000msat cltv=251148 gave CHANNEL_ERR_ADD_OK
+235.003274107 channeld-chan#2DEBUG: peer_out WIRE_UPDATE_ADD_HTLC
+235.003306397 channeld-chan#2DEBUG: REPLY WIRE_CHANNELD_OFFER_HTLC_REPLY with 0 fds
+235.003364354 plugin-cln-xpayIO_IN: 7b226a736f6e727063223a22322e30222c226964223a22636c693a6b657973656e6423313230343032382f636c6e3a6b657973656e64233137322f6b657973656e643a7761697473656e647061792331302f636c6e3a7270635f636f6d6d616e6423313831222c22726573756c74223a7b22726573756c74223a22636f6e74696e7565227d7d0a0a
+235.003380855 lightningdTRACE: Plugin cln-xpay returned from rpc_command hook call
+235.003568252 lightningdDEBUG: Payment part 0/0/0 status 0
+235.013414593 channeld-chan#2DEBUG: Trying commit
+235.013492998 channeld-chan#2DEBUG: htlc 16: SENT_ADD_HTLC->SENT_ADD_COMMIT
+235.013537420 channeld-chan#2DEBUG: htlc added REMOTE: local 40925559 remote 58952441
+235.013570211 channeld-chan#2DEBUG: -> local 39925559 remote 58952441
+235.013602961 channeld-chan#2DEBUG: sending_commit: HTLC LOCAL 16 = SENT_ADD_COMMIT/RCVD_ADD_COMMIT 
+235.014991553 hsmdDEBUG: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
+235.015055040 hsmdDEBUG: Client: Received message 19 from client
+235.015137643 channeld-chan#2DEBUG: Creating commit_sig signature 498 3044022018036a44f948073826b10a9a8d4d9ca777f38e6c9e80d39cf0d40a19904eda8202205d53d263eab39bf00ee16eb7e14b38de3a3ace9679a7826d7a703e4f8a0d397101 for tx 020000000105307a91765b800ebc9996360a77c961f1c48b905cfed34bbcae2a763c54b4e900000000006c3f088003e80300000000000022002084de7cddbf1a8cb33c54619f7b3f30d655f2d3dd0046947f476c239a08f24992f59b000000000000160014018fe70f788cd89de0e8c89b28c331a026e89ac75fe5000000000000220020d997c7fa3e2ea1d6aa152ffd0fe7180bd9907fff6f32d860f973393d3316eceb88839c20 wscript 5221022d734b88422d164b6ef41658c0dd31def34054103d918af2c349018468faabf92102fc3eda0f70867b5ec7201ecb848f0372bc7b954b951eeffce4dc6d8646d9df0852ae key 02fc3eda0f70867b5ec7201ecb848f0372bc7b954b951eeffce4dc6d8646d9df08
+235.016023183 hsmdDEBUG: Got WIRE_HSMD_SIGN_REMOTE_HTLC_TX
+235.016081060 hsmdDEBUG: Client: Received message 20 from client
+235.016160357 channeld-chan#2DEBUG: Creating HTLC signature 304402207336405321c4f3fe041ae28950c758111cc7e0e094e561f4e8f0efe189e8e740022057814031f1f10af9e4d720df8e3af2d787cdeb992e09f4890af551c0da48256a01 for tx 020000000150f2da1a7bd57e6516ae1ec40413e7c88b3f60853f4ea7bd37e84e4235d63cc1000000000000000000013103000000000000220020d997c7fa3e2ea1d6aa152ffd0fe7180bd9907fff6f32d860f973393d3316eceb00000000 wscript 76a914237a820389967303b7d29ac3598add16e96c6f1a8763ac6721024a58a43d38fd6db1fec3d45d280c6f748a2b5e34175c2c58dd603020fcfec7897c8201208763a914e4709ba2c771c824f4254dfa8e4940ca143dbca688527c2103b05374397095f55eea52b7884b531164589e6dd9953215cda465afef8a89311352ae6775030cd503b175ac6868 key 024a58a43d38fd6db1fec3d45d280c6f748a2b5e34175c2c58dd603020fcfec789
+235.016223794 channeld-chan#2DEBUG: Telling master we're about to commit...
+235.016256425 channeld-chan#2DEBUG: Sending master 1020
+235.016705837 lightningdBROKEN: Error executing statement: wallet/wallet.c:3175: INSERT INTO channel_htlcs ( id, channel_id, channel_htlc_id, direction, origin_htlc, msatoshi, cltv_expiry, payment_hash, payment_key, hstate, routing_onion, malformed_onion, partid, groupid, fees_msat, min_commit_num) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 0, ?, ?, ?, ?);: UNIQUE constraint failed: channel_htlcs.id
+235.016784723 lightningdBROKEN: Error executing statement: wallet/wallet.c:3175: INSERT INTO channel_htlcs ( id, channel_id, channel_htlc_id, direction, origin_htlc, msatoshi, cltv_expiry, payment_hash, payment_key, hstate, routing_onion, malformed_onion, partid, groupid, fees_msat, min_commit_num) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 0, ?, ?, ?, ?);: UNIQUE constraint failed: channel_htlcs.id
+235.072005678 lightningdBROKEN: FATAL SIGNAL 6 (version v25.02-130-g97d562c-modded)
+235.072047285 lightningdBROKEN: backtrace: common/daemon.c:41 (send_backtrace) 0x482f6d
+235.072059418 lightningdBROKEN: backtrace: common/daemon.c:78 (crashdump) 0x482fa8
+235.072074406 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fe8ffba8c2f
+235.072085516 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fe8ffc0211c
+235.072098670 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fe8ffba8afd
+235.072116524 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fe8ffb906cf
+235.072126732 lightningdBROKEN: backtrace: lightningd/log.c:1043 (fatal_vfmt) 0x42fff5
+235.072137783 lightningdBROKEN: backtrace: wallet/db.c:1116 (db_error) 0x461d0f
+235.072151027 lightningdBROKEN: backtrace: db/utils.c:323 (db_fatal) 0x4d3885
+235.072162178 lightningdBROKEN: backtrace: db/utils.c:197 (db_exec_prepared_v2) 0x4d3c50
+235.072175212 lightningdBROKEN: backtrace: wallet/wallet.c:3238 (wallet_htlc_save_out) 0x46ce91
+235.072186052 lightningdBROKEN: backtrace: lightningd/peer_htlcs.c:1978 (update_out_htlc) 0x44bce3
+235.072199577 lightningdBROKEN: backtrace: lightningd/peer_htlcs.c:2011 (changed_htlc) 0x44c085
+235.072209726 lightningdBROKEN: backtrace: lightningd/peer_htlcs.c:2108 (peer_sending_commitsig) 0x44f4ab
+235.072220185 lightningdBROKEN: backtrace: lightningd/channel_control.c:1508 (channel_msg) 0x40ffbc
+235.072232348 lightningdBROKEN: backtrace: lightningd/subd.c:560 (sd_msg_read) 0x45ac31
+235.072245953 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:60 (next_plan) 0x54b71e
+235.072257174 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:422 (do_plan) 0x54bb86
+235.072269266 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:439 (io_ready) 0x54bc39
+235.072278794 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:455 (io_loop) 0x54d4ae
+235.072287560 lightningdBROKEN: backtrace: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers) 0x42832f
+235.072297529 lightningdBROKEN: backtrace: lightningd/lightningd.c:1484 (main) 0x42d8b8
+235.072309691 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fe8ffb925f4
+235.072320601 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fe8ffb926a7
+235.072332564 lightningdBROKEN: backtrace: (null):0 ((null)) 0x402394
+235.072343814 lightningdBROKEN: backtrace: (null):0 ((null)) 0xffffffffffffffff

[grubles]

Looks like I might have hit the same crash? Though I was not trying to use keysend at the time. CLN at 8a56ccd

2025-05-15T05:14:29.921Z **BROKEN** lightningd: Error executing statement: wallet/wallet.c:3108: INSERT INTO channel_htlcs ( id, channel_id, channel_htlc_id,  direction, msatoshi, cltv_expiry, payment_hash,  payment_key, hstate, shared_secret, routing_onion, received_time, min_commit_num,  fail_immediate) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: channel_htlcs.id
2025-05-15T05:14:29.921Z **BROKEN** lightningd: Error executing statement: wallet/wallet.c:3108: INSERT INTO channel_htlcs ( id, channel_id, channel_htlc_id,  direction, msatoshi, cltv_expiry, payment_hash,  payment_key, hstate, shared_secret, routing_onion, received_time, min_commit_num,  fail_immediate) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: channel_htlcs.id
2025-05-15T05:14:29.968Z **BROKEN** lightningd: FATAL SIGNAL 6 (version v25.02-125-g8a56ccd)
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: common/daemon.c:41 (send_backtrace) 0x48664c
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: common/daemon.c:78 (crashdump) 0x486686
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f7ca7a3e72f
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f7ca7a8b53c
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f7ca7a3e685
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f7ca7a28832
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: lightningd/log.c:1043 (fatal_vfmt) 0x4336d3
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: wallet/db.c:1116 (db_error) 0x4654c2
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: db/utils.c:323 (db_fatal) 0x4d5450
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: db/utils.c:197 (db_exec_prepared_v2) 0x4d5813
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: wallet/wallet.c:3162 (wallet_htlc_save_in) 0x470470
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: lightningd/peer_htlcs.c:2215 (channel_added_their_htlc) 0x45251e
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: lightningd/peer_htlcs.c:2357 (peer_got_commitsig) 0x453084
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: lightningd/channel_control.c:1514 (channel_msg) 0x4137ce
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: lightningd/subd.c:560 (sd_msg_read) 0x45ee6e
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: ccan/ccan/io/io.c:60 (next_plan) 0x53d755
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: ccan/ccan/io/io.c:422 (do_plan) 0x53dbba
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: ccan/ccan/io/io.c:439 (io_ready) 0x53dc6d
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: ccan/ccan/io/poll.c:455 (io_loop) 0x53f52d
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers) 0x42bb5e
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: lightningd/lightningd.c:1484 (main) 0x431093
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f7ca7a295cf
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f7ca7a2967f
2025-05-15T05:14:29.968Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x405ce4
2025-05-15T05:14:29.969Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0xffffffffffffffff

[grubles]

After updating to the latest commit at 529337a and upgrading the database, CLN now crashes with this error:

0x48833e send_backtrace                                                                                                                                                                                                  
        common/daemon.c:33             
0x4883c1 crashdump
        common/daemon.c:78          
0x7fb55923e72f ???
        ???:0
0x7fb55928b53c ???
        ???:0
0x7fb55923e685 ???
        ???:0
0x7fb559228832 ???    
        ???:0
0x54acba call_error                 
        ccan/ccan/tal/tal.c:95
0x54ad58 check_bounds               
        ccan/ccan/tal/tal.c:169
0x54ad89 to_tal_hdr
        ccan/ccan/tal/tal.c:179
0x54adc5 to_tal_hdr_or_null
        ccan/ccan/tal/tal.c:193
0x54bb43 tal_bytelen
        ccan/ccan/tal/tal.c:693
0x49a239 tal_hex
        common/utils.c:76
0x415e6d channel_gossip_update_from_gossipd
        lightningd/channel_gossip.c:1101
0x4251ed handle_init_cupdate
        lightningd/gossip_control.c:147
0x42530e gossip_msg
        lightningd/gossip_control.c:216
0x460383 sd_msg_read
        lightningd/subd.c:560
0x53ffb5 next_plan
        ccan/ccan/io/io.c:60
0x54041a do_plan
        ccan/ccan/io/io.c:422
0x5404cd io_ready
        ccan/ccan/io/io.c:439
0x541d8d io_loop
        ccan/ccan/io/poll.c:455
0x425049 gossip_init
        lightningd/gossip_control.c:341
0x4318a6 main
        lightningd/lightningd.c:1382
0x7fb5592295cf ???
        ???:0
0x7fb55922967f ???
        ???:0
0x405ce4 ???
        ???:0
0xffffffffffffffff ???
        ???:0
Error: Error configuring the plugin!
lightningd: Died with signal 6
Error: Error configuring the plugin!

debug.log shows this at the time of the crash:

2025-05-15T18:28:02.250Z DEBUG   lightningd: updating channel 720561x1200x5 with inbound settings
2025-05-15T18:28:02.275Z DEBUG   lightningd: updating channel 726821x1167x2 with inbound settings
2025-05-15T18:28:02.299Z DEBUG   lightningd: updating channel 720561x1200x2 with inbound settings
2025-05-15T18:28:02.324Z DEBUG   lightningd: updating channel 890716x2688x1 with inbound settings
2025-05-15T18:28:02.349Z DEBUG   lightningd: updating channel 891202x554x0 with inbound settings
2025-05-15T18:28:02.374Z DEBUG   lightningd: updating channel 891314x1766x7 with inbound settings
2025-05-15T18:28:02.400Z DEBUG   lightningd: updating channel 891951x1980x0 with inbound settings
2025-05-15T18:28:02.425Z DEBUG   lightningd: updating channel 894979x1008x0 with inbound settings

Deleting gossip_store seems to have fixed that particular crash.

[endothermicdev]

I'll take a look, thanks for reminding me.

[endothermicdev]

The most recent crash at 529337a was resolved with #8292 and 40a86da. I don't think it was related to the earlier two.

[rustyrussell]

Were these upgraded from a previous version? I think I can see how this happens.

[grubles]

Running #8294 now and the crash here is gone. Thanks!