search

ElementsProject / lightning

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

Corrupt gossip file causes core lightning to refuse to start (gossipd: FATAL SIGNAL 6) #7249

Closed Amperstrand closed 5 months ago

Amperstrand commented 6 months ago

Issue and Steps to Reproduce

This is from a node used for experimenting. I am sharing some logs and a rough timeline for what happened and my progress in resolving the issue. It is not immediately obvious based on the error messages what should be done to get it running again

Here are some log lines that I have saved:

Core-Lightning starting
2024-04-19T12:13:54.843Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2024-04-19T12:13:58.184Z **BROKEN** gossipd: FATAL SIGNAL 6 (version basedon-v23.08)
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: common/daemon.c:38 (send_backtrace) 0x55fff4e9c494
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: common/daemon.c:75 (crashdump) 0x55fff4e9c4d4
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab224013f
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab2077ce1
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab2061536
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab206140e
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab2070661
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:629 (delete_by_index) 0x55fff4e902d5
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:676 (gossip_store_delete) 0x55fff4e90416
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/routing.c:1338 (delete_spam_update) 0x55fff4e94345
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/routing.c:1503 (routing_add_channel_update) 0x55fff4e96cf7
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:916 (gossip_store_load) 0x55fff4e907ba
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:892 (gossip_init) 0x55fff4e8dc4d
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:1146 (recv_req) 0x55fff4e8ddaa
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: common/daemon_conn.c:35 (handle_read) 0x55fff4e9c62e
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x55fff4fdca0b
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x55fff4fdce92
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x55fff4fdcf2b
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: ccan/ccan/io/poll.c:453 (io_loop) 0x55fff4fde81a
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:1281 (main) 0x55fff4e8e964
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab2062d09
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x55fff4e89d39
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0xffffffffffffffff
2024-04-19T12:13:58.185Z **BROKEN** gossipd: FATAL SIGNAL (version basedon-v23.08)
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: common/daemon.c:38 (send_backtrace) 0x55fff4e9c494
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: common/status.c:221 (status_failed) 0x55fff4ea1e92
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: common/subdaemon.c:18 (status_backtrace_exit) 0x55fff4ea1f8a
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: common/daemon.c:78 (crashdump) 0x55fff4e9c4da
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab224013f
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab2077ce1
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab2061536
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab206140e
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab2070661
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:629 (delete_by_index) 0x55fff4e902d5
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:676 (gossip_store_delete) 0x55fff4e90416
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/routing.c:1338 (delete_spam_update) 0x55fff4e94345
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/routing.c:1503 (routing_add_channel_update) 0x55fff4e96cf7
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:916 (gossip_store_load) 0x55fff4e907ba
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:892 (gossip_init) 0x55fff4e8dc4d
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:1146 (recv_req) 0x55fff4e8ddaa
2024-04-19T12:13:58.185Z **BROKEN** gossipd: backtrace: common/daemon_conn.c:35 (handle_read) 0x55fff4e9c62e
2024-04-19T12:13:58.186Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x55fff4fdca0b
2024-04-19T12:13:58.186Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x55fff4fdce92
2024-04-19T12:13:58.186Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x55fff4fdcf2b
2024-04-19T12:13:58.186Z **BROKEN** gossipd: backtrace: ccan/ccan/io/poll.c:453 (io_loop) 0x55fff4fde81a
2024-04-19T12:13:58.186Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:1281 (main) 0x55fff4e8e964
2024-04-19T12:13:58.186Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fdab2062d09
2024-04-19T12:13:58.186Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x55fff4e89d39
2024-04-19T12:13:58.186Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0xffffffffffffffff
2024-04-19T12:13:58.186Z **BROKEN** gossipd: STATUS_FAIL_INTERNAL_ERROR: FATAL SIGNAL
network=bitcoin added in /root/.lightning/config
Waiting /root/.nbxplorer/btc_fully_synched to be created...
The chain is fully synched
Waiting /var/lib/tor/hidden_services/c-lightning/hostname to be created by tor...
announce-addr=X.onion:9735 added to /root/.lightning/config
rpc-file=/root/.lightning/lightning-rpc added to /root/.lightning/config
Installing bundled plugins
Core-Lightning starting
2024-04-19T12:16:23.769Z INFO    lightningd: 3c3ba81-modded
2024-04-19T12:16:24.733Z INFO    lightningd: Updating database from version 233 to 256
2024-04-19T12:16:34.106Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2024-04-19T12:16:35.470Z **BROKEN** gossipd: gossip_store: Unknown message (offset 44574364). Moving to gossip_store.corrupt and truncating
Creating rune...
2024-04-19T12:16:35.523Z INFO    plugin-clnrest.py: REST server running at http://0.0.0.0:3010
Rune created
lightningd "$@"
2024-04-19T12:16:35.703Z INFO    lightningd: --------------------------------------------------
2024-04-19T12:16:35.703Z INFO    lightningd: Server started with public key X, alias X (color #036efb) and lightningd 3c3ba81-modded
2024-04-19T12:16:43.037Z UNUSUAL plugin-bcli: bitcoin-cli -datadir=/etc/bitcoin -rpcconnect=bitcoind getblockhash 836673 exited with status 1
2024-04-19T12:16:44.041Z UNUSUAL plugin-bcli: bitcoin-cli -datadir=/etc/bitcoin -rpcconnect=bitcoind getblockhash 836673 exited with status 1
2024-04-19T12:16:45.045Z UNUSUAL plugin-bcli: bitcoin-cli -datadir=/etc/bitcoin -rpcconnect=bitcoind getblockhash 836673 exited with status 1
2024-04-19T12:16:46.049Z UNUSUAL plugin-bcli: bitcoin-cli -datadir=/etc/bitcoin -rpcconnect=bitcoind getblockhash 836673 exited with status 1
2024-04-19T12:16:47.053Z UNUSUAL plugin-bcli: bitcoin-cli -datadir=/etc/bitcoin -rpcconnect=bitcoind getblockhash 836673 exited with status 1
2024-04-19T12:16:48.057Z UNUSUAL plugin-bcli: bitcoin-cli -datadir=/etc/bitcoin -rpcconnect=bitcoind getblockhash 836673 exited with status 1
network=bitcoin added in /root/.lightning/config
Waiting /root/.nbxplorer/btc_fully_synched to be created...
The chain is fully synched
Waiting /var/lib/tor/hidden_services/c-lightning/hostname to be created by tor...
announce-addr=X.onion:9735 added to /root/.lightning/config
rpc-file=/root/.lightning/lightning-rpc added to /root/.lightning/config
Installing bundled plugins
Core-Lightning starting
2024-04-19T12:17:07.616Z INFO    lightningd: 3c3ba81-modded
2024-04-19T12:17:10.705Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2024-04-19T12:17:11.075Z **BROKEN** gossipd: gossip_store: checksum verification failed? 008aa8f1 should be 19b46602 (offset 57035). Moving to gossip_store.corrupt and truncating
2024-04-19T12:17:11.075Z UNUSUAL X-chan#4: gossipd lost track of announced channel: re-announcing!
2024-04-19T12:17:11.076Z UNUSUAL Y-chan#5: gossipd lost track of announced channel: re-announcing!
2024-04-19T12:17:11.106Z INFO    plugin-clnrest.py: REST server running at http://0.0.0.0:3010
2024-04-19T12:17:11.108Z INFO    lightningd: --------------------------------------------------
2024-04-19T12:17:11.108Z INFO    lightningd: Server started with public key X, alias X (color #X) and lightningd 3c3ba81-modded
Rune already created
lightningd "$@"
2024-04-19T12:24:31.299Z UNUSUAL X-chan#6: Deferring incoming commit until we sync
2024-04-19T12:46:48.918Z INFO    plugin-keysend: Inserting a new invoice for keysend with payment_hash X
2024-04-19T12:46:48.957Z INFO    plugin-topology: Killing plugin: exited during normal operation
2024-04-19T12:46:48.957Z **BROKEN** lightningd: Missing result from listincoming: {"jsonrpc": "2.0","id": "cln:htlc_accepted#4726/keysend:invoice#3/cln:listincoming#4727","error": {"code":-4, "message":"Plugin terminated before replying to RPC call."}}
2024-04-19T12:46:48.957Z **BROKEN** lightningd: Missing result from listincoming: {"jsonrpc": "2.0","id": "cln:htlc_accepted#4726/keysend:invoice#3/cln:listincoming#4727","error": {"code":-4, "message":"Plugin terminated before replying to RPC call."}}
2024-04-19T12:46:49.024Z **BROKEN** lightningd: FATAL SIGNAL 6 (version 3c3ba81-modded)
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: common/daemon.c:38 (send_backtrace) 0x561a22e200b8
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: common/daemon.c:75 (crashdump) 0x561a22e200f8
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7efe77dfa13f
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7efe77bdece1
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7efe77bc8536
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/log.c:1025 (fatal_vfmt) 0x561a22dceaea
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/log.c:1035 (fatal) 0x561a22dceb83
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/routehint.c:45 (routehint_candidates) 0x561a22df6254
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/invoice.c:746 (add_routehints) 0x561a22dc34bd
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/invoice.c:961 (listincoming_done) 0x561a22dc476f
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/plugin.c:661 (plugin_response_handle) 0x561a22def82b
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/plugin.c:773 (plugin_read_json_one) 0x561a22df309e
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/plugin.c:252 (plugin_terminated_fail_req) 0x561a22df31fe
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/plugin.c:274 (destroy_plugin) 0x561a22df3ca9
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:246 (notify) 0x561a230385e0
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:437 (del_tree) 0x561a230386b3
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:521 (tal_free) 0x561a23038bb4
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/plugin.c:457 (plugin_kill) 0x561a22df19bd
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/plugin.c:879 (plugin_conn_finish) 0x561a22df1ce9
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/io/poll.c:246 (destroy_conn) 0x561a2302e7fd
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/io/poll.c:252 (destroy_conn_close_fd) 0x561a2302e81f
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:246 (notify) 0x561a230385e0
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:437 (del_tree) 0x561a230386b3
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:521 (tal_free) 0x561a23038bb4
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/io/io.c:450 (io_close) 0x561a2302d42b
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: ccan/ccan/io/poll.c:457 (io_loop) 0x561a2302ee0e
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers) 0x561a22dc6dd9
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: lightningd/lightningd.c:1425 (main) 0x561a22dcc3a3
2024-04-19T12:46:49.024Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7efe77bc9d09
2024-04-19T12:46:49.025Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x561a22da13f9
2024-04-19T12:46:49.025Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0xffffffffffffffff
network=bitcoin added in /root/.lightning/config
Waiting /root/.nbxplorer/btc_fully_synched to be created...
The chain is fully synched
Waiting /var/lib/tor/hidden_services/c-lightning/hostname to be created by tor...
announce-addr=X.onion:9735 added to /root/.lightning/config
rpc-file=/root/.lightning/lightning-rpc added to /root/.lightning/config
Installing bundled plugins
Core-Lightning starting
2024-04-19T12:46:51.188Z INFO    lightningd: 3c3ba81-modded
2024-04-19T12:46:54.780Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2024-04-19T12:46:55.174Z **BROKEN** gossipd: FATAL SIGNAL 6 (version 3c3ba81-modded)
2024-04-19T12:46:55.175Z **BROKEN** gossipd: backtrace: common/daemon.c:38 (send_backtrace) 0x555b1c7a59bf
2024-04-19T12:46:55.175Z **BROKEN** gossipd: backtrace: common/daemon.c:75 (crashdump) 0x555b1c7a59ff
2024-04-19T12:46:55.175Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fda024e013f
2024-04-19T12:46:55.175Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fda02317ce1
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fda02301536
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fda0230140e
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7fda02310661
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: common/gossmap.c:464 (add_channel) 0x555b1c7a9474
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: common/gossmap.c:661 (map_catchup) 0x555b1c7a992c
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: common/gossmap.c:726 (load_gossip_store) 0x555b1c7a9db9
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: common/gossmap.c:1081 (gossmap_load_fd_) 0x555b1c7a9f11
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: gossipd/gossmap_manage.c:432 (gossmap_manage_new) 0x555b1c79d09b
2024-04-19T12:46:55.176Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:441 (gossip_init) 0x555b1c79a064
2024-04-19T12:46:55.176Z **BROKEN** connectd: STATUS_FAIL_GOSSIP_IO: gossipd exited?
Amperstrand commented 6 months ago

update: found the crashlogs in /var/lib/docker/volumes/generated_clightning_bitcoin_datadir/_data/bitcoin

Available on request

Amperstrand commented 6 months ago 
+1781.312659633 channeld-chan#6DEBUG: Trying commit
+1781.312722380 channeld-chan#6DEBUG: Can't send commit: nothing to send, feechange not wanted ({ RCVD_ADD_ACK_REVOCATION:8589 }) blockheight not wanted ({ RCVD_ADD_ACK_REVOCATION:0 })
+1781.341536691 plugin-topologyINFO: Killing plugin: exited during normal operation
+1781.341719201 lightningdDEBUG: routehint: {"jsonrpc": "2.0","id": "cln:htlc_accepted#4726/keysend:invoice#3/cln:listincoming#4727","error": {"code":-4, "message":"Plugin terminated before replying to RPC call."}}
+1781.341820300 lightningdBROKEN: Missing result from listincoming: {"jsonrpc": "2.0","id": "cln:htlc_accepted#4726/keysend:invoice#3/cln:listincoming#4727","error": {"code":-4, "message":"Plugin terminated before replying to RPC call."}}
+1781.408873809 lightningdBROKEN: FATAL SIGNAL 6 (version 3c3ba81-modded)
+1781.408921739 lightningdBROKEN: backtrace: common/daemon.c:38 (send_backtrace) 0x561a22e200b8
+1781.408928031 lightningdBROKEN: backtrace: common/daemon.c:75 (crashdump) 0x561a22e200f8
+1781.408946034 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7efe77dfa13f
+1781.408958177 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7efe77bdece1
+1781.408966743 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7efe77bc8536
+1781.408976030 lightningdBROKEN: backtrace: lightningd/log.c:1025 (fatal_vfmt) 0x561a22dceaea
+1781.408984286 lightningdBROKEN: backtrace: lightningd/log.c:1035 (fatal) 0x561a22dceb83
+1781.409000386 lightningdBROKEN: backtrace: lightningd/routehint.c:45 (routehint_candidates) 0x561a22df6254
+1781.409016877 lightningdBROKEN: backtrace: lightningd/invoice.c:746 (add_routehints) 0x561a22dc34bd
+1781.409032937 lightningdBROKEN: backtrace: lightningd/invoice.c:961 (listincoming_done) 0x561a22dc476f
+1781.409038067 lightningdBROKEN: backtrace: lightningd/plugin.c:661 (plugin_response_handle) 0x561a22def82b
+1781.409056109 lightningdBROKEN: backtrace: lightningd/plugin.c:773 (plugin_read_json_one) 0x561a22df309e
+1781.409074714 lightningdBROKEN: backtrace: lightningd/plugin.c:252 (plugin_terminated_fail_req) 0x561a22df31fe
+1781.409084282 lightningdBROKEN: backtrace: lightningd/plugin.c:274 (destroy_plugin) 0x561a22df3ca9
+1781.409088731 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:246 (notify) 0x561a230385e0
+1781.409104160 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:437 (del_tree) 0x561a230386b3
+1781.409113116 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:521 (tal_free) 0x561a23038bb4
+1781.409137621 lightningdBROKEN: backtrace: lightningd/plugin.c:457 (plugin_kill) 0x561a22df19bd
+1781.409145326 lightningdBROKEN: backtrace: lightningd/plugin.c:879 (plugin_conn_finish) 0x561a22df1ce9
+1781.409163360 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:246 (destroy_conn) 0x561a2302e7fd
+1781.409168760 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:252 (destroy_conn_close_fd) 0x561a2302e81f
+1781.409188998 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:246 (notify) 0x561a230385e0
+1781.409197714 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:437 (del_tree) 0x561a230386b3
+1781.409209686 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:521 (tal_free) 0x561a23038bb4
+1781.409219234 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:450 (io_close) 0x561a2302d42b
+1781.409239381 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:457 (io_loop) 0x561a2302ee0e
+1781.409248679 lightningdBROKEN: backtrace: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers) 0x561a22dc6dd9
+1781.409271281 lightningdBROKEN: backtrace: lightningd/lightningd.c:1425 (main) 0x561a22dcc3a3
+1781.409285257 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7efe77bc9d09
+1781.409322056 lightningdBROKEN: backtrace: (null):0 ((null)) 0x561a22da13f9
+1781.409325993 lightningdBROKEN: backtrace: (null):0 ((null)) 0xffffffffffffffff
Amperstrand commented 6 months ago

Was able to resolve the issue by stopping core lightning, deleting the gossip file and starting core lightning again.

I would consider this issue resolved if the default behaviour of the gossipd plugin was to try to recover instead of crashing. Recovering could involve deleting the file and starting again.

I also want to add that the invoice that was attempted paid was from a private channel and happened while the bitcoin node was still catching up. And the keysend also happened in the same way.

The status now is that the lightning node is running again, but that some of the channels were either force closed or pending.

Amperstrand commented 6 months ago 
+1780.512058392 gossipdDEBUG: Bad gossip order: Unknown channel 826674x2890x1
+1780.512072148 gossipdDEBUG: handle_recv_gossip: WIRE_CHANNEL_UPDATE
+1780.512085723 gossipdDEBUG: Bad gossip order: Unknown channel 833439x5x1
+1780.512099309 gossipdDEBUG: handle_recv_gossip: WIRE_CHANNEL_UPDATE
+1780.512112995 gossipdDEBUG: Bad gossip order: Unknown channel 830532x423x1
+1780.676421311 gossipdDEBUG: handle_recv_gossip: WIRE_CHANNEL_UPDATE
+1780.676447009 gossipdDEBUG: Bad gossip order: Unknown channel 613641x2312x1
+1781.296566458 channeld-chan#6DEBUG: peer_in WIRE_REVOKE_AND_ACK
+1781.296618074 hsmdDEBUG: Got WIRE_HSMD_VALIDATE_REVOCATION
+1781.296634745 hsmdDEBUG: Client: Received message 36 from client
+1781.296872098 channeld-chan#6DEBUG: Received revoke_and_ack
+1781.296891955 channeld-chan#6DEBUG: htlc 4: SENT_ADD_ACK_COMMIT->RCVD_ADD_ACK_REVOCATION
+1781.296909728 channeld-chan#6DEBUG: rcvd_revoke_and_ack: HTLC REMOTE 4 = RCVD_ADD_ACK_REVOCATION/SENT_ADD_ACK_REVOCATION 
+1781.296927100 channeld-chan#6DEBUG: No commits outstanding after recv revoke_and_ack
+1781.296943701 channeld-chan#6DEBUG: HTLC 4[REMOTE] => RCVD_ADD_ACK_REVOCATION
+1781.297605576 hsmdDEBUG: Got WIRE_HSMD_SIGN_PENALTY_TO_US
+1781.297623189 hsmdDEBUG: Client: Received message 14 from client
+1781.297641112 channeld-chan#6DEBUG: Sending master 1022
+1781.297911336 chan#6DEBUG: got revoke 98: 1 changed
+1781.297923189 chan#6DEBUG: HTLC in 4 SENT_ADD_ACK_COMMIT->RCVD_ADD_ACK_REVOCATION
+1781.298691350 lightningdDEBUG: Calling htlc_accepted hook of plugin keysend
+1781.298799242 plugin-keysendIO_OUT: "cln:htlc_accepted#4726"
+1781.302335568 plugin-keysendIO_IN: x
+1781.302363139 plugin-keysendINFO: Inserting a new invoice for keysend with payment_hash x
+1781.302445433 jsonrpc#60IO_IN: x
+1781.302473946 channeld-chan#6DEBUG: ... , awaiting 1122
+1781.302529790 jsonrpc#60IO_IN: 7d7d0a0a
+1781.302546071 jsonrpc#60IO_IN: "cln:htlc_accepted#4726/keysend:invoice#3"
+1781.302765139 jsonrpc#60IO_OUT: "cln:htlc_accepted#4726/keysend:invoice#3/cln:listincoming#4727"
+1781.302807899 channeld-chan#6DEBUG: Got it!
+1781.302838305 channeld-chan#6DEBUG: revoke_and_ack REMOTE: remote_per_commit = x, old_remote_per_commit = x
+1781.303165005 jsonrpc#61IO_IN: x
+1781.303176316 jsonrpc#61IO_IN: "cln:htlc_accepted#4726/keysend:invoice#3/cln:listincoming#4727/topology:listpeerchannels#5"

+1781.312659633 channeld-chan#6DEBUG: Trying commit
+1781.312722380 channeld-chan#6DEBUG: Can't send commit: nothing to send, feechange not wanted ({ RCVD_ADD_ACK_REVOCATION:8589 }) blockheight not wanted ({ RCVD_ADD_ACK_REVOCATION:0 })
+1781.341536691 plugin-topologyINFO: Killing plugin: exited during normal operation
+1781.341719201 lightningdDEBUG: routehint: {"jsonrpc": "2.0","id": "cln:htlc_accepted#4726/keysend:invoice#3/cln:listincoming#4727","error": {"code":-4, "message":"Plugin terminated before replying to RPC call."}}
+1781.341820300 lightningdBROKEN: Missing result from listincoming: {"jsonrpc": "2.0","id": "cln:htlc_accepted#4726/keysend:invoice#3/cln:listincoming#4727","error": {"code":-4, "message":"Plugin terminated before replying to RPC call."}}
+1781.408873809 lightningdBROKEN: FATAL SIGNAL 6 (version 3c3ba81-modded)
+1781.408921739 lightningdBROKEN: backtrace: common/daemon.c:38 (send_backtrace) 0x561a22e200b8
+1781.408928031 lightningdBROKEN: backtrace: common/daemon.c:75 (crashdump) 0x561a22e200f8
+1781.408946034 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7efe77dfa13f
+1781.408958177 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7efe77bdece1
+1781.408966743 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7efe77bc8536
+1781.408976030 lightningdBROKEN: backtrace: lightningd/log.c:1025 (fatal_vfmt) 0x561a22dceaea
+1781.408984286 lightningdBROKEN: backtrace: lightningd/log.c:1035 (fatal) 0x561a22dceb83
+1781.409000386 lightningdBROKEN: backtrace: lightningd/routehint.c:45 (routehint_candidates) 0x561a22df6254
+1781.409016877 lightningdBROKEN: backtrace: lightningd/invoice.c:746 (add_routehints) 0x561a22dc34bd
+1781.409032937 lightningdBROKEN: backtrace: lightningd/invoice.c:961 (listincoming_done) 0x561a22dc476f
+1781.409038067 lightningdBROKEN: backtrace: lightningd/plugin.c:661 (plugin_response_handle) 0x561a22def82b
+1781.409056109 lightningdBROKEN: backtrace: lightningd/plugin.c:773 (plugin_read_json_one) 0x561a22df309e
+1781.409074714 lightningdBROKEN: backtrace: lightningd/plugin.c:252 (plugin_terminated_fail_req) 0x561a22df31fe
+1781.409084282 lightningdBROKEN: backtrace: lightningd/plugin.c:274 (destroy_plugin) 0x561a22df3ca9
+1781.409088731 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:246 (notify) 0x561a230385e0
+1781.409104160 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:437 (del_tree) 0x561a230386b3
+1781.409113116 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:521 (tal_free) 0x561a23038bb4
+1781.409137621 lightningdBROKEN: backtrace: lightningd/plugin.c:457 (plugin_kill) 0x561a22df19bd
+1781.409145326 lightningdBROKEN: backtrace: lightningd/plugin.c:879 (plugin_conn_finish) 0x561a22df1ce9
+1781.409163360 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:246 (destroy_conn) 0x561a2302e7fd
+1781.409168760 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:252 (destroy_conn_close_fd) 0x561a2302e81f
+1781.409188998 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:246 (notify) 0x561a230385e0
+1781.409197714 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:437 (del_tree) 0x561a230386b3
+1781.409209686 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:521 (tal_free) 0x561a23038bb4
+1781.409219234 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:450 (io_close) 0x561a2302d42b
+1781.409239381 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:457 (io_loop) 0x561a2302ee0e
+1781.409248679 lightningdBROKEN: backtrace: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers) 0x561a22dc6dd9
+1781.409271281 lightningdBROKEN: backtrace: lightningd/lightningd.c:1425 (main) 0x561a22dcc3a3
+1781.409285257 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7efe77bc9d09
+1781.409322056 lightningdBROKEN: backtrace: (null):0 ((null)) 0x561a22da13f9
+1781.409325993 lightningdBROKEN: backtrace: (null):0 ((null)) 0xffffffffffffffff

full debug log available on request

unsenttraffic commented 5 months ago

Same issue here.

2024-05-17T16:25:25.684Z INFO lightningd: v24.02.1-93-gc4edec8 2024-05-17T16:25:30.613Z INFO connectd: Static Tor service onion address: "[address]" bound from extern port 9736 2024-05-17T16:25:30.671Z INFO plugin-bcli: bitcoin-cli initialized and connected to bitcoind. 2024-05-17T16:25:32.184Z BROKEN gossipd: FATAL SIGNAL 6 (version v24.02.1-93-gc4edec8) 2024-05-17T16:25:32.184Z BROKEN gossipd: backtrace: common/daemon.c:38 (send_backtrace) 0x5556d033e7 2024-05-17T16:25:32.185Z BROKEN gossipd: backtrace: common/daemon.c:75 (crashdump) 0x5556d0343b 2024-05-17T16:25:32.185Z BROKEN gossipd: backtrace: (null):0 ((null)) 0x7f959677a7 2024-05-17T16:25:32.186Z BROKEN gossipd: backtrace: ../sysdeps/unix/sysv/linux/raise.c:51 (GI_raise) 0x7f9575eeac 2024-05-17T16:25:32.187Z BROKEN gossipd: backtrace: ./stdlib/abort.c:79 (__GI_abort) 0x7f9574ba9f 2024-05-17T16:25:32.187Z BROKEN gossipd: backtrace: ./assert/assert.c:92 (assert_fail_base) 0x7f95758477 2024-05-17T16:25:32.188Z BROKEN gossipd: backtrace: ./assert/assert.c:101 (__GI___assert_fail) 0x7f957584db 2024-05-17T16:25:32.189Z BROKEN gossipd: backtrace: common/gossmap.c:463 (add_channel) 0x5556d07687 2024-05-17T16:25:32.189Z BROKEN connectd: STATUS_FAIL_GOSSIP_IO: gossipd exited?

The node had been offline too for a few days and lightningd would crash on restart, but only after bitcoin re-synced the blockchain. During the sync it didn't crash.

I also deleted the gossipd folder, reset and the above is from /data/lightningd/cln.log following those steps.

overcoin commented 5 months ago

Experienced same issue today. CLN crashed after BROKEN gossipd: FATAL SIGNAL 6. Attempted restart failed. I had to remove both newly created gossip_store and gossip_store_corrupt files to successfully restart node.

Latest stable v24.02.2.

rustyrussell commented 5 months ago

OK, thanks for the report. Your gossip store seems to be gaining redundant channel announcements somehow. I've patched it to prevent the crash, and put some more debug info in, as I cannot figure out how this is happening...

Sjors commented 5 months ago

I also ended up with a corrupt gossip store today, probably because I accidentally turned the wrong circuit breaker off :-)

The first boot after power came back ends with:

2024-05-29T12:03:23.570Z **BROKEN** gossipd: gossip_store: get delete entry offset 41434415/5949 (version v24.02.2)
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: common/daemon.c:38 (send_backtrace) 0x5faf2c77c808
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: common/status.c:221 (status_failed) 0x5faf2c785edc
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:466 (gossip_store_get_with_hdr) 0x5faf2c772b11
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:491 (check_msg_type) 0x5faf2c772b8c
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:509 (gossip_store_set_flag) 0x5faf2c772d1f
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: gossipd/gossip_store.c:561 (gossip_store_del) 0x5faf2c772f32
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: gossipd/gossmap_manage.c:767 (process_channel_update) 0x5faf2c77472f
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: gossipd/gossmap_manage.c:876 (gossmap_manage_channel_update) 0x5faf2c774f03
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:217 (handle_recv_gossip) 0x5faf2c77187e
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:313 (connectd_req) 0x5faf2c771998
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: common/daemon_conn.c:35 (handle_read) 0x5faf2c77cad6
2024-05-29T12:03:23.570Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x5faf2c8ba529
2024-05-29T12:03:23.571Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x5faf2c8ba9f6
2024-05-29T12:03:23.571Z **BROKEN** gossipd: backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x5faf2c8baa93
2024-05-29T12:03:23.571Z **BROKEN** gossipd: backtrace: ccan/ccan/io/poll.c:453 (io_loop) 0x5faf2c8bc39f
2024-05-29T12:03:23.571Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:684 (main) 0x5faf2c771c77
2024-05-29T12:03:23.571Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7f5f5c82a1c9
2024-05-29T12:03:23.571Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x7f5f5c82a28a
2024-05-29T12:03:23.571Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x5faf2c76e874
2024-05-29T12:03:23.571Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0xffffffffffffffff
2024-05-29T12:03:23.571Z **BROKEN** gossipd: STATUS_FAIL_INTERNAL_ERROR: gossip_store: get delete entry offset 41434415/5949

It immediately restarted

2024-05-29T12:03:23.888Z INFO    lightningd: v24.02.2
...
2024-05-29T12:04:01.977Z **BROKEN** gossipd: gossip_store: checksum verification failed? fd6d6a9a should be a22febd1 (offset 191455). Moving to gossip_store.corrupt and truncating
2024-05-29T12:04:01.977Z DEBUG   gossipd: Store compact time: 68 msec
2024-05-29T12:04:01.977Z DEBUG   gossipd: gossip_store: Read 0/22/6/5 cannounce/cupdate/nannounce/delete from store in 253187 bytes, now 1 bytes (populated=false)
2024-05-29T12:04:01.977Z DEBUG   gossipd: seeker: state = STARTING_UP New seeker
2024-05-29T12:04:01.977Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_INIT_REPLY with 0 fds
2024-05-29T12:04:01.977Z UNUSUAL 025e5019685002fe76b46cbde6d84500e674ac33863fea3ab490ea72e1ad8974be-chan#13934: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.978Z UNUSUAL 03aa6fdee4c21d1af4119543e8b34087bf7ea4f6e6be284017f51fdc87019be628-chan#13611: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.978Z UNUSUAL 0387adcaa599a42f01c745ec4b130cf8ab8109d8b7ce5c7fbf722d8eb5bdccd92e-chan#13821: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.979Z UNUSUAL 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#13925: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.979Z UNUSUAL 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f-chan#13936: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.980Z UNUSUAL 0243054886aa6026a4312583bab952dad7723f840d037884d5a72b729fdb52ecbd-chan#13930: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.980Z UNUSUAL 028d98b9969fbed53784a36617eb489a59ab6dc9b9d77fcdca9ff55307cd98e3c4-chan#13804: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.980Z UNUSUAL 036387fa666993defcf79719d5cdb3e1243d694e4a71922878c3dc83c4e65872ab-chan#13915: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.981Z UNUSUAL 0364913d18a19c671bb36dd04d6ad5be0fe8f2894314c36a9db3f03c2d414907e1-chan#13923: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.981Z UNUSUAL 03d607f3e69fd032524a867b288216bfab263b6eaee4e07783799a6fe69bb84fac-chan#13928: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.981Z UNUSUAL 030b5d1a2f2502eb14f7dfccd6de8d227cc533fe14214c80ecb5dd9bd6ef9dc8e9-chan#13857: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.982Z UNUSUAL 02f324df7694f57b7d800d5a64f62fb226eabc8fbacb997f3ac5cd230e37944fbf-chan#13924: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.982Z UNUSUAL 02c4ad243f18d8ed3a40e98725bc6a795b941d7e3d64be9f7dab38144f1eb09cb8-chan#13933: gossipd lost track of announced channel: re-announcing!
2024-05-29T12:04:01.983Z DEBUG   lightningd: io_break: gossipd_init_done
2024-05-29T12:04:01.983Z DEBUG   lightningd: io_loop: gossip_init
...

A bunch more stuff, but it stayed online... in fact I received a bunch of keysend payments.

Then a bit later I crashed it, probably via the renepay plugin.

Upon restart I got errors again and a crash:

2024-05-29T17:27:49.354Z DEBUG   gossipd: Store compact time: 1215 msec
2024-05-29T17:27:49.354Z DEBUG   gossipd: gossip_store: Read 74726/88142/12004/50730 cannounce/cupdate/nannounce/delete from store in 64753953 bytes, now 52739729 bytes (populated=true)
2024-05-29T17:27:49.354Z **BROKEN** gossipd: FATAL SIGNAL 6 (version v24.02.2)
2024-05-29T17:27:49.354Z **BROKEN** gossipd: backtrace: common/daemon.c:38 (send_backtrace) 0x5b0d4cedf808
2024-05-29T17:27:49.354Z **BROKEN** gossipd: backtrace: common/daemon.c:75 (crashdump) 0x5b0d4cedf857
2024-05-29T17:27:49.355Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x746eaee4531f
2024-05-29T17:27:49.355Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x746eaee9eb1c
2024-05-29T17:27:49.355Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x746eaee4526d
2024-05-29T17:27:49.355Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x746eaee288fe
2024-05-29T17:27:49.355Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x746eaee2881a
2024-05-29T17:27:49.355Z **BROKEN** gossipd: backtrace: (null):0 ((null)) 0x746eaee3b506
2024-05-29T17:27:49.355Z **BROKEN** gossipd: backtrace: common/gossmap.c:464 (add_channel) 0x5b0d4cee33c0
2024-05-29T17:27:49.355Z **BROKEN** gossipd: backtrace: common/gossmap.c:661 (map_catchup) 0x5b0d4cee383b
2024-05-29T17:27:49.356Z **BROKEN** gossipd: backtrace: common/gossmap.c:726 (load_gossip_store) 0x5b0d4cee3cc2
2024-05-29T17:27:49.356Z **BROKEN** gossipd: backtrace: common/gossmap.c:1081 (gossmap_load_fd_) 0x5b0d4cee3e22
2024-05-29T17:27:49.356Z **BROKEN** gossipd: backtrace: gossipd/gossmap_manage.c:432 (gossmap_manage_new) 0x5b0d4ced6c81
2024-05-29T17:27:49.356Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:441 (gossip_init) 0x5b0d4ced3c22
2024-05-29T17:27:49.356Z **BROKEN** gossipd: backtrace: gossipd/gossipd.c:582 (recv_req) 0x5b0d4ced423c
2024-05-29T17:27:49.357Z **BROKEN** connectd: STATUS_FAIL_GOSSIP_IO: gossipd exited?

I ended up deleting the gossip store files entirely. Other than seeing all my peers as NO_ALIAS_SET, things seem to work now. Although the payment I tried failed for not being able to find a route; I assume that's a matter of waiting for gossip to catch up?

vincenzopalazzo commented 5 months ago

I assume that's a matter of waiting for gossip to catch up?

Probably yes!

The first boot after power came back ends with:

This is a really unfortunate crash :/ I am wondering if we can do something to catch this problem and recover without manual intervention

ksedgwic commented 5 months ago

I just had a crash on a fresh node, started from scratch within the hour:

user@home3:~/lightning-signer/vls-hsmd$ make list-versions 
vls-hsmd (vls-v0.11.0-rc.1-55-g88f6b63)
 1563919257ace7336519c494640d62e939bc0122 lightning (v24.05rc2-23-g156391925)
 24cb6a85ce8491ccfd21e77feeacf3bc8a2c2b88 vls (v0.11.0-142-g24cb6a85)
Fri 2024-05-31 16:17:58 PDT home3 bash[2781207]: [2024-05-31 23:17:58.101 remote_hsmd_serial/remote_hsmd_serial::serial INFO] replied 2781207/15/0
Fri 2024-05-31 16:17:58 PDT home3 bash[2781129]: 2024-05-31T23:17:58.103Z DEBUG   connectd: Responder: handshake failed act_one_responder2:944
Fri 2024-05-31 16:17:58 PDT home3 bash[2781129]: 2024-05-31T23:17:58.173Z DEBUG   gossipd: channel_announcement: got reply for 2222690x26x1...
Fri 2024-05-31 16:17:58 PDT home3 bash[2781129]: 2024-05-31T23:17:58.290Z DEBUG   gossipd: channel_announcement: got reply for 2227214x24x1...
Fri 2024-05-31 16:17:58 PDT home3 bash[2781129]: 2024-05-31T23:17:58.440Z DEBUG   gossipd: channel_announcement: got reply for 2253219x34x0...
Fri 2024-05-31 16:17:58 PDT home3 bash[2781129]: 2024-05-31T23:17:58.610Z DEBUG   gossipd: channel_announcement: got reply for 2283364x5x1...
Fri 2024-05-31 16:17:58 PDT home3 bash[2781129]: 2024-05-31T23:17:58.668Z DEBUG   gossipd: channel_announcement: got reply for 2341197x7x1...
Fri 2024-05-31 16:17:58 PDT home3 bash[2781129]: 2024-05-31T23:17:58.875Z DEBUG   gossipd: channel_announcement: got reply for 2377197x18x0...
Fri 2024-05-31 16:17:59 PDT home3 bash[2781129]: 2024-05-31T23:17:59.066Z DEBUG   gossipd: channel_announcement: got reply for 2414752x35x0...
Fri 2024-05-31 16:17:59 PDT home3 bash[2781129]: 2024-05-31T23:17:59.240Z DEBUG   gossipd: channel_announcement: got reply for 2425324x31x0...
Fri 2024-05-31 16:17:59 PDT home3 bash[2781129]: 2024-05-31T23:17:59.408Z DEBUG   gossipd: channel_announcement: got reply for 2425529x48x0...
Fri 2024-05-31 16:17:59 PDT home3 bash[2781129]: 2024-05-31T23:17:59.540Z DEBUG   gossipd: channel_announcement: got reply for 2470391x23x1...
Fri 2024-05-31 16:17:59 PDT home3 bash[2781129]: 2024-05-31T23:17:59.799Z DEBUG   gossipd: channel_announcement: got reply for 2580905x211x0...
Fri 2024-05-31 16:17:59 PDT home3 bash[2781129]: 2024-05-31T23:17:59.802Z DEBUG   gossipd: channel_announcement: got reply for 2580905x212x0...
Fri 2024-05-31 16:17:59 PDT home3 bash[2781129]: 2024-05-31T23:17:59.803Z DEBUG   gossipd: channel_announcement: got reply for 2580905x214x0...
Fri 2024-05-31 16:17:59 PDT home3 bash[2781129]: 2024-05-31T23:17:59.903Z DEBUG   gossipd: channel_announcement: got reply for 2742982x122x1...
Fri 2024-05-31 16:18:00 PDT home3 bash[2781129]: 2024-05-31T23:18:00.067Z DEBUG   gossipd: channel_announcement: got reply for 2254120x9x0...
Fri 2024-05-31 16:18:00 PDT home3 bash[2781129]: 2024-05-31T23:18:00.116Z DEBUG   gossipd: channel_announcement: got reply for 2254203x3x1...
Fri 2024-05-31 16:18:00 PDT home3 bash[2781129]: 2024-05-31T23:18:00.169Z DEBUG   gossipd: channel_announcement: got reply for 2254213x11x0...
Fri 2024-05-31 16:18:00 PDT home3 bash[2781129]: 2024-05-31T23:18:00.220Z DEBUG   gossipd: channel_announcement: got reply for 2254240x12x0...
Fri 2024-05-31 16:18:00 PDT home3 bash[2781129]: 2024-05-31T23:18:00.327Z DEBUG   gossipd: channel_announcement: got reply for 2254241x12x0...
Fri 2024-05-31 16:18:00 PDT home3 bash[2781129]: 2024-05-31T23:18:00.446Z DEBUG   gossipd: channel_announcement: got reply for 2254288x30x0...
Fri 2024-05-31 16:18:00 PDT home3 bash[2781129]: 2024-05-31T23:18:00.760Z DEBUG   gossipd: channel_announcement: got reply for 2254328x82x0...
Fri 2024-05-31 16:18:00 PDT home3 bash[2781129]: 2024-05-31T23:18:00.874Z DEBUG   gossipd: channel_announcement: got reply for 2314390x20x0...
Fri 2024-05-31 16:18:01 PDT home3 bash[2781129]: 2024-05-31T23:18:01.086Z DEBUG   gossipd: channel_announcement: got reply for 2350306x38x0...
Fri 2024-05-31 16:18:01 PDT home3 sshd[2816561]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=14.18.41.74  user=root
Fri 2024-05-31 16:18:02 PDT home3 bash[2781129]: 2024-05-31T23:18:02.286Z DEBUG   gossipd: channel_announcement: got reply for 2350464x144x0...
Fri 2024-05-31 16:18:02 PDT home3 bash[2781129]: 2024-05-31T23:18:02.527Z DEBUG   gossipd: channel_announcement: got reply for 2377268x31x1...
Fri 2024-05-31 16:18:02 PDT home3 bash[2781129]: 2024-05-31T23:18:02.798Z DEBUG   gossipd: channel_announcement: got reply for 2377394x24x1...
Fri 2024-05-31 16:18:03 PDT home3 bash[2781129]: 2024-05-31T23:18:03.207Z DEBUG   gossipd: channel_announcement: got reply for 2407754x104x1...
Fri 2024-05-31 16:18:03 PDT home3 bash[2781129]: 2024-05-31T23:18:03.310Z DEBUG   gossipd: channel_announcement: got reply for 2412248x32x1...
Fri 2024-05-31 16:18:03 PDT home3 bash[2781129]: 2024-05-31T23:18:03.446Z DEBUG   gossipd: channel_announcement: got reply for 2416158x36x0...
Fri 2024-05-31 16:18:03 PDT home3 bash[2781129]: 2024-05-31T23:18:03.639Z DEBUG   gossipd: channel_announcement: got reply for 2419024x27x1...
Fri 2024-05-31 16:18:03 PDT home3 sshd[2816561]: Failed password for root from 14.18.41.74 port 41094 ssh2
Fri 2024-05-31 16:18:03 PDT home3 bash[2781129]: 2024-05-31T23:18:03.823Z DEBUG   gossipd: channel_announcement: got reply for 2419337x70x0...
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.037Z DEBUG   gossipd: channel_announcement: got reply for 2426282x48x0...
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.202Z DEBUG   gossipd: channel_announcement: got reply for 2428583x34x0...
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.338Z DEBUG   gossipd: channel_announcement: got reply for 2428586x103x0...
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.386Z DEBUG   gossipd: channel_announcement: got reply for 2429362x51x1...
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.565Z DEBUG   gossipd: channel_announcement: got reply for 2431011x78x1...
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.703Z DEBUG   gossipd: channel_announcement: got reply for 2433784x13x4...
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.822Z DEBUG   gossipd: channel_announcement: got reply for 2439145x38x2...
Fri 2024-05-31 16:18:04 PDT home3 sshd[2816561]: Connection closed by authenticating user root 14.18.41.74 port 41094 [preauth]
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.938Z DEBUG   gossipd: channel_announcement: got reply for 2441943x19x0...
Fri 2024-05-31 16:18:04 PDT home3 bash[2781129]: 2024-05-31T23:18:04.997Z DEBUG   gossipd: channel_announcement: got reply for 2505219x74x0...
Fri 2024-05-31 16:18:06 PDT home3 bash[2781129]: 2024-05-31T23:18:06.094Z DEBUG   plugin-bcli: Feerate min_acceptable raised from 53234 perkb to floor of 100000
Fri 2024-05-31 16:18:07 PDT home3 bash[2781224]: lightning_gossipd: gossip_store: get delete entry offset 769455/3841798 (version v24.05rc2-23-g1563919)
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36fd77c send_backtrace
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         common/daemon.c:33
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a3706f6c status_failed
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         common/status.c:221
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f3a23 gossip_store_get_with_hdr
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossip_store.c:466
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f3a9d check_msg_type
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossip_store.c:491
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f3c30 gossip_store_set_flag
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossip_store.c:509
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f3e7c gossip_store_del
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossip_store.c:561
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f47dd process_node_announcement
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossmap_manage.c:942
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f5a21 reprocess_queued_msgs
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossmap_manage.c:1140
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f5e3c gossmap_manage_handle_get_txout_reply
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossmap_manage.c:698
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f216a recv_req
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossipd.c:585
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36fda92 handle_read
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         common/daemon_conn.c:35
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a3840ae3 next_plan
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         ccan/ccan/io/io.c:60
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a3840fbe do_plan
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         ccan/ccan/io/io.c:408
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a384105b io_ready
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         ccan/ccan/io/io.c:418
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a3842a27 io_loop
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         ccan/ccan/io/poll.c:455
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36f2b85 main
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         gossipd/gossipd.c:683
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x78ae84629d8f __libc_start_call_main
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         ../sysdeps/nptl/libc_start_call_main.h:58
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x78ae84629e3f __libc_start_main_impl
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         ../csu/libc-start.c:392
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0x63c1a36ef7c4 ???
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         ???:0
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]: 0xffffffffffffffff ???
Fri 2024-05-31 16:18:08 PDT home3 bash[2781224]:         ???:0
Fri 2024-05-31 16:18:08 PDT home3 bash[2781129]: 2024-05-31T23:18:08.155Z DEBUG   gossipd: channel_announcement: got reply for 2540278x27x0...
Fri 2024-05-31 16:18:08 PDT home3 bash[2781129]: 2024-05-31T23:18:08.155Z DEBUG   02312627fdf07fbdd7e5ddb136611bdde9b00d26821d14d94891395452f67af248-gossipd: Received channel_update for channel 1667946x1x0/1 now DISABLED
Fri 2024-05-31 16:18:08 PDT home3 bash[2781129]: 2024-05-31T23:18:08.155Z DEBUG   02312627fdf07fbdd7e5ddb136611bdde9b00d26821d14d94891395452f67af248-gossipd: Received channel_update for channel 1666602x199x0/0 now DISABLED
Fri 2024-05-31 16:18:08 PDT home3 bash[2781129]: 2024-05-31T23:18:08.155Z DEBUG   02312627fdf07fbdd7e5ddb136611bdde9b00d26821d14d94891395452f67af248-gossipd: Received channel_update for channel 1721908x57x0/0 now DISABLED
ksedgwic commented 5 months ago

If it's a clue, I had just seeded the node's gossip w/ three connections to the top three nodes at mempool.space:

 1082  lightning-cli --testnet connect 02312627fdf07fbdd7e5ddb136611bdde9b00d26821d14d94891395452f67af248@23.237.77.12:9735
 1083  lightning-cli --testnet connect 038863cf8ab91046230f561cd5b386cbff8309fa02e3f0c3ed161a3aeb64a643b9@203.132.94.196:9735
 1084  lightning-cli --testnet connect 031c64a68e6d1b9e50711336d92b434c584ce668b2fae59ee688bd73713fee1569@186.154.207.228:9735

Is there a problem w/ fast concurrent gossip from multiple sources?

overcoin commented 5 months ago

I'm really curious if people that use postgresql instead of sqlite experience same issue?