ElementsProject / lightning

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

bkpr-inspect crashing plugin, perhaps related to multifundchannel use #6800

Closed harvhat closed 2 months ago

harvhat commented 1 year ago

Issue and Steps to Reproduce

Of my 12 channels 4 for them crash plugin-bookkeeper when attempting to run

lightning-cli bkpr-inspect <peer_id>

Perhaps of note (or not) multifundchannel was used to fund these channels in two transactions, each transaction only has 1 channel that isn't crashing bkpr-inspect. Also all my channels funded singularly using fundchannel aren't causing issues.

2023-10-22T07:42:18.636Z INFO    plugin-clnrest.py: Killing plugin: disabled itself: No module named 'gunicorn'
2023-10-22T07:42:19.262Z INFO    plugin-backup.py: root        : Comparing backup version 133779 versus first write version 133780
2023-10-22T07:42:19.262Z INFO    plugin-backup.py: Comparing backup version 133779 versus first write version 133780
2023-10-22T07:42:19.262Z INFO    plugin-backup.py: root        : Versions match up
2023-10-22T07:42:19.262Z INFO    plugin-backup.py: Versions match up
2023-10-22T07:42:21.853Z INFO    connectd: Static Tor service onion address: "wor65jgzyeqkxawsyag7uknykt5aszf2zsaajyu6oppworz4jk5ygwid.onion:9736,127.0.0.1:9736" bound from extern port 9736 
2023-10-22T07:42:21.910Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2023-10-22T07:42:35.912Z INFO    lightningd: --------------------------------------------------
2023-10-22T07:42:35.912Z INFO    lightningd: Server started with public key 02cce866b659a12f14e29efccc3c240eaa16bfee3c763bdfddc9808244738c4cb3, alias StreamPipe (color #4aff00) and lightningd v23.08.1
2023-10-22T07:44:40.212Z INFO    02453e4e93322d60219808c00c2e6d1f1c673420e95b5511a33c40cfb4df5e9148-channeld-chan#15: Peer connection lost
2023-10-22T07:44:40.214Z INFO    02453e4e93322d60219808c00c2e6d1f1c673420e95b5511a33c40cfb4df5e9148-chan#15: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-10-22T07:44:40.215Z INFO    03ae9f91a0cb8ff43840e3c322c4c61f019d8c1c3cea15a25cfc425ac605e61a4a-channeld-chan#14: Peer connection lost
2023-10-22T07:44:40.215Z INFO    03ae9f91a0cb8ff43840e3c322c4c61f019d8c1c3cea15a25cfc425ac605e61a4a-chan#14: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-10-22T07:44:40.216Z INFO    03ecb3ee55ba6324d40bea174de096dc9134cb35d990235723b37ae9b5c49f4f53-channeld-chan#19: Peer connection lost
2023-10-22T07:44:40.216Z INFO    03ecb3ee55ba6324d40bea174de096dc9134cb35d990235723b37ae9b5c49f4f53-chan#19: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-10-22T07:44:40.216Z INFO    03ba0dc26e137f7fc5406908aaf614807cde5010a56b39973d68377fb0aa77e5d5-channeld-chan#2: Peer connection lost
2023-10-22T07:44:40.216Z INFO    03ba0dc26e137f7fc5406908aaf614807cde5010a56b39973d68377fb0aa77e5d5-chan#2: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-10-22T07:44:40.218Z INFO    024bfaf0cabe7f874fd33ebf7c6f4e5385971fc504ef3f492432e9e3ec77e1b5cf-channeld-chan#6: Peer connection lost
2023-10-22T07:44:40.219Z INFO    024bfaf0cabe7f874fd33ebf7c6f4e5385971fc504ef3f492432e9e3ec77e1b5cf-chan#6: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-10-22T07:44:40.220Z INFO    031240c4973c2687b5295a9bcae10539a4f2e51d35fd5689734bff2c6819629e3d-channeld-chan#1: Peer connection lost
2023-10-22T07:44:40.220Z INFO    031240c4973c2687b5295a9bcae10539a4f2e51d35fd5689734bff2c6819629e3d-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-10-22T08:04:36.962Z INFO    031240c4973c2687b5295a9bcae10539a4f2e51d35fd5689734bff2c6819629e3d-channeld-chan#1: Peer connection lost
2023-10-22T08:04:36.963Z INFO    031240c4973c2687b5295a9bcae10539a4f2e51d35fd5689734bff2c6819629e3d-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2023-10-22T08:04:46.247Z INFO    plugin-bookkeeper: Killing plugin: exited during normal operation
2023-10-22T08:04:46.248Z **BROKEN** plugin-bookkeeper: Plugin marked as important, shutting down lightningd!

getinfo output

{
   "id": "02cce866b659a12f14e29efccc3c240eaa16bfee3c763bdfddc9808244738c4cb3",
   "alias": "StreamPipe",
   "color": "4aff00",
   "num_peers": 12,
   "num_pending_channels": 0,
   "num_active_channels": 12,
   "num_inactive_channels": 0,
   "address": [
      {
         "type": "torv3",
         "address": "wor65jgzyeqkxawsyag7uknykt5aszf2zsaajyu6oppworz4jk5ygwid.onion",
         "port": 9736
      }
   ],
   "binding": [
      {
         "type": "ipv4",
         "address": "127.0.0.1",
         "port": 9736
      }
   ],
   "version": "v23.08.1",
   "blockheight": 813312,
   "network": "bitcoin",
   "fees_collected_msat": 1422599,
   "lightning-dir": "/home/bitcoin/.lightning/bitcoin",
   "our_features": {
      "init": "08a0000a0269a2",
      "node": "88a0000a0269a2",
      "channel": "",
      "invoice": "02000002024100"
   }
}
harvhat commented 1 year ago

I've open another set of three channels using multifundchannel and again bkpr-inspect works for only one of them, crashing lightningd on the other two. In this case and the previous two cases referred to above the channel that works is the last one listed in the accounts table in the sqlite3 db.

harvhat33 commented 11 months ago

If anyone actually cares about this bug it is reproducable on regtest (using the account_id not the peer_id as that was a typo in the OP)

source contrib/startup_regtest.sh
start_ln 4
connect 1 2
connect 1 3
connect 1 4
fund_nodes
l1-cli listpeerchannels
l1-cli close 03c21776dbf44a0f2ef1a58742056d5fe09dbab60a054a18c5ac18dfc1d3300115
bitcoin-cli -datadir="$PATH_TO_BITCOIN" -regtest generatetoaddress 5 "$ADDRESS"
l1-cli listfunds
l1-cli listpeers
l1-cli multifundchannel '[{"id":"03c21776dbf44a0f2ef1a58742056d5fe09dbab60a054a18c5ac18dfc1d3300115","amount":"100000sat"},{"id":"02f081f38929a054740c1bc107dc026e306ecced49c57926c483ef5ee07a2d2de2","amount":"200000sat"},{"id":"03b01a79afd28b80a16350c07fb0880f57e859b718de794ce77684e88c4827213f","amount":"300000sat"}]'
bitcoin-cli -datadir="$PATH_TO_BITCOIN" -regtest generatetoaddress 100 "$ADDRESS"
l1-cli listfunds
l1-cli bkpr-listbalances
{
   "accounts": [
      {
         "account": "wallet",
         "balances": [
            {
               "balance_msat": 99399429000,
               "coin_type": "bcrt"
            }
         ]
      },
      {
         "account": "582224f6b7678c7239142f1dc3428e60c36ad0a2cbac2e81134f6a7b40d55f09",
         "peer_id": "03c21776dbf44a0f2ef1a58742056d5fe09dbab60a054a18c5ac18dfc1d3300115",
         "we_opened": true,
         "account_closed": true,
         "account_resolved": true,
         "resolved_at_block": 124,
         "balances": [
            {
               "balance_msat": 0,
               "coin_type": "bcrt"
            }
         ]
      },
      {
         "account": "cda9bf1ff902298a9d81beb4445ae74527cac776a204acc32cc603479e00eeac",
         "peer_id": "03c21776dbf44a0f2ef1a58742056d5fe09dbab60a054a18c5ac18dfc1d3300115",
         "we_opened": true,
         "account_closed": false,
         "account_resolved": false,
         "balances": [
            {
               "balance_msat": 100000000,
               "coin_type": "bcrt"
            }
         ]
      },
      {
         "account": "7f6a8c3fc87ae04eca9b4220a85493ae6937da6fd0469f237960a3a9a911d235",
         "peer_id": "02f081f38929a054740c1bc107dc026e306ecced49c57926c483ef5ee07a2d2de2",
         "we_opened": true,
         "account_closed": false,
         "account_resolved": false,
         "balances": [
            {
               "balance_msat": 200000000,
               "coin_type": "bcrt"
            }
         ]
      },
      {
         "account": "2a8e270c03c7d8d806eb7263b5198aa4c6f7b125365869252c5639062ee43f50",
         "peer_id": "03b01a79afd28b80a16350c07fb0880f57e859b718de794ce77684e88c4827213f",
         "we_opened": true,
         "account_closed": false,
         "account_resolved": false,
         "balances": [
            {
               "balance_msat": 300000000,
               "coin_type": "bcrt"
            }
         ]
      }
   ]
}
l1-cli bkpr-inspect 582224f6b7678c7239142f1dc3428e60c36ad0a2cbac2e81134f6a7b40d55f09
{ ...snip... normal listing showed up here ...}
l1-cli bkpr-inspect cda9bf1ff902298a9d81beb4445ae74527cac776a204acc32cc603479e00eeac
bookkeeper: plugins/bkpr/recorder.c:365: find_account_onchain_fees: Assertion `ok' failed.
bookkeeper: FATAL SIGNAL 6 (version v23.11-1-g84f2206)
0x564449abccbb send_backtrace
    common/daemon.c:33
0x564449abcd43 crashdump
    common/daemon.c:75
0x7f7389c0efcf ???
    ./signal/../sysdeps/unix/sysv/linux/x86_64/libc_sigaction.c:0
0x7f7389c5dd3c __pthread_kill_implementation
    ./nptl/pthread_kill.c:44
0x7f7389c0ef31 __GI_raise
    ../sysdeps/posix/raise.c:26
0x7f7389bf9471 __GI_abort
    ./stdlib/abort.c:79
0x7f7389bf9394 __assert_fail_base
    ./assert/assert.c:92
0x7f7389c07e31 __GI___assert_fail
    ./assert/assert.c:101
0x564449aa7e0d find_account_onchain_fees
    plugins/bkpr/recorder.c:365
0x564449aa2d40 json_inspect
    plugins/bkpr/bookkeeper.c:259
0x564449aadc4d ld_command_handle
    plugins/libplugin.c:1645
0x564449aade49 ld_read_json_one
    plugins/libplugin.c:1721
0x564449aaded9 ld_read_json
    plugins/libplugin.c:1741
0x564449bf073c next_plan
    ccan/ccan/io/io.c:59
0x564449bf0bc3 do_plan
    ccan/ccan/io/io.c:407
0x564449bf0c5c io_ready
    ccan/ccan/io/io.c:417
0x564449bf24b9 io_loop
    ccan/ccan/io/poll.c:453
0x564449aae537 plugin_main
    plugins/libplugin.c:1948
0x564449aa3874 main
    plugins/bkpr/bookkeeper.c:1849
0x7f7389bfa1c9 __libc_start_call_main
    ../sysdeps/nptl/libc_start_call_main.h:58
0x7f7389bfa284 __libc_start_main_impl
    ../csu/libc-start.c:360
0x564449a9da10 ???
    ???:0
0xffffffffffffffff ???
    ???:0
bookkeeper: FATAL SIGNAL 11 (version v23.11-1-g84f2206)
0x564449abccbb send_backtrace
    common/daemon.c:33
0x564449abcd43 crashdump
    common/daemon.c:75
0x7f7389c0efcf ???
    ./signal/../sysdeps/unix/sysv/linux/x86_64/libc_sigaction.c:0
0x0 ???
    ???:0
{
   "code": -4,
   "message": "Plugin terminated before replying to RPC call."
}
vincenzopalazzo commented 11 months ago

cc @niftynei 😄

niftynei commented 10 months ago

@evansmj and I were able to reproduce and debug, patch incoming; tldr there's a SQL command that's grouping on the wrong thing and causing a crash.

Good news is all your data is/should be correct, just need a software update to be able to see it without crashing.

evansmj commented 10 months ago

ready for review ^

evansmj commented 6 months ago

@harvhat @harvhat33 A fix has been merged to v24.02, just wondering if this has resolved your issue?

niftynei commented 2 months ago

Closing this as resolved until further notice.