search

ElementsProject / lightning

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

Offers Fatal Signal on startup with --experimental-offers and a node doing IBD #7378

Closed farscapian closed 14 hours ago

farscapian commented 1 week ago

Issue and Steps to Reproduce

I am running lnplay. This issue only occurs on my image running 24.05 with bitcoind 27. (issue does not appear when running based on v24.02.2.) CLN is running with --experimental-offers. This issue only occurs when bitcoind is not fully synced. So this occurs on signet and mainnet during IBD. lightnignd does appear to stabilize, but the logging output is concerning.

getinfo output

{
   "id": "02797854612ee2908b2316f97d5a09b0b85da0ccacaad215aaf9e85874f8e898d9",
   "alias": "Alice",
   "color": "ffffff",
   "num_peers": 0,
   "num_pending_channels": 0,
   "num_active_channels": 0,
   "num_inactive_channels": 0,
   "address": [
      {
         "type": "ipv4",
         "address": "127.0.0.1",
         "port": 9735
      }
   ],
   "binding": [
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 9735
      }
   ],
   "version": "v24.05-modded",
   "blockheight": 11755,
   "network": "signet",
   "fees_collected_msat": 0,
   "lightning-dir": "/root/.lightning/signet",
   "warning_bitcoind_sync": "Bitcoind is not up-to-date with network.",
   "our_features": {
      "init": "080000000000000000000000000008aa882a8a59a1",
      "node": "080000000000000000000000000088aa882a8a59a1",
      "channel": "",
      "invoice": "02000002024100"
   }
}

lightningd logging output

The issue is some offer-related assertion related to blockheight. The last line in the output indicates that lightningd is shutting down, but lightning does in fact continue to run (which is how I'm able to get getinfo above).

2024-06-07T14:14:29.278Z INFO    lightningd: v24.05-modded
2024-06-07T14:14:37.158Z INFO    lightningd: v24.05-modded
2024-06-07T14:14:29.329Z INFO    lightningd: Creating configuration directory /root/.lightning/signet
2024-06-07T14:14:37.589Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2024-06-07T14:14:29.715Z INFO    lightningd: Creating database
2024-06-07T14:14:37.591Z UNUSUAL lightningd: Waiting for initial block download (this can take a while!)
2024-06-07T14:14:29.752Z UNUSUAL hsmd: HSM: created new hsm_secret file
2024-06-07T14:14:37.603Z INFO    plugin-reckless-wrapper.py: initializing reckless-wrapper.py.
2024-06-07T14:14:29.798Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2024-06-07T14:14:29.802Z UNUSUAL lightningd: Waiting for initial block download (this can take a while!)
offers: plugins/offers.c:1235: init: Assertion `blockheight' failed.
2024-06-07T14:14:29.814Z INFO    plugin-reckless-wrapper.py: initializing reckless-wrapper.py.
offers: FATAL SIGNAL 6 (version v24.05-modded)
0x57ab55a56485 send_backtrace
2024-06-07T14:14:29.818Z INFO    plugin-chanbackup: Creating Emergency Recovery
   common/daemon.c:33
offers: plugins/offers.c:1235: init: Assertion `blockheight' failed.
offers: FATAL SIGNAL 6 (version v24.05-modded)
0x57ab55a5650d crashdump
   common/daemon.c:75
0x59f3ed3ba485 send_backtrace
0x7dd20b02213f ???
   common/daemon.c:33
   ???:0
0x59f3ed3ba50d crashdump
0x7dd20ae59ce1 ???
   common/daemon.c:75
   ???:0
0x7dd20ae43536 ???
0x764fa583813f ???
   ???:0
0x7dd20ae4340e ???
   ???:0
0x7dd20ae52661 ???
   ???:0
   ???:0
0x57ab55a3effe init
   plugins/offers.c:1235
0x764fa566fce1 ???
0x57ab55a4763f handle_init
   ???:0
   plugins/libplugin.c:1376
0x57ab55a478ee ld_command_handle
0x764fa5659536 ???
   plugins/libplugin.c:1797
0x57ab55a47ec0 ld_read_json_one
   plugins/libplugin.c:1979
   ???:0
0x57ab55a47f49 ld_read_json
0x764fa565940e ???
   plugins/libplugin.c:1999
   ???:0
0x57ab55b934cc next_plan
0x764fa5668661 ???
   ccan/ccan/io/io.c:60
   ???:0
0x57ab55b93953 do_plan
0x59f3ed3a2ffe init
   ccan/ccan/io/io.c:408
   plugins/offers.c:1235
0x57ab55b939ec io_ready
   ccan/ccan/io/io.c:418
0x59f3ed3ab63f handle_init
0x57ab55b95302 io_loop
   plugins/libplugin.c:1376
   ccan/ccan/io/poll.c:455
0x59f3ed3ab8ee ld_command_handle
0x57ab55a486dc plugin_main
   plugins/libplugin.c:1797
   plugins/libplugin.c:2209
0x59f3ed3abec0 ld_read_json_one
0x57ab55a3f36d main
   plugins/libplugin.c:1979
   plugins/offers.c:1285
0x59f3ed3abf49 ld_read_json
0x7dd20ae44d09 ???
   plugins/libplugin.c:1999
   ???:0
0x59f3ed4f74cc next_plan
0x57ab55a3c799 ???
   ccan/ccan/io/io.c:60
0x59f3ed4f7953 do_plan
   ???:0
   ccan/ccan/io/io.c:408
0xffffffffffffffff ???
0x59f3ed4f79ec io_ready
   ccan/ccan/io/io.c:418
   ???:0
offers: FATAL SIGNAL 11 (version v24.05-modded)
0x59f3ed4f9302 io_loop
   ccan/ccan/io/poll.c:455
0x57ab55a56485 send_backtrace
0x59f3ed3ac6dc plugin_main
   common/daemon.c:33
   plugins/libplugin.c:2209
0x57ab55a5650d crashdump
0x59f3ed3a336d main
   plugins/offers.c:1285
   common/daemon.c:75
0x7dd20b02213f ???
0x764fa565ad09 ???
   ???:0
   ???:0
0x59f3ed3a0799 ???
0x0 ???
   ???:0
   ???:0
2024-06-07T14:14:37.734Z INFO    plugin-offers: Killing plugin: exited before replying to init
0xffffffffffffffff ???
   ???:0
2024-06-07T14:14:37.734Z **BROKEN** plugin-offers: Plugin marked as important, shutting down lightningd!
offers: FATAL SIGNAL 11 (version v24.05-modded)
0x59f3ed3ba485 send_backtrace
   common/daemon.c:33
0x59f3ed3ba50d crashdump
   common/daemon.c:75
0x764fa583813f ???
   ???:0
0x0 ???
   ???:0
2024-06-07T14:14:29.823Z INFO    plugin-bookkeeper: Creating database
2024-06-07T14:14:29.883Z INFO    plugin-offers: Killing plugin: exited before replying to init
2024-06-07T14:14:29.883Z **BROKEN** plugin-offers: Plugin marked as important, shutting down lightningd!
vincenzopalazzo commented 1 week ago

The crash looks like similar to this https://github.com/vincenzopalazzo/lampo.rs/issues/217

I will try to look at it in this week

vincenzopalazzo commented 1 week ago

Looking at the code, and open a patch https://github.com/ElementsProject/lightning/pull/7379

Idk you env, but in the lampo case, I just mined 100 blocks :) but lets see if the patch lands

theborakompanioni commented 6 days ago

Just fyi.. same here! In regtest on IBD.

Temporarily fixed by --disable-plugin=offers!

Logs:

2024-06-11T03:52:26.850Z INFO    lightningd: v24.05-modded
2024-06-11T03:52:26.943Z INFO    lightningd: Creating configuration directory /home/clightning/.lightning/regtest
2024-06-11T03:52:26.948Z DEBUG   plugin-manager: started(80) /usr/local/libexec/c-lightning/plugins/autoclean
2024-06-11T03:52:26.952Z DEBUG   plugin-manager: started(83) /usr/local/libexec/c-lightning/plugins/chanbackup
2024-06-11T03:52:26.956Z DEBUG   plugin-manager: started(84) /usr/local/libexec/c-lightning/plugins/bcli
2024-06-11T03:52:26.960Z DEBUG   plugin-manager: started(85) /usr/local/libexec/c-lightning/plugins/commando
2024-06-11T03:52:26.964Z DEBUG   plugin-manager: started(86) /usr/local/libexec/c-lightning/plugins/fetchinvoice
2024-06-11T03:52:26.968Z DEBUG   plugin-manager: started(87) /usr/local/libexec/c-lightning/plugins/funder
2024-06-11T03:52:26.971Z DEBUG   plugin-manager: started(88) /usr/local/libexec/c-lightning/plugins/topology
2024-06-11T03:52:26.974Z DEBUG   plugin-manager: started(89) /usr/local/libexec/c-lightning/plugins/keysend
2024-06-11T03:52:26.978Z DEBUG   plugin-manager: started(90) /usr/local/libexec/c-lightning/plugins/offers
2024-06-11T03:52:26.981Z DEBUG   plugin-manager: started(91) /usr/local/libexec/c-lightning/plugins/pay
2024-06-11T03:52:26.984Z DEBUG   plugin-manager: started(92) /usr/local/libexec/c-lightning/plugins/recover
2024-06-11T03:52:26.986Z DEBUG   plugin-manager: started(93) /usr/local/libexec/c-lightning/plugins/txprepare
2024-06-11T03:52:26.989Z DEBUG   plugin-manager: started(94) /usr/local/libexec/c-lightning/plugins/cln-renepay
2024-06-11T03:52:26.992Z DEBUG   plugin-manager: started(95) /usr/local/libexec/c-lightning/plugins/spenderp
2024-06-11T03:52:26.995Z DEBUG   plugin-manager: started(96) /usr/local/libexec/c-lightning/plugins/sql
2024-06-11T03:52:26.997Z DEBUG   plugin-manager: started(97) /usr/local/libexec/c-lightning/plugins/cln-grpc
2024-06-11T03:52:27.001Z DEBUG   plugin-manager: started(99) /usr/local/libexec/c-lightning/plugins/bookkeeper
2024-06-11T03:52:27.004Z DEBUG   plugin-manager: started(100) /usr/local/libexec/c-lightning/plugins/clnrest/clnrest
2024-06-11T03:52:27.008Z DEBUG   plugin-manager: started(101) /usr/local/libexec/c-lightning/plugins/wss-proxy/wss-proxy
2024-06-11T03:52:27.370Z DEBUG   lightningd: io_break: check_plugins_manifests
2024-06-11T03:52:27.370Z DEBUG   lightningd: io_loop_with_timers: plugins_init
2024-06-11T03:52:27.371Z DEBUG   lightningd: testing /usr/local/libexec/c-lightning/lightning_channeld
2024-06-11T03:52:27.372Z DEBUG   lightningd: testing /usr/local/libexec/c-lightning/lightning_closingd
2024-06-11T03:52:27.373Z DEBUG   lightningd: testing /usr/local/libexec/c-lightning/lightning_connectd
2024-06-11T03:52:27.374Z DEBUG   lightningd: testing /usr/local/libexec/c-lightning/lightning_gossipd
2024-06-11T03:52:27.375Z DEBUG   lightningd: testing /usr/local/libexec/c-lightning/lightning_hsmd
2024-06-11T03:52:27.376Z DEBUG   lightningd: testing /usr/local/libexec/c-lightning/lightning_onchaind
2024-06-11T03:52:27.377Z DEBUG   lightningd: testing /usr/local/libexec/c-lightning/lightning_openingd
2024-06-11T03:52:27.378Z DEBUG   hsmd: pid 125, msgfd 53
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_CHECK_PUBKEY
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_ANY_DELAYED_PAYMENT_TO_US
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_ANCHORSPEND
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_HTLC_TX_MINGLE
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_SPLICE_TX
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_CHECK_OUTPOINT
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_FORGET_CHANNEL
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_REVOKE_COMMITMENT_TX
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_PREAPPROVE_INVOICE_CHECK
2024-06-11T03:52:27.380Z DEBUG   hsmd: capability +WIRE_HSMD_PREAPPROVE_KEYSEND_CHECK
2024-06-11T03:52:27.380Z INFO    lightningd: Creating database
2024-06-11T03:52:27.426Z DEBUG   connectd: pid 126, msgfd 57
2024-06-11T03:52:27.426Z UNUSUAL hsmd: HSM: created new hsm_secret file
2024-06-11T03:52:27.426Z DEBUG   hsmd: Client: Received message 27 from client
2024-06-11T03:52:27.426Z DEBUG   hsmd: Client: Received message 27 from client
2024-06-11T03:52:27.426Z DEBUG   hsmd: new_client: 0
2024-06-11T03:52:27.426Z DEBUG   connectd: Created listener on [::]:20735
2024-06-11T03:52:27.426Z DEBUG   connectd: Failed to connect 10 socket: Network is unreachable
2024-06-11T03:52:27.426Z DEBUG   connectd: REPLY WIRE_CONNECTD_INIT_REPLY with 0 fds
2024-06-11T03:52:27.426Z DEBUG   lightningd: io_break: connect_init_done
2024-06-11T03:52:27.426Z DEBUG   lightningd: io_loop: connectd_init
2024-06-11T03:52:27.437Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2024-06-11T03:52:27.437Z DEBUG   lightningd: io_break: plugin_config_cb
2024-06-11T03:52:27.437Z DEBUG   lightningd: io_loop_with_timers: config_plugin
2024-06-11T03:52:27.437Z DEBUG   lightningd: All Bitcoin plugin commands registered
2024-06-11T03:52:27.441Z UNUSUAL lightningd: Waiting for initial block download (this can take a while!)
2024-06-11T03:52:27.449Z DEBUG   lightningd: Adding block 0: 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206
2024-06-11T03:52:27.454Z DEBUG   lightningd: io_break: maybe_completed_init
2024-06-11T03:52:27.454Z DEBUG   lightningd: io_loop_with_timers: setup_topology
2024-06-11T03:52:27.454Z DEBUG   wallet: Loaded 0 channels from DB
2024-06-11T03:52:27.455Z DEBUG   gossipd: pid 136, msgfd 56
2024-06-11T03:52:27.455Z DEBUG   hsmd: new_client: 0
2024-06-11T03:52:27.456Z DEBUG   gossipd: Store compact time: 0 msec
2024-06-11T03:52:27.456Z DEBUG   gossipd: gossip_store: Read 0/0/0/0 cannounce/cupdate/nannounce/delete from store in 0 bytes, now 1 bytes (populated=false)
2024-06-11T03:52:27.456Z DEBUG   gossipd: seeker: state = STARTING_UP New seeker
2024-06-11T03:52:27.456Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_INIT_REPLY with 0 fds
2024-06-11T03:52:27.456Z DEBUG   lightningd: io_break: gossipd_init_done
2024-06-11T03:52:27.456Z DEBUG   lightningd: io_loop: gossip_init
2024-06-11T03:52:27.457Z DEBUG   plugin-clnrest: Killing plugin: disabled itself at init: `clnrest-port` option is not configured
2024-06-11T03:52:27.457Z DEBUG   plugin-wss-proxy: Initiating websocket secure server...
2024-06-11T03:52:27.457Z DEBUG   plugin-wss-proxy: Killing plugin: disabled itself at init: `wss-bind-addr` option is not configured
2024-06-11T03:52:27.457Z DEBUG   lightningd: Looking for [autoclean,succeededforwards,num]
2024-06-11T03:52:27.458Z DEBUG   lightningd: Looking for [autoclean,failedforwards,num]
2024-06-11T03:52:27.458Z DEBUG   hsmd: Client: Received message 27 from client
2024-06-11T03:52:27.459Z DEBUG   plugin-fetchinvoice: Killing plugin: disabled itself at init: offers not enabled in config
2024-06-11T03:52:27.459Z DEBUG   lightningd: Looking for [autoclean,succeededpays,num]
2024-06-11T03:52:27.459Z DEBUG   lightningd: Looking for [autoclean,failedpays,num]
2024-06-11T03:52:27.460Z DEBUG   lightningd: Looking for [autoclean,paidinvoices,num]
2024-06-11T03:52:27.460Z DEBUG   plugin-recover: Recover Plugin Initialised!
2024-06-11T03:52:27.460Z DEBUG   plugin-recover: Gossmap loaded!
2024-06-11T03:52:27.460Z DEBUG   lightningd: Looking for [autoclean,expiredinvoices,num]
2024-06-11T03:52:27.460Z DEBUG   plugin-chanbackup: Chanbackup Initialised!
2024-06-11T03:52:27.460Z INFO    plugin-chanbackup: Creating Emergency Recovery
offers: plugins/offers.c:1235: init: Assertion `blockheight' failed.
offers: FATAL SIGNAL 6 (version v24.05-modded)
2024-06-11T03:52:27.463Z DEBUG   plugin-bookkeeper: Setting up database at sqlite3://accounts.sqlite3
2024-06-11T03:52:27.463Z INFO    plugin-bookkeeper: Creating database
0x55681866e485 send_backtrace
    common/daemon.c:33
0x55681866e50d crashdump
    common/daemon.c:75
0x7f545eae513f ???
    ???:0
0x7f545e91cce1 ???
    ???:0
0x7f545e906536 ???
    ???:0
0x7f545e90640e ???
    ???:0
0x7f545e915661 ???
    ???:0
0x556818656ffe init
    plugins/offers.c:1235
0x55681865f63f handle_init
    plugins/libplugin.c:1376
0x55681865f8ee ld_command_handle
    plugins/libplugin.c:1797
0x55681865fec0 ld_read_json_one
    plugins/libplugin.c:1979
0x55681865ff49 ld_read_json
    plugins/libplugin.c:1999
0x5568187ab4cc next_plan
    ccan/ccan/io/io.c:60
0x5568187ab953 do_plan
    ccan/ccan/io/io.c:408
0x5568187ab9ec io_ready
    ccan/ccan/io/io.c:418
0x5568187ad302 io_loop
    ccan/ccan/io/poll.c:455
0x5568186606dc plugin_main
    plugins/libplugin.c:2209
0x55681865736d main
    plugins/offers.c:1285
0x7f545e907d09 ???
    ???:0
0x556818654799 ???
    ???:0
0xffffffffffffffff ???
    ???:0
offers: FATAL SIGNAL 11 (version v24.05-modded)
0x55681866e485 send_backtrace
    common/daemon.c:33
0x55681866e50d crashdump
    common/daemon.c:75
0x7f545eae513f ???
    ???:0
0x0 ???
    ???:0
2024-06-11T03:52:27.588Z INFO    plugin-offers: Killing plugin: exited before replying to init
2024-06-11T03:52:27.588Z **BROKEN** plugin-offers: Plugin marked as important, shutting down lightningd!
2024-06-11T03:52:27.588Z DEBUG   lightningd: io_break: lightningd_exit
2024-06-11T03:52:27.589Z DEBUG   connectd: REPLY WIRE_CONNECTD_START_SHUTDOWN_REPLY with 0 fds
2024-06-11T03:52:27.589Z DEBUG   lightningd: io_break: connectd_start_shutdown_reply
2024-06-11T03:52:27.589Z DEBUG   lightningd: io_break: destroy_plugin
2024-06-11T03:52:27.589Z DEBUG   connectd: Shutting down
2024-06-11T03:52:27.590Z DEBUG   gossipd: Shutting down
2024-06-11T03:52:27.590Z DEBUG   hsmd: Shutting down
vincenzopalazzo commented 14 hours ago

This should be fixed in https://github.com/ElementsProject/lightning/commit/f2551091ca3cc2e7b03a6d3766a851a025dbfd4d

@endothermicdev probably we should include this in case we are planning a patch release