lightning
lightning copied to clipboard
ElementsProject
lightning-cli dev-memleak reports memleaks in lightningd.c while running clboss
I have a simple pytest for clboss and I can't seem to get it to pass, even with the most basic testing code.
Here's the test:
from pathlib import Path
from pyln.client.lightning import RpcError
from pyln.testing.fixtures import node_factory
CLBOSS_PLUGIN = Path.cwd().joinpath("../../clboss")
def test_rpc_clboss_status(node_factory):
pluginopt = {'plugin': CLBOSS_PLUGIN}
l1 = node_factory.get_node(options=pluginopt)
And here's the output:
$ VALGRIND=0 poetry run pytest -v
==================================================================================== test session starts =====================================================================================
platform linux -- Python 3.12.3, pytest-7.4.3, pluggy-1.3.0 -- /home/cguida/.cache/pypoetry/virtualenvs/tests-H63Gdp_e-py3.12/bin/python
cachedir: .pytest_cache
rootdir: /home/cguida/work/clboss/tests/plugins-ci
plugins: timeout-2.2.0
collected 1 item
test_rpc.py::test_rpc_clboss_status PASSED [100%]
test_rpc.py::test_rpc_clboss_status ERROR [100%]
=========================================================================================== ERRORS ===========================================================================================
________________________________________________________________________ ERROR at teardown of test_rpc_clboss_status _________________________________________________________________________
request = <SubRequest 'teardown_checks' for <Function test_rpc_clboss_status>>
@pytest.fixture
def teardown_checks(request):
"""A simple fixture to collect errors during teardown.
We need to collect the errors and raise them as the very last step in the
fixture tree, otherwise some fixtures may not be cleaned up
correctly. Require this fixture in all other fixtures that need to either
cleanup before reporting an error or want to add an error that is to be
reported.
"""
errors = TeardownErrors()
yield errors
if errors.has_errors():
# Format a nice list of everything that went wrong and raise an exception
request.node.has_errors = True
> raise ValueError(str(errors))
E ValueError:
E Node errors:
E - lightningd-1: had BROKEN messages
E - lightningd-1: had memleak messages
E Global errors:
E - Node /tmp/ltests-yiqcqbc6/test_rpc_clboss_status_1/lightning-1/ has memory leaks: [
E {
E "subdaemon": "lightningd"
E }
E ]
../../../../.cache/pypoetry/virtualenvs/tests-H63Gdp_e-py3.12/lib/python3.12/site-packages/pyln/testing/fixtures.py:206: ValueError
----------------------------------------------------------------------------------- Captured stdout setup ------------------------------------------------------------------------------------
Running tests in /tmp/ltests-yiqcqbc6
------------------------------------------------------------------------------------ Captured stdout call ------------------------------------------------------------------------------------
lightningd-1 2024-10-04T01:29:47.615Z INFO lightningd: v24.08.1-modded
lightningd-1 2024-10-04T01:29:47.804Z DEBUG lightningd: Opened log file -
lightningd-1 2024-10-04T01:29:47.804Z DEBUG lightningd: Opened log file /tmp/ltests-yiqcqbc6/test_rpc_clboss_status_1/lightning-1/log
lightningd-1 2024-10-04T01:29:47.826Z DEBUG plugin-manager: started(508924) /usr/local/libexec/c-lightning/plugins/autoclean
lightningd-1 2024-10-04T01:29:47.836Z DEBUG plugin-manager: started(508925) /usr/local/libexec/c-lightning/plugins/chanbackup
lightningd-1 2024-10-04T01:29:47.846Z DEBUG plugin-manager: started(508926) /usr/local/libexec/c-lightning/plugins/bcli
lightningd-1 2024-10-04T01:29:47.857Z DEBUG plugin-manager: started(508927) /usr/local/libexec/c-lightning/plugins/commando
lightningd-1 2024-10-04T01:29:47.869Z DEBUG plugin-manager: started(508928) /usr/local/libexec/c-lightning/plugins/funder
lightningd-1 2024-10-04T01:29:47.879Z DEBUG plugin-manager: started(508929) /usr/local/libexec/c-lightning/plugins/topology
lightningd-1 2024-10-04T01:29:47.889Z DEBUG plugin-manager: started(508930) /usr/local/libexec/c-lightning/plugins/keysend
lightningd-1 2024-10-04T01:29:47.900Z DEBUG plugin-manager: started(508931) /usr/local/libexec/c-lightning/plugins/offers
lightningd-1 2024-10-04T01:29:47.910Z DEBUG plugin-manager: started(508932) /usr/local/libexec/c-lightning/plugins/pay
lightningd-1 2024-10-04T01:29:47.920Z DEBUG plugin-manager: started(508933) /usr/local/libexec/c-lightning/plugins/recklessrpc
lightningd-1 2024-10-04T01:29:47.931Z DEBUG plugin-manager: started(508934) /usr/local/libexec/c-lightning/plugins/recover
lightningd-1 2024-10-04T01:29:47.941Z DEBUG plugin-manager: started(508935) /usr/local/libexec/c-lightning/plugins/txprepare
lightningd-1 2024-10-04T01:29:47.951Z DEBUG plugin-manager: started(508936) /usr/local/libexec/c-lightning/plugins/cln-renepay
lightningd-1 2024-10-04T01:29:47.962Z DEBUG plugin-manager: started(508937) /usr/local/libexec/c-lightning/plugins/spenderp
lightningd-1 2024-10-04T01:29:47.972Z DEBUG plugin-manager: started(508938) /usr/local/libexec/c-lightning/plugins/cln-askrene
lightningd-1 2024-10-04T01:29:47.983Z DEBUG plugin-manager: started(508939) /usr/local/libexec/c-lightning/plugins/sql
lightningd-1 2024-10-04T01:29:47.994Z DEBUG plugin-manager: started(508940) /usr/local/libexec/c-lightning/plugins/cln-grpc
lightningd-1 2024-10-04T01:29:48.005Z DEBUG plugin-manager: started(508941) /usr/local/libexec/c-lightning/plugins/bookkeeper
lightningd-1 2024-10-04T01:29:48.016Z DEBUG plugin-manager: started(508944) /usr/local/libexec/c-lightning/plugins/clnrest/clnrest
lightningd-1 2024-10-04T01:29:48.027Z DEBUG plugin-manager: started(508945) /usr/local/libexec/c-lightning/plugins/wss-proxy/wss-proxy
lightningd-1 2024-10-04T01:29:48.038Z DEBUG plugin-manager: started(508946) /home/cguida/work/clboss/clboss
lightningd-1 2024-10-04T01:29:48.061Z DEBUG plugin-cln-grpc: Plugin logging initialized
lightningd-1 2024-10-04T01:29:48.069Z INFO plugin-clnrest: Killing plugin: disabled itself: No module named 'gevent'
lightningd-1 2024-10-04T01:29:48.069Z INFO plugin-wss-proxy: Killing plugin: disabled itself: No module named 'websockets'
lightningd-1 2024-10-04T01:29:48.070Z UNUSUAL plugin-bookkeeper: topic 'utxo_deposit' is not a known notification topic
lightningd-1 2024-10-04T01:29:48.070Z UNUSUAL plugin-bookkeeper: topic 'utxo_spend' is not a known notification topic
lightningd-1 2024-10-04T01:29:48.071Z DEBUG lightningd: io_break: check_plugins_manifests
lightningd-1 2024-10-04T01:29:48.071Z DEBUG lightningd: io_loop_with_timers: plugins_init
lightningd-1 2024-10-04T01:29:48.072Z DEBUG lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_channeld
lightningd-1 2024-10-04T01:29:48.073Z DEBUG lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_closingd
lightningd-1 2024-10-04T01:29:48.074Z DEBUG lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_connectd
lightningd-1 2024-10-04T01:29:48.074Z DEBUG lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_gossipd
lightningd-1 2024-10-04T01:29:48.075Z DEBUG lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_hsmd
lightningd-1 2024-10-04T01:29:48.076Z DEBUG lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_onchaind
lightningd-1 2024-10-04T01:29:48.077Z DEBUG lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_openingd
lightningd-1 2024-10-04T01:29:48.079Z DEBUG hsmd: pid 508976, msgfd 56
lightningd-1 2024-10-04T01:29:48.079Z DEBUG hsmd: capability +WIRE_HSMD_CHECK_PUBKEY
lightningd-1 2024-10-04T01:29:48.079Z DEBUG hsmd: capability +WIRE_HSMD_SIGN_ANY_DELAYED_PAYMENT_TO_US
lightningd-1 2024-10-04T01:29:48.079Z DEBUG hsmd: capability +WIRE_HSMD_SIGN_ANCHORSPEND
lightningd-1 2024-10-04T01:29:48.079Z DEBUG hsmd: capability +WIRE_HSMD_SIGN_HTLC_TX_MINGLE
lightningd-1 2024-10-04T01:29:48.079Z DEBUG hsmd: capability +WIRE_HSMD_SIGN_SPLICE_TX
lightningd-1 2024-10-04T01:29:48.079Z DEBUG hsmd: capability +WIRE_HSMD_CHECK_OUTPOINT
lightningd-1 2024-10-04T01:29:48.079Z DEBUG hsmd: capability +WIRE_HSMD_FORGET_CHANNEL
lightningd-1 2024-10-04T01:29:48.080Z DEBUG hsmd: capability +WIRE_HSMD_REVOKE_COMMITMENT_TX
lightningd-1 2024-10-04T01:29:48.080Z DEBUG hsmd: capability +WIRE_HSMD_SIGN_BOLT12_2
lightningd-1 2024-10-04T01:29:48.080Z DEBUG hsmd: capability +WIRE_HSMD_PREAPPROVE_INVOICE_CHECK
lightningd-1 2024-10-04T01:29:48.080Z DEBUG hsmd: capability +WIRE_HSMD_PREAPPROVE_KEYSEND_CHECK
lightningd-1 2024-10-04T01:29:48.080Z INFO lightningd: Creating database
lightningd-1 2024-10-04T01:29:48.168Z DEBUG connectd: pid 508977, msgfd 60
lightningd-1 2024-10-04T01:29:48.169Z DEBUG hsmd: preinit: dev_fail_preapprove = 0, dev_no_preapprove_check = 0
lightningd-1 2024-10-04T01:29:48.169Z DEBUG hsmd: Client: Received message 27 from client
lightningd-1 2024-10-04T01:29:48.169Z DEBUG hsmd: Client: Received message 27 from client
lightningd-1 2024-10-04T01:29:48.169Z DEBUG hsmd: Client: Received message 27 from client
lightningd-1 2024-10-04T01:29:48.169Z DEBUG hsmd: new_client: 0
lightningd-1 2024-10-04T01:29:48.170Z DEBUG connectd: Created listener on 127.0.0.1:35829
lightningd-1 2024-10-04T01:29:48.170Z DEBUG connectd: REPLY WIRE_CONNECTD_INIT_REPLY with 0 fds
lightningd-1 2024-10-04T01:29:48.170Z DEBUG lightningd: io_break: connect_init_done
lightningd-1 2024-10-04T01:29:48.170Z DEBUG lightningd: io_loop: connectd_init
lightningd-1 2024-10-04T01:29:48.183Z INFO plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
lightningd-1 2024-10-04T01:29:48.183Z DEBUG lightningd: io_break: plugin_config_cb
lightningd-1 2024-10-04T01:29:48.183Z DEBUG lightningd: io_loop_with_timers: config_plugin
lightningd-1 2024-10-04T01:29:48.183Z DEBUG lightningd: All Bitcoin plugin commands registered
lightningd-1 2024-10-04T01:29:48.210Z DEBUG lightningd: Adding block 100: 3486689a2af290cb4acc1761a6151c31a8ef8ae6e466bbedf73db4f18a769aea
lightningd-1 2024-10-04T01:29:48.212Z DEBUG wallet: Loaded 0 channels from DB
lightningd-1 2024-10-04T01:29:48.212Z DEBUG lightningd: Increasing file descriptor limit to 65536 (0 channels, max is 1048576)
lightningd-1 2024-10-04T01:29:48.214Z DEBUG gossipd: pid 508987, msgfd 59
lightningd-1 2024-10-04T01:29:48.214Z DEBUG hsmd: new_client: 0
lightningd-1 2024-10-04T01:29:48.214Z DEBUG gossipd: Store compact time: 0 msec
lightningd-1 2024-10-04T01:29:48.214Z DEBUG gossipd: gossip_store: Read 0/0/0/0 cannounce/cupdate/nannounce/delete from store in 0 bytes, now 1 bytes (populated=false)
lightningd-1 2024-10-04T01:29:48.215Z DEBUG gossipd: seeker: state = STARTING_UP New seeker
lightningd-1 2024-10-04T01:29:48.215Z DEBUG gossipd: REPLY WIRE_GOSSIPD_INIT_REPLY with 0 fds
lightningd-1 2024-10-04T01:29:48.215Z DEBUG lightningd: io_break: gossipd_init_done
lightningd-1 2024-10-04T01:29:48.215Z DEBUG lightningd: io_loop: gossip_init
lightningd-1 2024-10-04T01:29:48.217Z DEBUG plugin-cln-grpc: Killing plugin: disabled itself at init: Missing 'grpc-port' option
lightningd-1 2024-10-04T01:29:48.218Z INFO plugin-clboss: clboss v0.14.0 (v0.14.0-rc2-0-gf014af3)
lightningd-1 2024-10-04T01:29:48.218Z INFO plugin-clboss: ChannelFeeManager: zerobasefee: allow
lightningd-1 2024-10-04T01:29:48.218Z DEBUG plugin-clboss: RPC socket opened.
lightningd-1 2024-10-04T01:29:48.221Z DEBUG plugin-clboss: Database file opened.
lightningd-1 2024-10-04T01:29:48.248Z DEBUG plugin-clboss: SwapManager: no more swaps need addresses
lightningd-1 2024-10-04T01:29:48.261Z DEBUG lightningd: Looking for [autoclean,succeededforwards,num]
lightningd-1 2024-10-04T01:29:48.262Z DEBUG plugin-clboss: Privkey file loaded.
lightningd-1 2024-10-04T01:29:48.262Z DEBUG plugin-clboss: Rpc out: getinfo {}
lightningd-1 2024-10-04T01:29:48.270Z DEBUG plugin-bookkeeper: Setting up database at sqlite3://accounts.sqlite3
lightningd-1 2024-10-04T01:29:48.270Z INFO plugin-bookkeeper: Creating database
lightningd-1 2024-10-04T01:29:48.271Z DEBUG lightningd: Looking for [autoclean,failedforwards,num]
lightningd-1 2024-10-04T01:29:48.277Z DEBUG hsmd: Client: Received message 27 from client
lightningd-1 2024-10-04T01:29:48.278Z DEBUG plugin-clboss: Rpc in: getinfo {} => {\"id\":\"0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518\",\"alias\":\"JUNIORBEAM-v24.08.1-modded\",\"color\":\"0266e4\",\"num_peers\":0,\"num_pending_chan...
lightningd-1 2024-10-04T01:29:48.278Z DEBUG plugin-clboss: Rpc out: listconfigs {}
lightningd-1 2024-10-04T01:29:48.281Z DEBUG plugin-recklessrpc: plugin initialized!
lightningd-1 2024-10-04T01:29:48.281Z DEBUG plugin-recklessrpc: lightning-dir: /tmp/ltests-yiqcqbc6/test_rpc_clboss_status_1/lightning-1/
lightningd-1 2024-10-04T01:29:48.281Z DEBUG plugin-recover: Recover Plugin Initialised!
lightningd-1 2024-10-04T01:29:48.281Z DEBUG plugin-recover: Gossmap loaded!
lightningd-1 2024-10-04T01:29:48.285Z DEBUG plugin-chanbackup: Chanbackup Initialised!
lightningd-1 2024-10-04T01:29:48.285Z INFO plugin-chanbackup: Creating Emergency Recovery
lightningd-1 2024-10-04T01:29:48.288Z DEBUG lightningd: Looking for [autoclean,succeededpays,num]
lightningd-1 2024-10-04T01:29:48.289Z DEBUG plugin-clboss: Rpc in: listconfigs {} => {\"configs\":{\"developer\":{\"set\":true,\"source\":\"cmdline\"},\"lightning-dir\":{\"value_str\":\"/tmp/ltests-yiqcqbc6/test_rpc_clboss_status_1/lightning-1/\",\"source\":\"cmdl...
lightningd-1 2024-10-04T01:29:48.289Z DEBUG plugin-clboss: Initiator: No proxy.
lightningd-1 2024-10-04T01:29:48.293Z DEBUG plugin-clboss: Rpc out: help {}
lightningd-1 2024-10-04T01:29:48.293Z DEBUG plugin-clboss: Rpc out: waitblockheight {\"blockheight\": 1, \"timeout\": 86400}
lightningd-1 2024-10-04T01:29:48.293Z UNUSUAL plugin-clboss: HardcodedSeeds: Cannot seed by hardcoded: No known nodes for this network.
lightningd-1 2024-10-04T01:29:48.294Z DEBUG plugin-clboss: TimerTwiceDailyAnnouncer: Announce.
lightningd-1 2024-10-04T01:29:48.294Z DEBUG plugin-clboss: Rpc out: feerates {\"style\": \"perkw\"}
lightningd-1 2024-10-04T01:29:48.294Z DEBUG plugin-clboss: Rpc out: listfunds {}
lightningd-1 2024-10-04T01:29:48.294Z DEBUG hsmd: Client: Received message 27 from client
lightningd-1 2024-10-04T01:29:48.298Z DEBUG lightningd: Looking for [autoclean,failedpays,num]
lightningd-1 2024-10-04T01:29:48.298Z DEBUG plugin-clboss: Rpc out: listpeerchannels {}
lightningd-1 2024-10-04T01:29:48.298Z DEBUG plugin-clboss: ChannelCandidateInvestigator: Have 0 channel candidates, soliciting more.
lightningd-1 2024-10-04T01:29:48.300Z DEBUG plugin-clboss: BoltzSwapper: No instances for this network.
lightningd-1 2024-10-04T01:29:48.300Z DEBUG plugin-clboss: Rpc out: listchannels {\"source\": \"0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518\"}
lightningd-1 2024-10-04T01:29:48.300Z DEBUG plugin-clboss: Rpc out: listpays {}
lightningd-1 2024-10-04T01:29:48.300Z DEBUG plugin-clboss: Rpc out: listchannels {\"source\": \"0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518\"}
lightningd-1 2024-10-04T01:29:48.300Z DEBUG plugin-clboss: PaymentDeleter: Start.
lightningd-1 2024-10-04T01:29:48.300Z UNUSUAL plugin-clboss: DnsSeed: Cannot seed by DNS: No known seeds for this network.
lightningd-1 2024-10-04T01:29:48.301Z DEBUG plugin-clboss: Rpc out: listpays {}
lightningd-1 2024-10-04T01:29:48.301Z DEBUG plugin-clboss: Initialization raised.
lightningd-1 2024-10-04T01:29:48.301Z INFO plugin-clboss: ChannelFinderByEarnedFee: No peers with earned outgoing fee, nothing for us to process.
lightningd-1 2024-10-04T01:29:48.301Z INFO plugin-clboss: Started.
lightningd-1 2024-10-04T01:29:48.301Z DEBUG plugin-clboss: PeerComplaintsDesk: Soliciting complaints.
lightningd-1 2024-10-04T01:29:48.301Z DEBUG hsmd: Client: Received message 27 from client
lightningd-1 2024-10-04T01:29:48.302Z DEBUG plugin-clboss: Rpc in: help {} => {\"help\":[{\"command\":\"addgossip message\"},{\"command\":\"addpsbtoutput satoshi [initialpsbt] [locktime] [destination]\"},{\"command\":\"askrene-age layer cutoff\"},{\"com...
lightningd-1 2024-10-04T01:29:48.302Z DEBUG plugin-clboss: Rpc in: listfunds {} => {\"outputs\":[],\"channels\":[]}
lightningd-1 2024-10-04T01:29:48.302Z DEBUG plugin-clboss: Rpc in: feerates {\"style\": \"perkw\"} => {\"perkw\":{\"opening\":7500,\"mutual_close\":3750,\"unilateral_close\":11000,\"unilateral_anchor_close\":3750,\"penalty\":7500,\"min_acceptable\":1875,\"max_acceptable\":15000...
lightningd-1 2024-10-04T01:29:48.302Z DEBUG plugin-clboss: Rpc in: waitblockheight {\"blockheight\": 1, \"timeout\": 86400} => {\"blockheight\":100}
lightningd-1 2024-10-04T01:29:48.302Z INFO plugin-clboss: New block at 100
lightningd-1 2024-10-04T01:29:48.303Z DEBUG plugin-clboss: OnchainFeeMonitor: Init: (253, 253, 253): 7500: high fees.
lightningd-1 2024-10-04T01:29:48.304Z DEBUG plugin-clboss: AvailableRpcCommandsAnnouncer: Node has 175 commands.
lightningd-1 2024-10-04T01:29:48.304Z DEBUG plugin-clboss: PeerCompetitorFeeMonitor: have_listchannels_destination = true
lightningd-1 2024-10-04T01:29:48.304Z DEBUG plugin-clboss: Rpc out: waitblockheight {\"blockheight\": 101, \"timeout\": 86400}
lightningd-1 2024-10-04T01:29:48.304Z DEBUG plugin-clboss: Rpc out: fundpsbt {\"satoshi\": \"all\", \"feerate\": \"normal\", \"startweight\": 214, \"minconf\": 3, \"reserve\": false}
lightningd-1 2024-10-04T01:29:48.305Z DEBUG plugin-clboss: Rpc in: listpeerchannels {} => {\"channels\":[]}
lightningd-1 2024-10-04T01:29:48.305Z DEBUG lightningd: Looking for [autoclean,paidinvoices,num]
lightningd-1 2024-10-04T01:29:48.305Z DEBUG plugin-clboss: InitialConnect: Needs connect: No peers with live channels.
lightningd-1 2024-10-04T01:29:48.305Z DEBUG plugin-clboss: NeedsConnectSolicitor: Soliciting candidates for connection.
lightningd-1 2024-10-04T01:29:48.306Z DEBUG plugin-clboss: PeerCompetitorFeeMonitor: Weighted median fees:
lightningd-1 2024-10-04T01:29:48.306Z DEBUG plugin-clboss: RegularActiveProbe: Rolling dice for all peers.
lightningd-1 2024-10-04T01:29:48.306Z UNUSUAL plugin-clboss: NeedsConnectSolicitor: Ran out of candidates.
lightningd-1 2024-10-04T01:29:48.306Z DEBUG hsmd: Client: Received message 27 from client
lightningd-1 2024-10-04T01:29:48.307Z INFO plugin-clboss: InternetConnectionMonitor: online.
lightningd-1 2024-10-04T01:29:48.307Z DEBUG plugin-clboss: NeedsConnectSolicitor: Soliciting candidates for connection.
lightningd-1 2024-10-04T01:29:48.307Z UNUSUAL plugin-clboss: NeedsConnectSolicitor: Ran out of candidates.
lightningd-1 2024-10-04T01:29:48.308Z DEBUG plugin-clboss: Rpc in: fundpsbt {\"satoshi\": \"all\", \"feerate\": \"normal\", \"startweight\": 214, \"minconf\": 3, \"reserve\": false} => error {\"code\":-32602,\"message\":\"reserve: should be an integer: invalid token 'false'\"}
lightningd-1 2024-10-04T01:29:48.308Z DEBUG plugin-clboss: Rpc out: fundpsbt {\"satoshi\": \"all\", \"feerate\": \"normal\", \"startweight\": 214, \"minconf\": 3, \"reserve\": 0}
lightningd-1 2024-10-04T01:29:48.309Z DEBUG plugin-clboss: Rpc in: listchannels {\"source\": \"0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518\"} => {\"channels\":[]}
lightningd-1 2024-10-04T01:29:48.309Z INFO plugin-clboss: ChannelFinderByDistance: We are not on network.
lightningd-1 2024-10-04T01:29:48.309Z DEBUG lightningd: Looking for [autoclean,expiredinvoices,num]
lightningd-1 2024-10-04T01:29:48.310Z DEBUG plugin-clboss: Rpc in: listchannels {\"source\": \"0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518\"} => {\"channels\":[]}
lightningd-1 2024-10-04T01:29:48.310Z DEBUG plugin-clboss: ChannelFinderByPopularity: We have not set our already-ran flag; will find nodes.
lightningd-1 2024-10-04T01:29:48.310Z DEBUG plugin-clboss: Rpc out: listnodes {}
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: Rpc in: listpays {} => {\"pays\":[]}
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: Rpc in: listpays {} => {\"pays\":[]}
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: Rpc in: fundpsbt {\"satoshi\": \"all\", \"feerate\": \"normal\", \"startweight\": 214, \"minconf\": 3, \"reserve\": 0} => error {\"code\":304,\"message\":\"Cannot afford: still syncing with bitcoin network...\"}
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: OnchainFundsAnnouncer: No onchain funds found.
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: Rpc in: listnodes {} => {\"nodes\":[]}
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: ChannelFinderByListpays: Finished processing 0 `listpays`.
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: PaymentDeleter: End.
lightningd-1 2024-10-04T01:29:48.312Z INFO plugin-clboss: ChannelFinderByPopularity: Not enough nodes in routemap (only 0, need 10), will try again later.
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: ChannelFinderByListpays: No proposals.
lightningd-1 2024-10-04T01:29:48.312Z DEBUG plugin-clboss: ChannelFinderByListpays: Run completion.
lightningd-1 2024-10-04T01:29:48.313Z DEBUG connectd: REPLY WIRE_CONNECTD_ACTIVATE_REPLY with 0 fds
lightningd-1 2024-10-04T01:29:48.313Z DEBUG lightningd: io_break: connect_activate_done
lightningd-1 2024-10-04T01:29:48.313Z DEBUG lightningd: io_loop: connectd_activate
lightningd-1 2024-10-04T01:29:48.314Z INFO lightningd: --------------------------------------------------
lightningd-1 2024-10-04T01:29:48.314Z INFO lightningd: Server started with public key 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518, alias JUNIORBEAM-v24.08.1-modded (color #0266e4) and lightningd v24.08.1-modded
lightningd-1 2024-10-04T01:29:48.322Z INFO plugin-clboss: InternetConnectionMonitor: online.
lightningd-1 2024-10-04T01:29:48.323Z DEBUG lightningd: Adding block 101: 395dd2fa79ca28358d5bd01752309350e09060d10f91ad5fadd1f357ea522eab
lightningd-1 2024-10-04T01:29:48.332Z DEBUG gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-1 2024-10-04T01:29:48.332Z DEBUG plugin-clboss: Rpc in: waitblockheight {\"blockheight\": 101, \"timeout\": 86400} => {\"blockheight\":101}
lightningd-1 2024-10-04T01:29:48.332Z INFO plugin-clboss: New block at 101
lightningd-1 2024-10-04T01:29:48.332Z DEBUG plugin-clboss: Rpc out: listchannels {\"source\": \"0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518\"}
lightningd-1 2024-10-04T01:29:48.333Z DEBUG plugin-clboss: Rpc out: waitblockheight {\"blockheight\": 102, \"timeout\": 86400}
lightningd-1 2024-10-04T01:29:48.333Z DEBUG plugin-clboss: Rpc out: fundpsbt {\"satoshi\": \"all\", \"feerate\": \"normal\", \"startweight\": 214, \"minconf\": 3, \"reserve\": false}
lightningd-1 2024-10-04T01:29:48.334Z DEBUG plugin-clboss: Rpc in: fundpsbt {\"satoshi\": \"all\", \"feerate\": \"normal\", \"startweight\": 214, \"minconf\": 3, \"reserve\": false} => error {\"code\":-32602,\"message\":\"reserve: should be an integer: invalid token 'false'\"}
lightningd-1 2024-10-04T01:29:48.334Z DEBUG plugin-clboss: Rpc out: fundpsbt {\"satoshi\": \"all\", \"feerate\": \"normal\", \"startweight\": 214, \"minconf\": 3, \"reserve\": 0}
lightningd-1 2024-10-04T01:29:48.334Z DEBUG plugin-bookkeeper: account wallet has balance 0msat
lightningd-1 2024-10-04T01:29:48.334Z INFO plugin-bookkeeper: account wallet not found, adding
lightningd-1 2024-10-04T01:29:48.334Z DEBUG plugin-bookkeeper: Snapshot balances updated
lightningd-1 2024-10-04T01:29:48.335Z DEBUG plugin-clboss: Rpc in: listchannels {\"source\": \"0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518\"} => {\"channels\":[]}
lightningd-1 2024-10-04T01:29:48.335Z DEBUG plugin-clboss: ChannelFinderByPopularity: We have not set our already-ran flag; will find nodes.
lightningd-1 2024-10-04T01:29:48.335Z DEBUG plugin-clboss: Rpc out: listnodes {}
lightningd-1 2024-10-04T01:29:48.336Z DEBUG plugin-clboss: Rpc in: fundpsbt {\"satoshi\": \"all\", \"feerate\": \"normal\", \"startweight\": 214, \"minconf\": 3, \"reserve\": 0} => error {\"code\":301,\"message\":\"Could not afford all using all 0 available UTXOs: all short\"}
lightningd-1 2024-10-04T01:29:48.336Z DEBUG plugin-clboss: OnchainFundsAnnouncer: No onchain funds found.
lightningd-1 2024-10-04T01:29:48.336Z DEBUG plugin-clboss: Rpc in: listnodes {} => {\"nodes\":[]}
lightningd-1 2024-10-04T01:29:48.336Z INFO plugin-clboss: ChannelFinderByPopularity: Not enough nodes in routemap (only 0, need 10), will try again later.
---------------------------------------------------------------------------------- Captured stdout teardown ----------------------------------------------------------------------------------
lightningd-1 2024-10-04T01:29:48.369Z **BROKEN** lightningd: MEMLEAK: 0x5732f7c74708
lightningd-1 2024-10-04T01:29:48.369Z **BROKEN** lightningd: label=struct plugin_destroyed
lightningd-1 2024-10-04T01:29:48.370Z **BROKEN** lightningd: alloc:
lightningd-1 2024-10-04T01:29:48.468Z **BROKEN** lightningd: ccan/ccan/tal/tal.c:488 (tal_alloc_)
lightningd-1 2024-10-04T01:29:48.469Z **BROKEN** lightningd: lightningd/plugin.c:618 (plugin_detect_destruction)
lightningd-1 2024-10-04T01:29:48.469Z **BROKEN** lightningd: lightningd/plugin.c:732 (plugin_read_json_one)
lightningd-1 2024-10-04T01:29:48.469Z **BROKEN** lightningd: lightningd/plugin.c:826 (plugin_read_json)
lightningd-1 2024-10-04T01:29:48.469Z **BROKEN** lightningd: ccan/ccan/io/io.c:60 (next_plan)
lightningd-1 2024-10-04T01:29:48.469Z **BROKEN** lightningd: ccan/ccan/io/io.c:422 (do_plan)
lightningd-1 2024-10-04T01:29:48.469Z **BROKEN** lightningd: ccan/ccan/io/io.c:439 (io_ready)
lightningd-1 2024-10-04T01:29:48.470Z **BROKEN** lightningd: ccan/ccan/io/poll.c:455 (io_loop)
lightningd-1 2024-10-04T01:29:48.470Z **BROKEN** lightningd: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers)
lightningd-1 2024-10-04T01:29:48.470Z **BROKEN** lightningd: lightningd/lightningd.c:1470 (main)
lightningd-1 2024-10-04T01:29:48.470Z **BROKEN** lightningd: ../sysdeps/nptl/libc_start_call_main.h:58 (__libc_start_call_main)
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: ../csu/libc-start.c:360 (__libc_start_main_impl)
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: parents:
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: MEMLEAK: 0x5732f7dd6b58
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: label=char
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: alloc:
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: ccan/ccan/tal/tal.c:488 (tal_alloc_)
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: lightningd/plugin.c:658 (plugin_response_handle)
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: lightningd/plugin.c:775 (plugin_read_json_one)
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: lightningd/plugin.c:826 (plugin_read_json)
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: ccan/ccan/io/io.c:60 (next_plan)
lightningd-1 2024-10-04T01:29:48.471Z **BROKEN** lightningd: ccan/ccan/io/io.c:422 (do_plan)
lightningd-1 2024-10-04T01:29:48.472Z **BROKEN** lightningd: ccan/ccan/io/io.c:439 (io_ready)
lightningd-1 2024-10-04T01:29:48.472Z **BROKEN** lightningd: ccan/ccan/io/poll.c:455 (io_loop)
lightningd-1 2024-10-04T01:29:48.472Z **BROKEN** lightningd: lightningd/io_loop_with_timers.c:22 (io_loop_with_timers)
lightningd-1 2024-10-04T01:29:48.472Z **BROKEN** lightningd: lightningd/lightningd.c:1470 (main)
lightningd-1 2024-10-04T01:29:48.472Z **BROKEN** lightningd: ../sysdeps/nptl/libc_start_call_main.h:58 (__libc_start_call_main)
lightningd-1 2024-10-04T01:29:48.472Z **BROKEN** lightningd: ../csu/libc-start.c:360 (__libc_start_main_impl)
lightningd-1 2024-10-04T01:29:48.472Z **BROKEN** lightningd: parents:
lightningd-1 2024-10-04T01:29:48.473Z DEBUG connectd: REPLY WIRE_CONNECTD_DEV_MEMLEAK_REPLY with 0 fds
lightningd-1 2024-10-04T01:29:48.473Z DEBUG gossipd: REPLY WIRE_GOSSIPD_DEV_MEMLEAK_REPLY with 0 fds
lightningd-1 2024-10-04T01:29:49.347Z UNUSUAL lightningd: JSON-RPC shutdown
lightningd-1 2024-10-04T01:29:49.348Z DEBUG lightningd: io_break: start_json_stream
lightningd-1 2024-10-04T01:29:49.348Z DEBUG lightningd: io_loop_with_timers: main
lightningd-1 2024-10-04T01:29:49.442Z INFO connectd: dev_report_fds: 3 -> hsm fd
lightningd-1 2024-10-04T01:29:49.442Z INFO connectd: dev_report_fds: 4 -> gossipd fd
lightningd-1 2024-10-04T01:29:49.442Z INFO connectd: dev_report_fds: 5 -> listener (connection_in)
lightningd-1 2024-10-04T01:29:49.442Z INFO connectd: dev_report_fds: 5 name IPv4 socket 127.0.0.1:35829
lightningd-1 2024-10-04T01:29:49.442Z DEBUG connectd: REPLY WIRE_CONNECTD_START_SHUTDOWN_REPLY with 0 fds
lightningd-1 2024-10-04T01:29:49.443Z DEBUG lightningd: io_break: connectd_start_shutdown_reply
lightningd-1 2024-10-04T01:29:49.444Z DEBUG plugin-autoclean: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.444Z DEBUG plugin-chanbackup: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.445Z DEBUG plugin-bcli: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.445Z DEBUG plugin-commando: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.445Z DEBUG plugin-funder: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.445Z DEBUG plugin-topology: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.446Z DEBUG plugin-pay: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.446Z DEBUG plugin-recklessrpc: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.446Z DEBUG plugin-recover: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.446Z DEBUG plugin-keysend: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.446Z DEBUG plugin-offers: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.447Z DEBUG plugin-cln-askrene: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.447Z DEBUG plugin-spenderp: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.447Z DEBUG plugin-cln-renepay: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.447Z DEBUG plugin-sql: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.447Z DEBUG plugin-txprepare: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.448Z DEBUG plugin-bookkeeper: Killing plugin: exited during normal operation
lightningd-1 2024-10-04T01:29:49.448Z DEBUG lightningd: io_break: destroy_plugin
lightningd-1 2024-10-04T01:29:49.448Z DEBUG lightningd: Command returned result after jcon close
lightningd-1 2024-10-04T01:29:49.448Z DEBUG lightningd: Command returned result after jcon close
lightningd-1 2024-10-04T01:29:49.448Z DEBUG connectd: Shutting down
lightningd-1 2024-10-04T01:29:49.450Z DEBUG gossipd: Shutting down
lightningd-1 2024-10-04T01:29:49.450Z DEBUG hsmd: Shutting down
Leaving base_dir /tmp/ltests-yiqcqbc6 intact, it still has test sub-directories with failure details: ['test_rpc_clboss_status_1']
====================================================================================== warnings summary ======================================================================================
../../../../.cache/pypoetry/virtualenvs/tests-H63Gdp_e-py3.12/lib/python3.12/site-packages/cheroot/__init__.py:7
/home/cguida/.cache/pypoetry/virtualenvs/tests-H63Gdp_e-py3.12/lib/python3.12/site-packages/cheroot/__init__.py:7: DeprecationWarning: pkg_resources is deprecated as an API. See https://setuptools.pypa.io/en/latest/pkg_resources.html
import pkg_resources
-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
================================================================================== short test summary info ===================================================================================
ERROR test_rpc.py::test_rpc_clboss_status - ValueError:
=========================================================================== 1 passed, 1 warning, 1 error in 3.77s ============================================================================
If I don't include the plugin, the test passes, so it doesn't seem that there's anything wrong with the framework. It just seems that CLN leaks memory somehow when running with CLBOSS. I'm not sure why this would happen, as none of the other plugins in the repo have this issue when running nightly in the CI.
Anyone got ideas? @rustyrussell @cdecker @ShahanaFarooqui @ksedgwic @vincenzopalazzo
From what I can tell this might be a timing issue with clboss being maybe a bit slow to shut down? The way we track plugin shutdowns may have an implicit timing assumption so that if a plugin is slow it gives up and exits early, which valgrind then detects as a memleak on the shutdown tracking state.
Pretty sure this is a bug in CLN. I cannot figure out how to make this memleak go away.
It seems to happen during launch rather than shutdown, around here: https://github.com/ElementsProject/lightning/blob/8330e3a0dff96249b76af5410d0df986f96edccc/lightningd/plugin.c#L658
Ok I've narrowed it down a bit further, it appears that if I turn valgrind on, it actually fixes the problem. When it's off (apparently this is by default now, IIRC valgrind used to be on by default), this section of pyln-testing runs:
https://github.com/ElementsProject/lightning/blob/8330e3a0dff96249b76af5410d0df986f96edccc/contrib/pyln-testing/pyln/testing/utils.py#L1727
So calling the dev_memleak rpc appears to be causing the leak? or at least causing the leak log messages.
Ok yeah confirmed, calling lightning-cli dev-memleak with clboss running like so:
LIGHTNINGD_DEV_MEMLEAK=1 nohup lightningd --disable-plugin bcli --plugin /home/cguida/work/plugins/sauron/sauron.py --plugin /home/cguida/work/clboss/clboss --sauron-api-endpoint https://blockstream.info/api --developer &
..results in the above 2 memleak traces.
What does this mean?
Curiously, the tests pass when valgrind is on, but fail when valgrind is off. Does this mean that dev-memleak itself may be causing the leak??
Hey @rustyrussell did you fix this? I'm not running into it anymore on v24.11.1, and I've re-confirmed that it's broken on v.24.08.2.