Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

lightning-rpc file isn't created #8035

Open
NicolasDorier opened this issue Jan 27, 2025 · 8 comments
Open

lightning-rpc file isn't created #8035

NicolasDorier opened this issue Jan 27, 2025 · 8 comments
Assignees
Milestone

Comments

@NicolasDorier
Copy link
Collaborator

It seems that several of BTCPay Server users are experiencing an issue with core-lightning 24.08.2.

It is hard to say when it started, but I have this issue now on two servers.

Core lightning seems to be running fine, but the lightning-rpc isn't created.

Config

bitcoin-datadir=/etc/bitcoin
bitcoin-rpcconnect=bitcoind
experimental-offers
database-upgrade=true
rpc-file-mode=0666
clnrest-port=3010
clnrest-protocol=http
clnrest-host=0.0.0.0
log-level=debug
proxy=tor:9050

bind-addr=0.0.0.0:9735
network=bitcoin
announce-addr=....
announce-addr=....
rpc-file=/root/.lightning/lightning-rpc

Logs

2025-01-27T09:13:16.006Z INFO    lightningd: basedon-v24.08.2
2025-01-27T09:13:17.124Z DEBUG   plugin-manager: started(16) /usr/local/libexec/c-lightning/plugins/autoclean
2025-01-27T09:13:17.133Z DEBUG   plugin-manager: started(17) /usr/local/libexec/c-lightning/plugins/chanbackup
2025-01-27T09:13:17.141Z DEBUG   plugin-manager: started(18) /usr/local/libexec/c-lightning/plugins/bcli
2025-01-27T09:13:17.147Z DEBUG   plugin-manager: started(19) /usr/local/libexec/c-lightning/plugins/commando
2025-01-27T09:13:17.154Z DEBUG   plugin-manager: started(20) /usr/local/libexec/c-lightning/plugins/funder
2025-01-27T09:13:17.161Z DEBUG   plugin-manager: started(21) /usr/local/libexec/c-lightning/plugins/topology
2025-01-27T09:13:17.168Z DEBUG   plugin-manager: started(22) /usr/local/libexec/c-lightning/plugins/keysend
2025-01-27T09:13:17.175Z DEBUG   plugin-manager: started(23) /usr/local/libexec/c-lightning/plugins/offers
2025-01-27T09:13:17.181Z DEBUG   plugin-manager: started(24) /usr/local/libexec/c-lightning/plugins/pay
2025-01-27T09:13:17.189Z DEBUG   plugin-manager: started(25) /usr/local/libexec/c-lightning/plugins/recklessrpc
2025-01-27T09:13:17.195Z DEBUG   plugin-manager: started(26) /usr/local/libexec/c-lightning/plugins/recover
2025-01-27T09:13:17.202Z DEBUG   plugin-manager: started(27) /usr/local/libexec/c-lightning/plugins/txprepare
2025-01-27T09:13:17.210Z DEBUG   plugin-manager: started(28) /usr/local/libexec/c-lightning/plugins/cln-renepay
2025-01-27T09:13:17.220Z DEBUG   plugin-manager: started(29) /usr/local/libexec/c-lightning/plugins/spenderp
2025-01-27T09:13:17.226Z DEBUG   plugin-manager: started(30) /usr/local/libexec/c-lightning/plugins/cln-askrene
2025-01-27T09:13:17.232Z DEBUG   plugin-manager: started(31) /usr/local/libexec/c-lightning/plugins/sql
2025-01-27T09:13:17.237Z DEBUG   plugin-manager: started(32) /usr/local/libexec/c-lightning/plugins/cln-grpc
2025-01-27T09:13:17.243Z DEBUG   plugin-manager: started(33) /usr/local/libexec/c-lightning/plugins/bookkeeper
2025-01-27T09:13:17.249Z DEBUG   plugin-manager: started(35) /usr/local/libexec/c-lightning/plugins/clnrest/clnrest
2025-01-27T09:13:17.255Z DEBUG   plugin-manager: started(36) /usr/local/libexec/c-lightning/plugins/wss-proxy/wss-proxy
2025-01-27T09:13:17.263Z DEBUG   plugin-manager: started(37) /root/.lightning/plugins/invoicewithdescriptionhash
2025-01-27T09:13:18.171Z UNUSUAL plugin-bookkeeper: topic 'utxo_deposit' is not a known notification topic
2025-01-27T09:13:18.171Z UNUSUAL plugin-bookkeeper: topic 'utxo_spend' is not a known notification topic
2025-01-27T09:13:18.171Z DEBUG   lightningd: io_break: check_plugins_manifests
2025-01-27T09:13:18.171Z DEBUG   lightningd: io_loop_with_timers: plugins_init
2025-01-27T09:13:18.179Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_channeld
2025-01-27T09:13:18.187Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_closingd
2025-01-27T09:13:18.194Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_connectd
2025-01-27T09:13:18.198Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_gossipd
2025-01-27T09:13:18.202Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_hsmd
2025-01-27T09:13:18.205Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_onchaind
2025-01-27T09:13:18.211Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_openingd
2025-01-27T09:13:18.216Z DEBUG   hsmd: pid 51, msgfd 57
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_CHECK_PUBKEY
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_ANY_DELAYED_PAYMENT_TO_US
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_ANCHORSPEND
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_HTLC_TX_MINGLE
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_SPLICE_TX
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_CHECK_OUTPOINT
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_FORGET_CHANNEL
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_REVOKE_COMMITMENT_TX
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_SIGN_BOLT12_2
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_PREAPPROVE_INVOICE_CHECK
2025-01-27T09:13:18.219Z DEBUG   hsmd: capability +WIRE_HSMD_PREAPPROVE_KEYSEND_CHECK
2025-01-27T09:13:22.136Z DEBUG   connectd: pid 52, msgfd 61
2025-01-27T09:13:22.136Z DEBUG   hsmd: Client: Received message 27 from client
2025-01-27T09:13:22.136Z DEBUG   hsmd: Client: Received message 27 from client
2025-01-27T09:13:22.136Z DEBUG   hsmd: Client: Received message 27 from client
2025-01-27T09:13:22.136Z DEBUG   hsmd: new_client: 0
2025-01-27T09:13:22.166Z DEBUG   connectd: Proxy address: 172.19.0.11:9050
2025-01-27T09:13:22.166Z DEBUG   connectd: Created listener on 0.0.0.0:9735
2025-01-27T09:13:22.166Z DEBUG   connectd: REPLY WIRE_CONNECTD_INIT_REPLY with 0 fds
2025-01-27T09:13:22.166Z DEBUG   lightningd: io_break: connect_init_done
2025-01-27T09:13:22.166Z DEBUG   lightningd: io_loop: connectd_init
2025-01-27T09:13:22.232Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
2025-01-27T09:13:22.232Z DEBUG   lightningd: io_break: plugin_config_cb
2025-01-27T09:13:22.232Z DEBUG   lightningd: io_loop_with_timers: config_plugin
2025-01-27T09:13:22.232Z DEBUG   lightningd: All Bitcoin plugin commands registered
2025-01-27T09:13:22.768Z DEBUG   lightningd: Adding block 846278: 00000000000000000002dfdec0128767130197235d745eacc64660b7f4ce034d
2025-01-27T09:13:22.898Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.899Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.900Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.900Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.901Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.902Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.903Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.903Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.904Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.906Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.907Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.908Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.909Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.909Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.910Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.911Z DEBUG   wallet: Loaded 0 HTLC signatures from DB
2025-01-27T09:13:22.911Z DEBUG   wallet: Loaded 16 channels from DB
2025-01-27T09:13:22.911Z DEBUG   02907887f9bfcc9e83512bfdf40ddfdabcb8569786f11ac3e9c52c42d77da3eb6b-chan#6477: Loading in HTLCs for channel 6477 (state=CHANNELD_NORMAL)
2025-01-27T09:13:22.925Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:22.925Z DEBUG   0207c1a319f33301309685c4ddf948943c29e79b529d5b21b02ba47b380ba1e891-chan#67: Loading in HTLCs for channel 67 (state=CHANNELD_NORMAL)
2025-01-27T09:13:22.925Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:22.925Z DEBUG   034ea80f8b148c750463546bd999bf7321a0e6dfc60aaf84bd0400a2e8d376c0d5-chan#5: Loading in HTLCs for channel 5 (state=CHANNELD_NORMAL)
2025-01-27T09:13:22.959Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:22.959Z DEBUG   037b6d276f7a3c5835b43d0e1d7c2204d4344feed775d865643c15f1ce19f5e952-chan#346: Loading in HTLCs for channel 346 (state=CHANNELD_NORMAL)
2025-01-27T09:13:22.966Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:22.967Z DEBUG   03a718f9f5acf1a4b488b88f1fbc50b07fad37d8d5d510e4970652bf3b433d03a4-chan#1578: Loading in HTLCs for channel 1578 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.067Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.068Z DEBUG   034c347e36cdc5cd3484c1b1b986945ad8c20619b889af17a6991cb664b8e06a3a-chan#5110: Loading in HTLCs for channel 5110 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.074Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.074Z DEBUG   022a4ffb8f874d9df65783f5b1d888a84e8df733ca399dcb2c14026dca107082dd-chan#5213: Loading in HTLCs for channel 5213 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.074Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.074Z DEBUG   0351876efe01167a1f81f988ef470311eca17661dd1994bad01861d4a54565bc5c-chan#5664: Loading in HTLCs for channel 5664 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.074Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.074Z DEBUG   030059ea3a156fd36b4826a171989bd48fd83baf829864feab3fa807b42943b220-chan#5046: Loading in HTLCs for channel 5046 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.074Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.074Z DEBUG   02c69ee990b25ed36e92a29b64ada7d4bdeca47c7269fa74fc0e3def5f443a9e92-chan#1632: Loading in HTLCs for channel 1632 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.075Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.075Z DEBUG   0296fe7513262a289a1a787df321ba8583c998411994aa3a2be367cf6c374a144d-chan#1612: Loading in HTLCs for channel 1612 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.078Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.078Z DEBUG   0384b220ab8701207f6e4b3576517c6390276ee9ee40b1d0c97e96579190e5c946-chan#92: Loading in HTLCs for channel 92 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.091Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.091Z DEBUG   025e833bcd832a3bb23684a774cb155ad0973950d5d884c310319f97823b49ee75-chan#1294: Loading in HTLCs for channel 1294 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.091Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.091Z DEBUG   0243054886aa6026a4312583bab952dad7723f840d037884d5a72b729fdb52ecbd-chan#2095: Loading in HTLCs for channel 2095 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.139Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.139Z DEBUG   024493961860471995ff826aeab557834d61523240e20e118986cd2c6e8d1e6430-chan#5167: Loading in HTLCs for channel 5167 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.140Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.140Z DEBUG   038bcc6471941c7d6c14a8ce5b7159d8f73a3a0bb9a93e8896bcb892e14552658a-chan#2634: Loading in HTLCs for channel 2634 (state=CHANNELD_NORMAL)
2025-01-27T09:13:23.899Z DEBUG   wallet: Restored 0 incoming HTLCS
2025-01-27T09:13:23.904Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.904Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.909Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.909Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.921Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.922Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.922Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.922Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.923Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.923Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.924Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.927Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.927Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.934Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:23.934Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:24.064Z DEBUG   wallet: Restored 0 outgoing HTLCS
2025-01-27T09:13:24.075Z DEBUG   gossipd: pid 62, msgfd 60
2025-01-27T09:13:24.076Z DEBUG   hsmd: new_client: 0

Note that after DEBUG hsmd: new_client: 0, nothing happen. No more logs ever happen even with log-level=debug.

@NicolasDorier
Copy link
Collaborator Author

Strange thing is that when I checked again today, lightning-rpc was there! However, it was impossible to connect to it (connection refused).

When I deleted it and restarted the container, it doesn't recreate it.
I tried to remove tor as well, to no effect.

@NicolasDorier
Copy link
Collaborator Author

NicolasDorier commented Jan 31, 2025

I think tracking this issue might be hard for you.
I have a machine that "fixed itself", and another one still broken. Same deployment/config.

If some of you have a commit I can cherry pick adding printf logs left and right to narrow down the issue, I can build it and tweak it myself to help find the issue.

@rustyrussell
Copy link
Contributor

This implies gossipd isn't starting up properly: we expect to see "io_break: gossipd_init_done".

The next line, in fact, should be " DEBUG gossipd: Store compact time: NNN msec". Is it stuck reading the gossip store somehow? Is it large and/or strange?

@NicolasDorier
Copy link
Collaborator Author

NicolasDorier commented Feb 4, 2025

Thanks for looking at it @rustyrussell

So here are the logs that have shown after 20 min or so, it actually seems cln restart continuously. The hsmd: new_client: 0 is stuck for 23 minutes. Then plugin-topology crashes the instance.

Additional context: We run on pruned nodes.

Also

Rune already created
lightningd "$@"

Are logs coming from our docker container, you can dismiss this. However, the fact we see that mean that the lighting-rpc connection worked a little bit before the instance crash.

2025-02-04T05:29:32.561Z DEBUG   hsmd: new_client: 0
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
2025-02-04T05:53:28.582Z DEBUG   gossipd: Store compact time: 1429910 msec
2025-02-04T05:53:28.583Z DEBUG   gossipd: gossip_store: Read 62716143/1739952/5158256/0 cannounce/cupdate/nannounce/delete from store in 31634458462 bytes, now 31634458440 bytes (populated=true)
2025-02-04T05:53:28.584Z DEBUG   gossipd: seeker: state = STARTING_UP New seeker
2025-02-04T05:53:28.584Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_INIT_REPLY with 0 fds
2025-02-04T05:53:28.584Z UNUSUAL 0384b220ab8701207f6e4b3576517c6390276ee9ee40b1d0c97e96579190e5c946-chan#92: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.593Z UNUSUAL 034c347e36cdc5cd3484c1b1b986945ad8c20619b889af17a6991cb664b8e06a3a-chan#5110: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.595Z UNUSUAL 034ea80f8b148c750463546bd999bf7321a0e6dfc60aaf84bd0400a2e8d376c0d5-chan#5: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.596Z UNUSUAL 03a718f9f5acf1a4b488b88f1fbc50b07fad37d8d5d510e4970652bf3b433d03a4-chan#1578: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.598Z UNUSUAL 0296fe7513262a289a1a787df321ba8583c998411994aa3a2be367cf6c374a144d-chan#1612: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.599Z UNUSUAL 038bcc6471941c7d6c14a8ce5b7159d8f73a3a0bb9a93e8896bcb892e14552658a-chan#2634: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.601Z UNUSUAL 030059ea3a156fd36b4826a171989bd48fd83baf829864feab3fa807b42943b220-chan#5046: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.602Z UNUSUAL 024493961860471995ff826aeab557834d61523240e20e118986cd2c6e8d1e6430-chan#5167: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.603Z UNUSUAL 0351876efe01167a1f81f988ef470311eca17661dd1994bad01861d4a54565bc5c-chan#5664: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.604Z UNUSUAL 037b6d276f7a3c5835b43d0e1d7c2204d4344feed775d865643c15f1ce19f5e952-chan#346: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.605Z UNUSUAL 0243054886aa6026a4312583bab952dad7723f840d037884d5a72b729fdb52ecbd-chan#2095: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.606Z UNUSUAL 022a4ffb8f874d9df65783f5b1d888a84e8df733ca399dcb2c14026dca107082dd-chan#5213: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.608Z UNUSUAL 02907887f9bfcc9e83512bfdf40ddfdabcb8569786f11ac3e9c52c42d77da3eb6b-chan#6477: gossipd lost track of announced channel: re-announcing!
2025-02-04T05:53:28.609Z DEBUG   lightningd: io_break: gossipd_init_done
2025-02-04T05:53:28.610Z DEBUG   lightningd: io_loop: gossip_init
2025-02-04T05:53:28.648Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 6 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.649Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.650Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.650Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.651Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.651Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.651Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.651Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 3 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 4 from client
2025-02-04T05:53:28.652Z DEBUG   hsmd: Client: Received message 3 from client
plugin-invoicewithdescriptionhash  initialized plugin v1.4
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
2025-02-04T05:53:29.750Z DEBUG   plugin-cln-grpc: Killing plugin: disabled itself at init: Missing 'grpc-port' option
2025-02-04T05:53:29.751Z DEBUG   lightningd: Looking for [autoclean,succeededforwards,num]
2025-02-04T05:53:29.751Z DEBUG   plugin-clnrest: REST Server is starting at http://0.0.0.0:3010
2025-02-04T05:53:29.751Z INFO    plugin-clnrest: REST server running at http://0.0.0.0:3010
2025-02-04T05:53:29.751Z DEBUG   plugin-wss-proxy: Initiating websocket secure server...
2025-02-04T05:53:29.751Z DEBUG   plugin-wss-proxy: Killing plugin: disabled itself at init: `wss-bind-addr` option is not configured
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_CHANNEL_ANNOUNCEMENT
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_CHANNEL_UPDATE
2025-02-04T05:53:29.752Z DEBUG   gossipd: Bad gossip order: Unknown channel 697603x792x0
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_NODE_ANNOUNCEMENT
2025-02-04T05:53:29.752Z DEBUG   gossipd: Received node_announcement for node 029c20772e97f6ce82d2dd15f589182d4fd1d15c582819fe017da7d8215f534dc1
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_CHANNEL_ANNOUNCEMENT
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_CHANNEL_UPDATE
2025-02-04T05:53:29.752Z DEBUG   gossipd: Bad gossip order: Unknown channel 759744x1289x0
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_CHANNEL_ANNOUNCEMENT
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_CHANNEL_UPDATE
2025-02-04T05:53:29.752Z DEBUG   gossipd: Bad gossip order: Unknown channel 695761x2281x0
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_CHANNEL_ANNOUNCEMENT
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: inject_gossip: WIRE_CHANNEL_UPDATE
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:29.752Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_ADDGOSSIP_REPLY with 0 fds
2025-02-04T05:53:30.117Z DEBUG   lightningd: Looking for [autoclean,failedforwards,num]
2025-02-04T05:53:30.924Z DEBUG   lightningd: Looking for [autoclean,succeededpays,num]
2025-02-04T05:53:30.928Z DEBUG   hsmd: Client: Received message 27 from client
2025-02-04T05:53:30.932Z DEBUG   lightningd: Looking for [autoclean,failedpays,num]
2025-02-04T05:53:31.580Z DEBUG   plugin-chanbackup: Chanbackup Initialised!
2025-02-04T05:53:31.581Z DEBUG   lightningd: Looking for [autoclean,paidinvoices,num]
2025-02-04T05:53:31.584Z DEBUG   plugin-recklessrpc: plugin initialized!
2025-02-04T05:53:31.584Z DEBUG   plugin-recklessrpc: lightning-dir: /root/.lightning
2025-02-04T05:53:32.024Z DEBUG   lightningd: Looking for [autoclean,expiredinvoices,num]
2025-02-04T05:53:32.025Z DEBUG   plugin-clnrest: Client Connecting...
2025-02-04T05:53:32.326Z DEBUG   hsmd: Client: Received message 27 from client
2025-02-04T05:53:32.330Z DEBUG   hsmd: Client: Received message 27 from client
2025-02-04T05:53:32.332Z DEBUG   plugin-bookkeeper: Setting up database at sqlite3://accounts.sqlite3
2025-02-04T05:53:32.332Z DEBUG   hsmd: Client: Received message 27 from client
2025-02-04T05:53:32.350Z DEBUG   plugin-clnrest: Client Connected
Rune already created
lightningd "$@"
cln-askrene: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!
2025-02-04T05:54:29.806Z UNUSUAL plugin-topology: Killing plugin: timed out before replying to init
2025-02-04T05:54:29.808Z **BROKEN** plugin-topology: Plugin marked as important, shutting down lightningd!
2025-02-04T05:54:29.808Z DEBUG   lightningd: io_break: lightningd_exit
Can't recover from plugin failure, terminating.
Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.network=bitcoin added in /root/.lightning/config

@NicolasDorier
Copy link
Collaborator Author

May be related to #7724

@pavlenex
Copy link

pavlenex commented Feb 6, 2025

Would be awesome to get this unblocked, since BitcoinSmiles initiative is eagerly waiting to start a new campaign, but their node is down for quite a while and blocked by this (they couldn't receive new donations for weeks now) and it would really be bad to push them into using custodial node solution or an alternative implementation, since CLN worked for them great since 2021, plus there's still funds and channels there. Thanks you guys!

@rustyrussell
Copy link
Contributor

OK, I've got it. It's actually related to this:

lightning_gossipd: gossmap: redundant channel_announce for 864063x1306x1, offsets 1272259 and 1784859!"

We stall there and don't make more progress. So gossipd itself doesn't see the entire gossip_store.

Then things get really batshit:

2025-02-04T05:53:28.582Z DEBUG   gossipd: Store compact time: 1429910 msec

This took 1429 seconds to process. Why?

Because it hasn't been processing the gossip store fully, gossipd kept adding "new" records to the end:

2025-02-04T05:53:28.583Z DEBUG   gossipd: gossip_store: Read 62716143/1739952/5158256/0 cannounce/cupdate/nannounce/delete from store in 31634458462 bytes, now 31634458440 bytes (populated=true)

It has 31GB of gossip in there! No wonder it took so long, and no wonder topology plugin (which tried to digest that crap) timed out.

@rustyrussell
Copy link
Contributor

rustyrussell commented Feb 7, 2025

Hmm, can you send me the first 2MB of the gossip_store file BTW? And your node id?

You should delete the gossip store once this is done, BTW, and this problem should resolve itself (for now: I'm still interested in HOW we got here...)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants