ElementsProject / lightning

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

recover: The recovery plugin crashes if a channel has not fully been forgotten #7162

Closed nakoshi-satamoto closed 5 months ago

nakoshi-satamoto commented 7 months ago

New description

The recover plugin appears to crash if we had dataloss, but the database still contains a trace of the channel, causing the insert to fail during the recovery.

Original issue

Issue and Steps to Reproduce

My system to froze up and was non-responsive. I had to do a forced reboot of the computer. lightningd won't even start up now. I'm on version 24.02, I even tried reverting back to the old version 23.11.2 and still no luck with starting up this node. I even re-extracted clightning-v24.02-Ubuntu-22.04.tar.xz and tried running v24.02 again and yet no luck. I cannot run the newer version 24.0.2.1 because that is not signed with any valid known signature. So I am on 24.0.2 as the latest version. Yes I was mirroring the sqlite database but that is pointless if the mirror gets corrupted also, if this is a case of database corruption.

Below is the output I get when running in debug mode.

While trying to keep starting up core lightning I noticed one of my channels with alot of funds got forced closed. The chan that got forced closed was 831793x2527x0 (boltz) with closure transaction ID being e6df69daa0eefd910d871601bbf0e78e838b6396c79601a28dbbf31bb8312591

I am scared that these funds have been lost forever, if this was a penalty closure, or if this was a force closure and my lightning node lost the information needed to claim the funds after the wait time.

At this point, I'm done with lightning. Too many issues over my time with running core lightning. I just want to recover my funds. I'm okay if I have to force close all my chans if it means I get my funds back.

1. How can I get core lightning working again, or recover my funds?

2. Assuming the database is corrupted and that chan was indeed forced closed, am I able to claim the funds from the forced close script after the wait time?

Output from lightningd in debug mode


2024-03-21T00:02:54.885Z INFO    lightningd: v24.02e6df69daa0eefd910d871601bbf0e78e838b6396c79601a28dbbf31bb8312591
2024-03-21T00:02:54.941Z DEBUG   lightningd: Opened log file /home/user/.lightning/ln-log.txt
2024-03-21T00:02:54.947Z DEBUG   plugin-manager: started(32757) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/autoclean
2024-03-21T00:02:54.951Z DEBUG   plugin-manager: started(32758) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/chanbackup
2024-03-21T00:02:54.956Z DEBUG   plugin-manager: started(32759) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/bcli
2024-03-21T00:02:54.960Z DEBUG   plugin-manager: started(32760) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/commando
2024-03-21T00:02:54.965Z DEBUG   plugin-manager: started(32761) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/fetchinvoice
2024-03-21T00:02:54.970Z DEBUG   plugin-manager: started(32762) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/funder
2024-03-21T00:02:54.976Z DEBUG   plugin-manager: started(32763) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/topology
2024-03-21T00:02:54.979Z DEBUG   plugin-manager: started(32764) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/keysend
2024-03-21T00:02:54.983Z DEBUG   plugin-manager: started(32765) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/offers
2024-03-21T00:02:54.985Z DEBUG   plugin-manager: started(32766) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/pay
2024-03-21T00:02:54.988Z DEBUG   plugin-manager: started(32767) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/recover
2024-03-21T00:02:54.992Z DEBUG   plugin-manager: started(32768) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/txprepare
2024-03-21T00:02:54.995Z DEBUG   plugin-manager: started(32769) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/cln-renepay
2024-03-21T00:02:55.001Z DEBUG   plugin-manager: started(32770) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/spenderp
2024-03-21T00:02:55.007Z DEBUG   plugin-manager: started(32771) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/sql
2024-03-21T00:02:55.011Z DEBUG   plugin-manager: started(32772) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/cln-grpc
2024-03-21T00:02:55.015Z DEBUG   plugin-manager: started(32774) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/bookkeeper
2024-03-21T00:02:55.019Z DEBUG   plugin-manager: started(32775) /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/plugins/clnrest/clnrest.py
2024-03-21T00:02:55.051Z INFO    plugin-clnrest.py: Killing plugin: disabled itself: No module named 'gevent'
2024-03-21T00:02:55.051Z DEBUG   lightningd: io_break: check_plugins_manifests
2024-03-21T00:02:55.051Z DEBUG   lightningd: io_loop_with_timers: plugins_init
2024-03-21T00:02:55.052Z DEBUG   lightningd: testing /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/lightning_channeld
2024-03-21T00:02:55.053Z DEBUG   lightningd: testing /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/lightning_closingd
2024-03-21T00:02:55.054Z DEBUG   lightningd: testing /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/lightning_connectd
2024-03-21T00:02:55.055Z DEBUG   lightningd: testing /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/lightning_gossipd
2024-03-21T00:02:55.056Z DEBUG   lightningd: testing /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/lightning_hsmd
2024-03-21T00:02:55.057Z DEBUG   lightningd: testing /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/lightning_onchaind
2024-03-21T00:02:55.058Z DEBUG   lightningd: testing /home/user/apps/clightning/clightning-24.02/usr/libexec/c-lightning/lightning_openingd
2024-03-21T00:02:55.059Z DEBUG   hsmd: pid 32783, msgfd 52
2024-03-21T00:02:55.060Z DEBUG   hsmd: capability +WIRE_HSMD_CHECK_PUBKEY
2024-03-21T00:02:55.060Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_ANY_DELAYED_PAYMENT_TO_US
2024-03-21T00:02:55.060Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_ANCHORSPEND
2024-03-21T00:02:55.060Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_HTLC_TX_MINGLE
2024-03-21T00:02:55.060Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_SPLICE_TX
2024-03-21T00:02:55.060Z DEBUG   hsmd: capability +WIRE_HSMD_CHECK_OUTPOINT
2024-03-21T00:02:55.060Z DEBUG   hsmd: capability +WIRE_HSMD_FORGET_CHANNEL
2024-03-21T00:02:55.060Z DEBUG   hsmd: capability +WIRE_HSMD_REVOKE_COMMITMENT_TX
2024-03-21T00:02:56.333Z DEBUG   connectd: pid 32784, msgfd 56
2024-03-21T00:02:56.334Z DEBUG   hsmd: Client: Received message 27 from client
2024-03-21T00:02:56.334Z DEBUG   hsmd: Client: Received message 27 from client
2024-03-21T00:02:56.334Z DEBUG   hsmd: new_client: 0
2024-03-21T00:02:56.335Z DEBUG   038e5677dc7d1ec4e9a82bd004d524b2469fedb0867e85bd1e2f5d3352957e03b7-hsmd: Got WIRE_HSMD_ECDH_REQ
2024-03-21T00:02:56.335Z DEBUG   hsmd: Client: Received message 1 from client
2024-03-21T00:02:56.582Z DEBUG   connectd: Proxy address: 127.0.0.1:9050
2024-03-21T00:02:56.582Z DEBUG   connectd: Created listener on 127.0.0.1:9735
2024-03-21T00:02:56.582Z INFO    connectd: Static Tor service onion address: "d62gy2sc4tspad44resx6ylanagxo23sismn3wkczodl2aorn24y6pyd.onion:9735,127.0.0.1:9735" bound from extern port 9735 
2024-03-21T00:02:56.582Z DEBUG   connectd: REPLY WIRE_CONNECTD_INIT_REPLY with 0 fds
2024-03-21T00:02:56.582Z DEBUG   lightningd: io_break: connect_init_done
2024-03-21T00:02:56.582Z DEBUG   lightningd: io_loop: connectd_init
2024-03-21T00:02:56.607Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2024-03-21T00:02:56.608Z DEBUG   lightningd: io_break: plugin_config_cb
2024-03-21T00:02:56.608Z DEBUG   lightningd: io_loop_with_timers: config_plugin
2024-03-21T00:02:56.608Z DEBUG   lightningd: All Bitcoin plugin commands registered
2024-03-21T00:02:56.894Z DEBUG   lightningd: Adding block 835386: 000000000000000000011645ca433b9b720096ab39de982f85bee18c9416fedf
2024-03-21T00:02:56.894Z DEBUG   lightningd: io_break: maybe_completed_init
2024-03-21T00:02:56.901Z DEBUG   lightningd: io_loop_with_timers: setup_topology
2024-03-21T00:02:56.901Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.902Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.902Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.902Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.903Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.903Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.904Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.904Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.905Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.905Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.906Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2024-03-21T00:02:56.907Z DEBUG   wallet: Loaded 1 HTLC signatures from DB
2024-03-21T00:02:56.908Z DEBUG   wallet: Loaded 12 channels from DB
2024-03-21T00:02:56.908Z DEBUG   wallet: Loading in HTLCs for channel 1
2024-03-21T00:02:56.910Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.910Z DEBUG   wallet: Loading in HTLCs for channel 21
2024-03-21T00:02:56.910Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.910Z DEBUG   wallet: Loading in HTLCs for channel 9
2024-03-21T00:02:56.914Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.914Z DEBUG   wallet: Loading in HTLCs for channel 22
2024-03-21T00:02:56.915Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.915Z DEBUG   wallet: Loading in HTLCs for channel 17
2024-03-21T00:02:56.932Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.932Z DEBUG   wallet: Loading in HTLCs for channel 15
2024-03-21T00:02:56.932Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.932Z DEBUG   wallet: Loading in HTLCs for channel 4
2024-03-21T00:02:56.937Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.938Z DEBUG   wallet: Loading in HTLCs for channel 16
2024-03-21T00:02:56.938Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.938Z DEBUG   wallet: Loading in HTLCs for channel 6
2024-03-21T00:02:56.941Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.941Z DEBUG   wallet: Loading in HTLCs for channel 29
2024-03-21T00:02:56.963Z DEBUG   wallet: Restored 1 incoming HTLCS
2024-03-21T00:02:56.963Z DEBUG   wallet: Loading in HTLCs for channel 14
2024-03-21T00:02:56.966Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.966Z DEBUG   wallet: Loading in HTLCs for channel 7
2024-03-21T00:02:56.966Z DEBUG   wallet: Restored 0 incoming HTLCS
2024-03-21T00:02:56.971Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.971Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.973Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.976Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.980Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.980Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.981Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.981Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.982Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:56.999Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:57.002Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:57.002Z DEBUG   wallet: Restored 0 outgoing HTLCS
2024-03-21T00:02:57.008Z DEBUG   gossipd: pid 32794, msgfd 55
2024-03-21T00:02:57.009Z DEBUG   hsmd: new_client: 0
2024-03-21T00:02:57.010Z DEBUG   gossipd: Store compact time: 0 msec
2024-03-21T00:02:57.010Z DEBUG   gossipd: gossip_store: Read 12/12/1/0 cannounce/cupdate/nannounce/delete from store in 7614 bytes, now 7592 bytes (populated=true)
2024-03-21T00:02:57.010Z DEBUG   gossipd: seeker: state = STARTING_UP New seeker
2024-03-21T00:02:57.010Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_INIT_REPLY with 0 fds
2024-03-21T00:02:57.010Z DEBUG   lightningd: io_break: gossipd_init_done
2024-03-21T00:02:57.010Z DEBUG   lightningd: io_loop: gossip_init
2024-03-21T00:02:57.011Z DEBUG   lightningd: Looking for [autoclean,succeededforwards,num]
2024-03-21T00:02:57.013Z DEBUG   plugin-cln-grpc: Killing plugin: disabled itself at init: Missing 'grpc-port' option
2024-03-21T00:02:57.031Z DEBUG   lightningd: Looking for [autoclean,failedforwards,num]
2024-03-21T00:02:57.038Z DEBUG   lightningd: Looking for [autoclean,succeededpays,num]
2024-03-21T00:02:57.044Z DEBUG   plugin-fetchinvoice: Killing plugin: disabled itself at init: offers not enabled in config
2024-03-21T00:02:57.053Z DEBUG   hsmd: Client: Received message 27 from client
2024-03-21T00:02:57.053Z DEBUG   lightningd: Looking for [autoclean,failedpays,num]
2024-03-21T00:02:57.067Z DEBUG   lightningd: Looking for [autoclean,paidinvoices,num]
2024-03-21T00:02:57.068Z DEBUG   plugin-chanbackup: Chanbackup Initialised!
2024-03-21T00:02:57.074Z DEBUG   plugin-recover: Recover Plugin Initialised!
2024-03-21T00:02:57.074Z DEBUG   plugin-recover: Gossmap loaded!
2024-03-21T00:02:57.074Z DEBUG   lightningd: Looking for [autoclean,expiredinvoices,num]
2024-03-21T00:02:57.076Z DEBUG   hsmd: Client: Received message 27 from client
2024-03-21T00:02:57.077Z DEBUG   plugin-bookkeeper: Setting up database at sqlite3://accounts.sqlite3
2024-03-21T00:02:57.077Z DEBUG   connectd: REPLY WIRE_CONNECTD_ACTIVATE_REPLY with 0 fds
2024-03-21T00:02:57.077Z DEBUG   lightningd: io_break: connect_activate_done
2024-03-21T00:02:57.077Z DEBUG   lightningd: io_loop: connectd_activate
2024-03-21T00:02:57.077Z INFO    lightningd: --------------------------------------------------
2024-03-21T00:02:57.077Z INFO    lightningd: Server started with public key 038e5677dc7d1ec4e9a82bd004d524b2469fedb0867e85bd1e2f5d3352957e03b7, alias nakoshi-satamoto@posteo.net (color #f7931a) and lightningd v24.02
2024-03-21T00:02:57.077Z DEBUG   026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Adding funding_spend_watch
2024-03-21T00:02:57.077Z **BROKEN** 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Cannot broadcast our commitment tx: they have a future one
2024-03-21T00:02:57.077Z DEBUG   03ceeaec6cb017d1ea8ad04a5dfb3facb24a28399d24624ecce8f319973de361d9-chan#1: Watching for funding txid: 02008407990a213aa17d60e2c8954c59fbcefa312372b93897dc77dca17d23ad
2024-03-21T00:02:57.077Z DEBUG   03ceeaec6cb017d1ea8ad04a5dfb3facb24a28399d24624ecce8f319973de361d9-lightningd: Will try reconnect in 1 seconds
2024-03-21T00:02:57.077Z DEBUG   025c644f64160761662483c24aedba90f47f81f74292c7678640cf688a4223caeb-chan#21: Watching for funding txid: 2b0b9f5d365ff8dd5eecfda901789191be44b04fc90b713ceda70dfef331ee6a
2024-03-21T00:02:57.077Z DEBUG   025c644f64160761662483c24aedba90f47f81f74292c7678640cf688a4223caeb-lightningd: Will try reconnect in 1 seconds
2024-03-21T00:02:57.077Z DEBUG   0256ab9b7d257b30dc7308b7a9556b4793c9c3824989feaf0bfdafdb867278f7ee-chan#9: Watching for funding txid: fdd3b833fc60d37c97286c022920b7601d7cf77f5317940c7b25bcee8ddcdefb
2024-03-21T00:02:57.077Z DEBUG   0256ab9b7d257b30dc7308b7a9556b4793c9c3824989feaf0bfdafdb867278f7ee-lightningd: Will try reconnect in 1 seconds
2024-03-21T00:02:57.077Z DEBUG   020a128145c54dec1c1d72e9bf0ec26759d1e16b9a7bba1453e1fc2b4cec6a6fbd-chan#22: Watching for funding txid: 61f9908bfc066e6b7d0e737956b9782c6aba173e06bf76c38e6fd414d5a15556
2024-03-21T00:02:57.077Z DEBUG   020a128145c54dec1c1d72e9bf0ec26759d1e16b9a7bba1453e1fc2b4cec6a6fbd-lightningd: Will try reconnect in 1 seconds
2024-03-21T00:02:57.077Z DEBUG   035cf526f4c01ed693bacd7434461b9dc53d65b910fb3006110d8b42a574858fb2-chan#17: Watching for funding txid: 5ba6f3df167362ab540b09020ba15d757387bc0998ae7fd783cef43fc54d6627
2024-03-21T00:02:57.077Z DEBUG   035cf526f4c01ed693bacd7434461b9dc53d65b910fb3006110d8b42a574858fb2-lightningd: Will try reconnect in 1 seconds
2024-03-21T00:02:57.077Z DEBUG   03c1c8eef8e86c4bdf61067cf7d33e82532dc371f703e24207101e70989d3034a8-chan#15: Watching for funding txid: 055608f9ac3d2d3069a19ad07a4dcb31d3bd3dd925173f1a6c5350b18dcefa84
2024-03-21T00:02:57.077Z DEBUG   03c1c8eef8e86c4bdf61067cf7d33e82532dc371f703e24207101e70989d3034a8-lightningd: Will try reconnect in 1 seconds
2024-03-21T00:02:57.077Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-chan#4: Watching for funding txid: f18949a8a6985ffb6a1ffa4ba7bba62ee891ef15356c13064e9b5f8296a52c79
2024-03-21T00:02:57.077Z DEBUG   02f1a8c87607f415c8f22c00593002775941dea48869ce23096af27b0cfdcc0b69-lightningd: Will try reconnect in 2 seconds
2024-03-21T00:02:57.078Z DEBUG   03b279522ced2ccd9d2c7d1fc500d24f567129fc12b9495a076e30a2e861fffb1d-chan#16: Watching for funding txid: f736c8be9c6a6f8134b075f5b76016422462654cd3d8747a6ee15925ecb5a15a
2024-03-21T00:02:57.078Z DEBUG   03b279522ced2ccd9d2c7d1fc500d24f567129fc12b9495a076e30a2e861fffb1d-lightningd: Will try reconnect in 4 seconds
2024-03-21T00:02:57.078Z DEBUG   034cb28d896ef2ff25e2fbf5f6b524af3b5d9dc462272bf0620173d7d91b6559c9-chan#6: Watching for funding txid: 3953a2d07a99435e9ed03011e2da4c306bf473ee322cdad3af1304e4570c318c
2024-03-21T00:02:57.078Z DEBUG   034cb28d896ef2ff25e2fbf5f6b524af3b5d9dc462272bf0620173d7d91b6559c9-lightningd: Will try reconnect in 6 seconds
2024-03-21T00:02:57.078Z DEBUG   026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Watching for funding txid: 86ef7d15b6117e07537a7cadf26dd17d48e79c4c5cbd1ca4a0944d3566a25355
2024-03-21T00:02:57.078Z DEBUG   036af7ab4e7a929065414e52de5ca4c4d88b1dddaf8e1be261b1530e69d0f3693e-chan#14: Watching for funding txid: 499b3f31b62a9c79ba32c2805992a0dc54867a58065bc9b36d2f5e8eac249d40
2024-03-21T00:02:57.078Z DEBUG   036af7ab4e7a929065414e52de5ca4c4d88b1dddaf8e1be261b1530e69d0f3693e-lightningd: Will try reconnect in 10 seconds
2024-03-21T00:02:57.078Z DEBUG   03eaf4f94ad680855a7818c2f156ae4a86482dea2f396320c336989ce5f49da880-chan#7: Watching for funding txid: 4b3a864968697f2625a48f7115bf265c9f84699997d2d673d18964ac807fdf5f
2024-03-21T00:02:57.078Z DEBUG   03eaf4f94ad680855a7818c2f156ae4a86482dea2f396320c336989ce5f49da880-lightningd: Will try reconnect in 12 seconds
2024-03-21T00:02:57.272Z DEBUG   lightningd: Adding block 835387: 00000000000000000000e85174c561fd042c961d1e2f7ef241b217a9cfb4ead6
2024-03-21T00:02:57.526Z DEBUG   lightningd: Adding block 835388: 000000000000000000028ad7c164e44b5bfd29422027026a22aff95a58957cba
2024-03-21T00:02:57.662Z DEBUG   plugin-bcli: Log pruned 433 entries (mem 10492225 -> 4380503)
2024-03-21T00:02:57.742Z DEBUG   lightningd: Adding block 835389: 0000000000000000000156b78efca111c021778e0a58f11c561d0e731947edee
2024-03-21T00:02:57.997Z DEBUG   lightningd: Adding block 835390: 000000000000000000005d55276bdab0044e25ae890422972d34f2e456634b8d
2024-03-21T00:02:58.131Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
2024-03-21T00:02:58.166Z DEBUG   plugin-bcli: Log pruned 203 entries (mem 10490366 -> 2596313)
2024-03-21T00:02:58.253Z DEBUG   lightningd: Adding block 835391: 00000000000000000002e2002164799a1b6b96081c67002397c28bcb370a9800
2024-03-21T00:02:58.307Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
2024-03-21T00:02:58.495Z DEBUG   lightningd: Adding block 835392: 00000000000000000001c86c1e42b72c93b405c67ed6bab305ab4cd23c7ca796
2024-03-21T00:02:58.544Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
2024-03-21T00:02:58.605Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
2024-03-21T00:02:58.663Z DEBUG   plugin-bcli: Log pruned 151 entries (mem 10534526 -> 2454817)
2024-03-21T00:02:58.751Z DEBUG   lightningd: Adding block 835393: 0000000000000000000274ab2523cae8073e4c86cb2442acf9c500e54e471411
2024-03-21T00:02:58.799Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
2024-03-21T00:02:58.992Z DEBUG   lightningd: Adding block 835394: 000000000000000000004c11c8083e1e815b76d8ec4c98b5442e2bb8a0a3c8ca
2024-03-21T00:02:59.038Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
2024-03-21T00:02:59.038Z DEBUG   plugin-recover: Listpeerchannels called
2024-03-21T00:02:59.038Z DEBUG   plugin-recover: Detected a channel with lost state, Entering Recovery mode!
2024-03-21T00:02:59.039Z DEBUG   lightningd: channel 6aee31f3fe0da7ed3c710bc94fb044be91917801a9fdec5eddf85f365d9f0b2b already exists!
2024-03-21T00:02:59.039Z DEBUG   lightningd: channel 27664dc53ff4ce83d77fae9809bc8773755da10b02090b54ab627316dff3a65b already exists!
2024-03-21T00:02:59.039Z DEBUG   lightningd: channel fbdedc8deebc257b0c9417537ff77c1d60b72029026c28977cd360fc33b8d3fd already exists!
2024-03-21T00:02:59.041Z **BROKEN** lightningd: Error executing statement: wallet/wallet.c:2594: INSERT INTO channels (  peer_id, first_blocknum, id, revocation_basepoint_local, payment_basepoint_local, htlc_basepoint_local, delayed_payment_basepoint_local, funding_pubkey_local, require_confirm_inputs_remote, require_confirm_inputs_local) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: channels.id
2024-03-21T00:02:59.041Z **BROKEN** lightningd: Error executing statement: wallet/wallet.c:2594: INSERT INTO channels (  peer_id, first_blocknum, id, revocation_basepoint_local, payment_basepoint_local, htlc_basepoint_local, delayed_payment_basepoint_local, funding_pubkey_local, require_confirm_inputs_remote, require_confirm_inputs_local) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: channels.id
2024-03-21T00:02:59.075Z **BROKEN** lightningd: FATAL SIGNAL 6 (version v24.02)
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: common/daemon.c:38 (send_backtrace) 0x556ec94f9fe6
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: common/daemon.c:75 (crashdump) 0x556ec94fa035
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f5276ca004f
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f5276ceee2c
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f5276c9ffb1
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f5276c8a471
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/log.c:1025 (fatal_vfmt) 0x556ec94a7c37
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: wallet/db.c:1097 (db_error) 0x556ec94d9e55
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: db/utils.c:316 (db_fatal) 0x556ec9548efd
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: db/utils.c:190 (db_exec_prepared_v2) 0x556ec95492c1
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: wallet/wallet.c:2619 (wallet_channel_insert) 0x556ec94e424b
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/opening_control.c:1581 (json_recoverchannel) 0x556ec94aed17
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/jsonrpc.c:839 (command_exec) 0x556ec949fe0c
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/jsonrpc.c:982 (rpc_command_hook_final) 0x556ec94a298b
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/plugin_hook.c:247 (plugin_hook_call_) 0x556ec94cf162
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/jsonrpc.c:1070 (plugin_hook_call_rpc_command) 0x556ec94a2174
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/jsonrpc.c:1189 (parse_request) 0x556ec94a2174
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/jsonrpc.c:1295 (read_json) 0x556ec94a259e
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x556ec966a557
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x556ec966aa32
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x556ec966aacf
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: ccan/ccan/io/poll.c:453 (io_loop) 0x556ec966c46c
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers) 0x556ec949fd88
2024-03-21T00:02:59.075Z **BROKEN** lightningd: backtrace: lightningd/lightningd.c:1425 (main) 0x556ec94a5456
2024-03-21T00:02:59.076Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f5276c8b249
2024-03-21T00:02:59.076Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f5276c8b304
2024-03-21T00:02:59.076Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x556ec9479d64
2024-03-21T00:02:59.076Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0xffffffffffffffff
nakoshi-satamoto commented 7 months ago

My node ID is 038e5677dc7d1ec4e9a82bd004d524b2469fedb0867e85bd1e2f5d3352957e03b7 alias nakoshi-satamoto@posteo.net

nakoshi-satamoto commented 7 months ago

The first crashdump log file I am finding from today , crash.log.20240320221217 has ALOT of very large blocks of numbers after the entries jsonrpc#67IO_IN:

And then I get this in the end of the log file

+86.164710347 jsonrpc#67IO_IN: "recover:emergencyrecover#6/cln:emergencyrecover#44/chanbackup:recoverchannel#4"
+86.164748773 lightningdDEBUG: channel 6aee31f3fe0da7ed3c710bc94fb044be91917801a9fdec5eddf85f365d9f0b2b already exists!
+86.164757663 lightningdDEBUG: channel 27664dc53ff4ce83d77fae9809bc8773755da10b02090b54ab627316dff3a65b already exists!
+86.164764958 lightningdDEBUG: channel fbdedc8deebc257b0c9417537ff77c1d60b72029026c28977cd360fc33b8d3fd already exists!
+86.166025133 lightningdBROKEN: Error executing statement: wallet/wallet.c:2594: INSERT INTO channels (  peer_id, first_blocknum, id, revocation_basepoint_local, payment_basepoint_local, htlc_basepoint_local, delayed_payment_basepoint_local, funding_pubkey_local, require_confirm_inputs_remote, require_confirm_inputs_local) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: channels.id
+86.166130668 lightningdBROKEN: Error executing statement: wallet/wallet.c:2594: INSERT INTO channels (  peer_id, first_blocknum, id, revocation_basepoint_local, payment_basepoint_local, htlc_basepoint_local, delayed_payment_basepoint_local, funding_pubkey_local, require_confirm_inputs_remote, require_confirm_inputs_local) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: channels.id
+86.239775795 lightningdBROKEN: FATAL SIGNAL 6 (version v24.02)
+86.239831244 lightningdBROKEN: backtrace: common/daemon.c:38 (send_backtrace) 0x5646e19cafe6
+86.239847897 lightningdBROKEN: backtrace: common/daemon.c:75 (crashdump) 0x5646e19cb035
+86.239862803 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fee3bf7204f
+86.239878248 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fee3bfc0e2c
+86.239891614 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fee3bf71fb1
+86.239908035 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fee3bf5c471
+86.239922657 lightningdBROKEN: backtrace: lightningd/log.c:1025 (fatal_vfmt) 0x5646e1978c37
+86.239937494 lightningdBROKEN: backtrace: wallet/db.c:1097 (db_error) 0x5646e19aae55
+86.239953172 lightningdBROKEN: backtrace: db/utils.c:316 (db_fatal) 0x5646e1a19efd
+86.239967634 lightningdBROKEN: backtrace: db/utils.c:190 (db_exec_prepared_v2) 0x5646e1a1a2c1
+86.239983621 lightningdBROKEN: backtrace: wallet/wallet.c:2619 (wallet_channel_insert) 0x5646e19b524b
+86.240001919 lightningdBROKEN: backtrace: lightningd/opening_control.c:1581 (json_recoverchannel) 0x5646e197fd17
+86.240019036 lightningdBROKEN: backtrace: lightningd/jsonrpc.c:839 (command_exec) 0x5646e1970e0c
+86.240035240 lightningdBROKEN: backtrace: lightningd/jsonrpc.c:982 (rpc_command_hook_final) 0x5646e197398b
+86.240051331 lightningdBROKEN: backtrace: lightningd/plugin_hook.c:247 (plugin_hook_call_) 0x5646e19a0162
+86.240067735 lightningdBROKEN: backtrace: lightningd/jsonrpc.c:1070 (plugin_hook_call_rpc_command) 0x5646e1973174
+86.240085007 lightningdBROKEN: backtrace: lightningd/jsonrpc.c:1189 (parse_request) 0x5646e1973174
+86.240103772 lightningdBROKEN: backtrace: lightningd/jsonrpc.c:1295 (read_json) 0x5646e197359e
+86.240118341 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x5646e1b3b557
+86.240132772 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x5646e1b3ba32
+86.240148980 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x5646e1b3bacf
+86.240164578 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:453 (io_loop) 0x5646e1b3d46c
+86.240179043 lightningdBROKEN: backtrace: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers) 0x5646e1970d88
+86.240195353 lightningdBROKEN: backtrace: lightningd/lightningd.c:1425 (main) 0x5646e1976456
+86.240211916 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fee3bf5d249
+86.240225728 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7fee3bf5d304
+86.240238765 lightningdBROKEN: backtrace: (null):0 ((null)) 0x5646e194ad64
+86.240251401 lightningdBROKEN: backtrace: (null):0 ((null)) 0xffffffffffffffff
nakoshi-satamoto commented 7 months ago

greping my log file for that channel that forced closed (Boltz) grep 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29 ln-log.txt

I see this

024-03-20T01:46:34.941Z INFO 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208) 2024-03-20T01:49:39.948Z INFO 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208) 2024-03-20T01:53:54.907Z INFO 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208) 2024-03-20T03:42:17.419Z INFO 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (9) 2024-03-20T05:12:46.161Z INFO 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (9) 2024-03-20T22:12:15.330Z UNUSUAL 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Peer permanent failure in CHANNELD_NORMAL: channeld: sent Awaiting unilateral close 2024-03-20T22:12:15.330Z **BROKEN** 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Cannot broadcast our commitment tx: they have a future one 2024-03-20T22:12:15.330Z INFO 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: State changed from CHANNELD_NORMAL to AWAITING_UNILATERAL 2024-03-20T22:12:15.508Z **BROKEN** 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: gossipd rejected our channel update: Bad signature for [REDACTED THE DATA HERE FROM THIS LOG FILE IN CASE IF THIS WAS SENSITIVE INFO] 2024-03-20T22:15:19.894Z UNUSUAL 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: gossipd lost track of announced channel: re-announcing! 2024-03-20T22:15:19.968Z **BROKEN** 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Cannot broadcast our commitment tx: they have a future one 2024-03-20T22:18:03.199Z UNUSUAL 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: gossipd lost track of announced channel: re-announcing! 2024-03-20T22:18:03.279Z DEBUG 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Adding funding_spend_watch 2024-03-20T22:18:03.279Z **BROKEN** 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Cannot broadcast our commitment tx: they have a future one 2024-03-20T22:18:03.280Z DEBUG 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Watching for funding txid: 86ef7d15b6117e07537a7cadf26dd17d48e79c4c5cbd1ca4a0944d3566a25355 2024-03-20T22:19:46.909Z UNUSUAL 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: gossipd lost track of announced channel: re-announcing! 2024-03-20T22:19:46.981Z DEBUG 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Adding funding_spend_watch 2024-03-20T22:19:46.981Z **BROKEN** 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Cannot broadcast our commitment tx: they have a future one 2024-03-20T22:19:46.982Z DEBUG 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Watching for funding txid: 86ef7d15b6117e07537a7cadf26dd17d48e79c4c5cbd1ca4a0944d3566a25355 2024-03-20T22:20:52.864Z DEBUG 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Adding funding_spend_watch 2024-03-20T22:20:52.864Z **BROKEN** 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Cannot broadcast our commitment tx: they have a future one 2024-03-20T22:20:52.865Z DEBUG 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Watching for funding txid: 86ef7d15b6117e07537a7cadf26dd17d48e79c4c5cbd1ca4a0944d3566a25355 2024-03-20T22:28:05.525Z DEBUG 026165850492521f4ac8abd9bd8088123446d126f648ca35e60f88177dc149ceb2-chan#29: Adding funding_spend_watch

nakoshi-satamoto commented 7 months ago

Gossipd, channel with a lost state.

This is what stood out to me. I also don't know yet what caused the forced close. Maybe this is why lightningd won't start up?

Did I lose my funds?

cdecker commented 7 months ago

Ping @adi2011: this appears to be an issue with the recovery plugin, attempting to recover a channel as if it were fully forgotten, but the CLN node "just" lost state.

Generally speaking: if a node does not start, DO NOT tinker with the database unless told to. This includes up and downgrades.

Don't worry the funds should be save, and we just need to get the node running again. I'll let @adi2011 guide you through the steps, but I'll note that we can get you unstuck by adding --disable-plugin=recovery to the command line ;-)

If you could take a snapshot of the DB (not the hsm_secret file), we can get you unstuck while still retaining the ability to debug offline and fix it for other users too.

cdecker commented 7 months ago

As for things currently in flight, only channel 29 is at risk of closure, as it is the only one with an HTLC attached.

nakoshi-satamoto commented 7 months ago

Thank you cdecker. High respect. I am at computer for the rest of the day. I have made a snapshot of my .lightning\bitcoin directory, I also started it up with the command .\lightningd --disable-plugin=recover (not recovery).

After I get this resolved, I might continue operating a clightning node having peace of mind knowing what to do next time if this happens again.

For that forced close chan 831793x2527x0 I see this now

{ "timestamp": "2024-03-20T22:12:15.335Z", "old_state": "CHANNELD_NORMAL", "new_state": "AWAITING_UNILATERAL", "cause": "local", "message": "channeld: sent Awaiting unilateral close"

and then an htcl direction in with state "RCVD_REMOVE_REVOCATION"

Just let me know what I should check or try out now if you could. I'll follow your instructions. Thank you very much.

nakoshi-satamoto commented 7 months ago

I stopped my lightning node now to keep it offline, to await further instruction @cdecker @adi2011

nakoshi-satamoto commented 7 months ago

For that forced close chan I do see cause set to "local" does that indicate that it was my node that initiated the forced close? So strange. Anyways, I am able to start up lightningd but only when the recover plugin is set to disabled. I have also since been using the --offline flag as well in caution.

cdecker commented 7 months ago

I think that already means we're past the problem, it was just the recover plugin crashing due to a misidentified missing channel. You should be able to just run the node normally now.

nakoshi-satamoto commented 7 months ago

What do you suggest? When I attempt to start it up normally again it crashes again like it did earlier. I can only start it up when I set recover plugin to disabled.

nakoshi-satamoto commented 7 months ago

I do have a backup of accounts.sqlite3 and emergency.recover from before these issues, if that is helpful at all.

nakoshi-satamoto commented 7 months ago

email from boltz:

We force closed you:

2024-03-20 22:12:13.495 [ERR] HSWC: ChannelLink([REDACTED INFO]:0): failing link: unable to synchronize channel states: possible remote commitment state data loss with error: sync error

2024-03-20 22:12:13.495 [WRN] HSWC: ChannelLink([REDACTED INFO]:0): error when syncing channel states: possible remote commitment state data loss

2024-03-20 22:12:13.495 [ERR] LNWL: ChannelPoint([REDACTED INFO]:0): sync failed: remote's next commit height is 65391, while we believe it is 65392!

When looking at the close transaction (https://mempool.space/tx/e6df69daa0eefd910d871601bbf0e78e838b6396c79601a28dbbf31bb8312591) and our nodes view, we'll get ~3.2m and you ~8.3m sats. It's force close, not a penalty, so you are all good. We'll just need to wait ~112 blocks and the funds will be back in our wallet.

Let me know if the CLN team needs our logs for that channel to debug your crash.

I replaced parts with [REDACTED INFO]

nakoshi-satamoto commented 7 months ago

When I run ./lightning-cli listpeers I see "lost_state": true only for that channel that forced closed. The rest show false for lost state.

  1. Am I able to recover my funds from this unilateral close, even with this lost channel state and inability to startup lightningd unless I disable the recover plugin?

  2. After I recover the funds, any ideas on how I can restore functionality? I think it is this one channel that is breaking the recover plugin from operating normally.

nakoshi-satamoto commented 7 months ago

Update

TL;DR summary = My lightning router eventually forgot this channel that was forced closed, in which I was then able to start up lightningd normally again. I still need help recovering funds from the unilateral close transaction

I started up lightningd with the recover plugin disabled

I then reconnected to the peer that forced closed the chan (boltz).

I then saw my 8.3 million sats from the forced channel closure listed as "onchain". But I cannot access these funds because I think lightning needs to claim it. I did load my nodes private keys into sparrow wallet with proper derivation path and I do not see funds in there. From my experience with unilateral closures lightning needs to see the unilateral close transaction t then execute some script to sweep the funds to one of its onchain addresses.

I restarted lightningd again with the recover plugin disabled and let it catch up with the blockchain.

After catching up with the blockchain I restarted lightningd again with the recover plugin disabled, I then saw that the problem channel (that forced closed) was forgotten by lightning.

I restarted lightningd again normally (not disabling the recover plugin). That problem channel is indeed forgotten by my node thus enabling lightningd to start up normally again.

However what remains, I need to recover my sats from that forced channel closure. I see this when I type ./lightning-cli listfunds

{ "txid": "e6df69daa0eefd910d871601bbf0e78e838b6396c79601a28dbbf31bb8312591", "output": 1, "amount_msat": 8387232000, "scriptpubkey": "[REDACTED INFO]", "address": "bc1q8s5ay4093kwx9ln0yntcckuapxnp3ngmr5l6s3", "status": "confirmed", "blockheight": 835578, "reserved": false } I replaced the scrippubkey with REDACTED INFO in case if that is sensitive information.

How do I claim these though from that unilateral close? I do not see these funds in my wallet. Will lightning sweep these funds after some delayed output? Or are these funds lost because lightning lost the state of this channel? Is the delayed output the peers delayed output of I think 144 blocks or my delayed output of what I think was around 1400 blocks?

nakoshi-satamoto commented 7 months ago

I was able to withdraw all funds including the ones from the forced channel closure by using the command ./lightning-cli withdraw [destination] all urgent

Not sure why it was not showing up in sparrow wallet, but my funds are returned. Core Lightning remains solid!

If anyone experiences an issue like I did, the solution is to start up the node with the recover plugin disabled, use the listpeers command to look at the lost_state field to see which channel is causing the problems, reconnect to that node if it is disconnected. Restart lightningd again with the recover plugin disabled, let it catch up with the blockchain. Restart lightningd again with the recover plugin disabled to see if that problem channel is corrected or forgotten. Once the channel state is corrected or forgotten you should then be able to restart lightningd again normally without having to disable the recover plugin. All these steps might be unnecessary, I just am documenting the steps I took to resolve.

Now, why this chan forced closed I don't know. Maybe it was because my computer crashed and something goofed up somewhere. You can close this out, or if someone wants to keep this open to investigate further I will co-operate in investigating what went wrong if needed. Thanks

cdecker commented 7 months ago

Am I able to recover my funds from this unilateral close, even with this lost channel state and inability to startup lightningd unless I disable the recover plugin?

Yes, CLN supports the option_upfront_shutdown which specifies a refund address from your wallet. The spec used to mandate rotating keys, but we have since removed that requirement, exactly due to the loss potential here.

We also support option_dataloss_protection, which will ask the peer to close the channel if we detect that we lost data (which sounds like your scenario).

After I recover the funds, any ideas on how I can restore functionality? I think it is this one channel that is breaking the recover plugin from operating normally.

You can always start without the recover plugin until the underlying crash issue has been addressed. After a couple of days you should forget the channel, and you can re-enable the recover plugin without risking triggering it again afaik.

cdecker commented 7 months ago

I rephrased the issue now that the funds are back, and we want to address the underlying issue.

adi2011 commented 7 months ago

So the issue is that we were trying to insert a channel (in the db) at the same 'id' which is already preoccupied, and all this happens while running the rpc recoverchannel.

We have a check inside recoverchannel to see if the channel already exists in the DB using find_channel_by_id(peer, &cid) and when this returns true, it logs "channel < ChannelId > already exists!" which it did for 3 channels but not this one.

Hence the possible reasons for this could be:

  1. That the Database had a different channel at the same index.

    • This would happen in the case when the emergency.recover file used is an older file i.e. Some channels have been closed/opened after the last backup of this file. This case seems less probable, @nakoshi-satamoto can you please confirm if this is the case?
  2. For some reason find_channel_by_id(peer, &cid) could not detect the channel because it was not loaded inside peer struct.

nakoshi-satamoto commented 7 months ago

@adi2011 I have not done anything with the emergency.recover file.

Also, this happened again today. Last time and this time it happened it was when my computer turned off from a system crash or froze up forcing me to do a hard reboot. I have noticed that my computer only has these issues of crashing when I run elementsqt, which is the gui for liquid the bitcoin sidechain, elementsd (non GUI) works fine.

Today I found my computer was turned off, probably from a system crash. When I started it up again, I let bitcoin core fully sync to latest block then I started up lightningd and these same issues occured. I also noticed that this also caused another channel to unilaterally close on me. Both last time and this time when my computer crashed it caused a channel to unilaterlaly close and the lightningd to not start up unless I disable the recover plugin. This is the second time in a few days where this has happened and my node having a channel die as a result, and where I can only start with the recover plugin disabled. The last time I was able to start it normally after that killed channel was forgotten.

It might also be helpful to know, that these issues started with version 24.02, the first case documented in this issue was on version 24.02, the second incident, the one from today is on version 24.02.01. This is also the first time I've seen channels unilaterally close when my system crashes. In the past before version 24 when my system crashes I am able to start up lightningd normally and with retaining channels.

Steps taken:

  1. started normally, lightningd crashed like what I documented here.
  2. I started up with recover plugin disabled
  3. I let lightningd catch up with the blocks
  4. started normally, error came up again and lightningd crashed
  5. I started up with recover plugin disabled and it was catching up with blocks again, or it was not fully caught up and was finishing catching up.
  6. started normally, got the errors again and lightningd crashed
  7. I started up lightningd with recover plugin disabled. It is currently only working when recover plugin is disabled. I do see that forced close chan is still being remembered by lightningd and says it is waiting 69 more blocks before forgetting channel.

I plan to see if lightningd starts up again normally later once that chan is forgotten.

In summary: So for some reason, a system crash is causing a channel to unilaterally close and when I start up lightningd after a unilateral close the recover plugin freaks out and lightningd crashes. Some questions:

  1. is it safe for me to run lightningd with the recover plugin disabled?
  2. does lightningd resync with recent blocks every time it is started up? If so maybe it is during this period that the recover plugin sees things not up to date and crashes before it has a chance for blocks to catch up
  3. Theory, maybe recover plugin is also crashing until the problem channel is forgotten? I'll test this later on today and can report back.
nakoshi-satamoto commented 7 months ago

Adding to my last post, I checked the sha256 hash of my emergency.recover file and it is the same as the one in my backup from before issues, so that verifies that the emergency.recover file was not changed since my last backup.

nakoshi-satamoto commented 7 months ago

After the channel was forgotten by lightning, I was able to start it up normally without needing to disable the recover plugin

adi2011 commented 7 months ago

Hi @nakoshi-satamoto, I think the issue is because peer->channels doesn't hold closed channels and due to this the recover plugin is trying to stub a channel inside the db at an already preoccupied space, which leads it to crashing.

Answering to your questions:

  1. is it safe for me to run lightningd with the recover plugin disabled? => In your case it might be a good idea to disable recover plugin otherwise it'd try to stub channels at already closed channel positions.

  2. does lightningd resync with recent blocks every time it is started up? If so maybe it is during this period that the recover plugin sees things not up to date and crashes before it has a chance for blocks to catch up. => The problem (from what i could figure looking at the logs) is because your node entered the recovery mode and it tries to recover the node through the emergency.recover file

  3. Theory, maybe recover plugin is also crashing until the problem channel is forgotten? I'll test this later on today and can report back. => Once the channel is forgotten it gets removed and everything works fine.

adi2011 commented 7 months ago

BTW is it still throwing **BROKEN** lightningd: Error executing statement: wallet/wallet.c:2594: INSERT INTO channels ( peer_id, first_blocknum, id, revocation_basepoint_local, payment_basepoint_local, htlc_basepoint_local, delayed_payment_basepoint_local, funding_pubkey_local, require_confirm_inputs_remote, require_confirm_inputs_local) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: channels.id while crashing?

nakoshi-satamoto commented 7 months ago

I was travelling pardon my delayed response. I have not had that issue ever since I did the steps I described above. It starts up normally now and without needing to disable the recover plugin.

adi2011 commented 6 months ago

It means, your DB forgot the channel which was having unique ID constraints. Do you have the snapshot of the DB from the point when it was throwing the error?

adi2011 commented 5 months ago

This should be resolved now... @nakoshi-satamoto Pls do lmk if the DB error still persists.

vincenzopalazzo commented 5 months ago

Fixed in https://github.com/ElementsProject/lightning/pull/7216