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.

Sign up for GitHub

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

Jump to bottom

lightning-cli dev-memleak reports memleaks in lightningd.c while running clboss #7716

Open
chrisguida opened this issue Oct 4, 2024 · 6 comments
Open

lightning-cli dev-memleak reports memleaks in lightningd.c while running clboss #7716

chrisguida opened this issue Oct 4, 2024 · 6 comments

Comments

@chrisguida
Copy link
Contributor

chrisguida commented Oct 4, 2024 •
edited
Loading

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
@cdecker
Copy link
Member

cdecker commented Oct 4, 2024

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.

@chrisguida
Copy link
Contributor Author

chrisguida commented Oct 4, 2024 •
edited
Loading

@cdecker I ran with VALGRIND=0, I thought this disables valgrind?

@chrisguida
Copy link
Contributor Author

chrisguida commented Oct 8, 2024 •
edited
Loading

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:

lightning/lightningd/plugin.c

Line 658 in 8330e3a

ctx = tal(NULL, char);

@chrisguida chrisguida changed the title pyln-testing: memleak in basic clboss smoke test Memleak in lightningd.c when destroying plugins Oct 8, 2024
@chrisguida chrisguida changed the title Memleak in lightningd.c when destroying plugins Memleak in lightningd.c while launching clboss Oct 8, 2024
@chrisguida
Copy link
Contributor Author

chrisguida commented Oct 8, 2024 •
edited
Loading

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:

lightning/contrib/pyln-testing/pyln/testing/utils.py

Line 1727 in 8330e3a

leaks = self.nodes[i].rpc.dev_memleak()['leaks']

So calling the dev_memleak rpc appears to be causing the leak? or at least causing the leak log messages.

@chrisguida
Copy link
Contributor Author

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?

@chrisguida chrisguida changed the title Memleak in lightningd.c while launching clboss lightning-cli dev-memleak reports memleaks in lightningd.c while running clboss Oct 8, 2024
@chrisguida
Copy link
Contributor Author

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??

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@cdecker @chrisguida