We don't expect an internal command to take 5 seconds to service
without explicitly pausing: if it does, log at a higher level.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We are seeing this in the CI logs, eg tests/test_connection.py::test_reconnect_sender_add1:
lightningd-1 2025-11-17T05:48:00.665Z DEBUG jsonrpc#84: Pausing parsing after 1 requests
followed by:
lightningd-1 2025-11-17T05:48:02.068Z **BROKEN** 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: wake delay for WIRE_CHANNEL_REESTABLISH: 8512msec
So, what is consuming lightningd for 8 or so seconds?
This message helped diagnose that the issue was dev-memleak: fixed in a different branch.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We have a reasonable number of commands now, and we *already* keep a
strmap for the usage strings. So simply keep the usage and the command
in the map, and skip the array.
tests/test_coinmoves.py::test_generate_coinmoves (2,000,000, sqlite3):
Time (from start to end of l2 node): 95 seconds (was 102)
Worst latency: 4.5 seconds
tests/test_coinmoves.py::test_generate_coinmoves (2,000,000, Postgres):
Time (from start to end of l2 node): 231 seconds
Worst latency: 4.8 seconds
Note the values compare against 25.09.2 (Postgres):
sqlite3:
Time (from start to end of l2 node): 403 seconds
Postgres:
Time (from start to end of l2 node): 671 seconds
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Now that ccan/io rotates through callbacks, we can call io_always() to
yield.
We're now fast enough that this doesn't have any effect on this test,
bit it's still good to have.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Now that ccan/io rotates through callbacks, we can call io_always() to yield.
Though it doesn't fire on our benchmark, it's a good thing to do.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Added: Plugins: "filters" can be specified on the `custommsg` hook to limit what message types the hook will be called for.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Added: Plugins: the `rpc_command` hook can now specify a "filter" on what commands it is interested in.
We're going to use this on the "rpc_command" hook, to allow xpay to specify that it
only wants to be called on "pay" commands.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Profiling shows us spending all our time in tal_arr_remove when dealing
with a giant number of output streams. This applies both for RPC output
and plugin output.
Use linked list instead.
tests/test_coinmoves.py::test_generate_coinmoves (2,000,000, sqlite3):
Time (from start to end of l2 node): 239 seconds **WAS 518**
Worst latency: 56.9 seconds **WAS 353**
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
When we have many commands, this is where we spend all our time, and it's
just for an old assertion.
tests/test_coinmoves.py::test_generate_coinmoves (100,000, sqlite3):
Time (from start to end of l2 node): 13 seconds **WAS 34**
Worst latency: 4.0 seconds **WAS 24*
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
If we add a new hook, not at the end, while hooks are getting called,
then iteration could be messed up (e.g. calling a plugin twice, or
skipping one).
The simplest thing is to defer updates until nobody is calling the
hook. In theory this could livelock, in practice it won't.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We make a copy, then attach a destructor to the hook in case that plugin exits, so we
can NULL it out in the local copy. When we have 300,000 requests pending, this means
we have 300,000 destructors, which don't scale (it's a single-linked list).
Simply NULL out (rather than shrink) the array in the `plugin_hook`.
Then we can keep using that.
tests/test_coinmoves.py::test_generate_coinmoves (100,000, sqlite3):
Time (from start to end of l2 node): 34 seconds **WAS 85**
Worst latency: 24 seconds **WAS 75**
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
65dccea5bd "pytest: fix flake in test_reconnect_signed" accidentally
introduced a bug, where the connect command may not return.
If we call "connect" while a connection is still being processed
through the peer_connected hooks, we would call peer_channels_cleanup(),
which (if the peer has no channels) would free the peer.
Then when the peer_connected hook returned, it would lookup the peer,
see it was gone, and silently return. The connect_succeeded() function
was never called, and the connect command never woken.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-None: bug introduced this release.
We had a flake of form:
```
2025-11-18T04:42:23.489Z **BROKEN** 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: wake delay for WIRE_CHANNEL_REESTABLISH: 6789msec
```
Which happened as we're shutting down. Some investigation revealed
the cause: `dev-memleak` can be extremely slow. Fair enough.
So we change `dev-memleak` to call connectd first, and connectd uses
that as a trigger to stop complaining about delays.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
If we see a close tx at the same time we see the channel reach announce depth (here, 104x1x0 confirms
and we process blocks 109 and 110), we see it go from:
CGOSSIP_WAITING_FOR_ANNOUNCE_DEPTH->CGOSSIP_CHANNEL_UNANNOUNCED_DYING (Channel closing before 6 confirms)
Then:
CGOSSIP_CHANNEL_UNANNOUNCED_DYING->CGOSSIP_CHANNEL_ANNOUNCED_DEAD
```
INFO 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: State changed from CHANNELD_NORMAL to CHANNELD_SHUTTING_DOWN
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: gossip state: CGOSSIP_WAITING_FOR_ANNOUNCE_DEPTH->CGOSSIP_CHANNEL_UNANNOUNCED_DYING (Channel closing before 6 confirms)
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#2: billboard: Channel ready for use. They've sent shutdown, waiting for ours
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#2: Trying commit
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#2: Can't send commit: nothing to send, feechange not wanted ({ RCVD_ADD_ACK_REVOCATION:3755 }) blockheight not wanted ({ RCVD_ADD_ACK_REVOCATION:109 })
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#2: peer_out WIRE_SHUTDOWN
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#2: billboard: Channel ready for use. Shutdown messages exchanged.
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: pid 35692, msgfd 86
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#2: Status closed, but not exited. Killing
INFO 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: State changed from CHANNELD_SHUTTING_DOWN to CLOSINGD_SIGEXCHANGE
DEBUG hsmd: new_client: 2
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: Expected closing weight = 772, fee 2895sat (min 1447sat, max 1006268sat)
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: out = 506268sat/500000sat
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: dustlimit = 546sat
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: fee = 2895sat
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: fee negotiation step = 50%
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: billboard perm: Negotiating closing fee between 1447sat and 1006268sat satoshi (ideal 2895sat) using step 50%
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: billboard: Waiting for their initial closing fee offer
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: peer_in WIRE_CLOSING_SIGNED
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: Making close tx at = 506268sat/500000sat fee 2895sat
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: Received fee offer 2895sat
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: ...offer is reasonable
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: Their actual closing tx fee is 2895sat vs previous 4220sat: weight is 772
INFO 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: performing quickclose in range 1447sat-8492sat
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: Making close tx at = 506268sat/500000sat fee 2895sat
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-hsmd: Got WIRE_HSMD_SIGN_MUTUAL_CLOSE_TX
DEBUG hsmd: Client: Received message 21 from client
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: sending fee offer 2895sat
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: peer_out WIRE_CLOSING_SIGNED
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-closingd-chan#2: billboard perm: We agreed on a closing fee of 2895 satoshi for tx:7685256e6e4632bd601f42bb85b6f22b7a0db8d55c468dfbb1703c3ab2e4d9ce
INFO 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: State changed from CLOSINGD_SIGEXCHANGE to CLOSINGD_COMPLETE
DEBUG wallet: Owning output 1 506268sat (p2tr) txid 7685256e6e4632bd601f42bb85b6f22b7a0db8d55c468dfbb1703c3ab2e4d9ce
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: We have 1 anchor points to use
DEBUG lightningd: Broadcasting txid 7685256e6e4632bd601f42bb85b6f22b7a0db8d55c468dfbb1703c3ab2e4d9ce
DEBUG lightningd: sendrawtransaction: 020000000001016f50e5481abf2482ed719dde6014cf9da9b3076fe12af7c8bbccfb705150ffbe0000000000ffffffff02d195070000000000225120eed745804da9784cc203f563efa99ffa54fdf01b137bc964e63c3124070ffbe69cb90700000000002251208a73bb281433f2b5db5461c6778aa2afd28e011de6bd04799a5991662c61d7a80400473044022015af4ffc277e44ab701507e017194b1e3ab8598397efab02c59dbe72340790b50220762065e91ce0a2c73f36fdf3a4d54732ef91d075c0887cfb28580220e081e81a01473044022050730b9d051a3fdecb368750ecbd558d625a1acaa42e59586c7187407319dda402202f2f6e099b2e092698fe528260e2b56be8de325bc985a17945c724514fb65b9c014752210259b3cb48220dc2016f4d320bb8105cc2c92bd8c79fc25c2ad96f37b496e491c62103bbee60c395056b8a1201e06ed79e2914c11a61d7b1aa781846468d02489dba6952ae00000000
DEBUG lightningd: Adding block 108: 4e6ba3059c6890797a29acd306e82d6f4e85ad62a6aa6d0ee5bc6ead3e6329cd
DEBUG hsmd: Client: Received message 5 from client
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: peer_downgrade
DEBUG plugin-bcli: sendrawtx exit 0 (bitcoin-cli -regtest -datadir=/tmp/ltests-laf51vlg/test_buy_liquidity_ad_check_bookkeeping_1/lightning-2/ -rpcclienttimeout=60 -rpcport=41847 -rpcuser=... -stdinrpcpass sendrawtransaction 020000000001016f50e5481abf2482ed719dde6014cf9da9b3076fe12af7c8bbccfb705150ffbe0000000000ffffffff02d195070000000000225120eed745804da9784cc203f563efa99ffa54fdf01b137bc964e63c3124070ffbe69cb90700000000002251208a73bb281433f2b5db5461c6778aa2afd28e011de6bd04799a5991662c61d7a80400473044022015af4ffc277e44ab701507e017194b1e3ab8598397efab02c59dbe72340790b50220762065e91ce0a2c73f36fdf3a4d54732ef91d075c0887cfb28580220e081e81a01473044022050730b9d051a3fdecb368750ecbd558d625a1acaa42e59586c7187407319dda402202f2f6e099b2e092698fe528260e2b56be8de325bc985a17945c724514fb65b9c014752210259b3cb48220dc2016f4d320bb8105cc2c92bd8c79fc25c2ad96f37b496e491c62103bbee60c395056b8a1201e06ed79e2914c11a61d7b1aa781846468d02489dba6952ae00000000)
DEBUG lightningd: Adding block 109: 540a47d6b316aec8d1b56efca22ffb384403659e3b29cddd3d68f87df72065a6
DEBUG lightningd: Adding block 110: 1931e9ea62324d0fb50188df525e84ee7021e1910cf3534b343db05cc4639851
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: Got UTXO spend for beff505170fbccbbc8f72ae16f07b3a99dcf1460de9d71ed8224bf1a48e5506f:0: 7685256e6e4632bd601f42bb85b6f22b7a0db8d55c468dfbb1703c3ab2e4d9ce
UNUSUAL 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: Peer permanent failure in CLOSINGD_COMPLETE: Funding transaction spent: onchain txid 7685256e6e4632bd601f42bb85b6f22b7a0db8d55c468dfbb1703c3ab2e4d9ce (reason=unknown)
UNUSUAL 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: Not dropping our unilateral close onchain since we already saw 7685256e6e4632bd601f42bb85b6f22b7a0db8d55c468dfbb1703c3ab2e4d9ce confirm.
INFO 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: State changed from CLOSINGD_COMPLETE to FUNDING_SPEND_SEEN
**BROKEN** 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#2: Illegal gossip state transition: CGOSSIP_CHANNEL_UNANNOUNCED_DYING->CGOSSIP_CHANNEL_ANNOUNCED_DEAD
DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#2: pid 35721, msgfd 86
```
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This is just a polite way of telling us that if we close, don't bother broadcasting
since we didn't broadcast the funding tx.
Changelog-Added: JSON-RPC: `fundchannel_complete` new parameter `withhold` (default false).
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Added: JSON-RPC: `listpeerchannels` `funding` object `withheld` flag, and `listclosedchannels` `funding_withheld` flags, indicating fundchannel_complete was called with the `withheld` parameter true.
Normally we don't care, but if we're withholding it, keep it around
so we can sign & broadcast later.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Added: JSON-RPC: `psbt` field in `funding` in listpeerchannels, and `funding_psbt` in listclosedchannels.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Fixed: Protocol: we now re-transmit unseen funding transactions on startup, for more robustness.
Interestingly, @niftynei added a funding_psbt column to the db in 2020,
but we don't use it (it was removed early 2021 with the "inflight"
architecture). So we don't need to add a new column, just plumb it
back in.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This can definitely happen with zeroconf and the about-to-be-implemented withheld=True:
```
lightningd-1 2025-09-12T13:17:50.848Z **BROKEN** 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Illegal gossip state transition: CGOSSIP_WAITING_FOR_SCID->CGOSSIP_CHANNEL_UNANNOUNCED_DYING
```
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Somehow I missed this when deprecating `short_channel_id` being null.
Changelog-Deprecated: Plugins: `channel_state_changed` notification `message` field being `null`: it will be omitted instead.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
I added amount_msat_accumulate for the "a+=b" case, but I was struggling
with a name for the subtractive equivalent. After some prompting, ChatGPT
suggested deduct.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This is immune to things like clock changes, and has the convenient side-effect that
it will *not* be overridden when we override time for developer purposes.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Only in developer mode, ofc.
Notes:
1. We have to move the initialization before the lightningd main trace_start,
since that uses pseudorand().
2. To make the results stable, we need to use per-caller values to randbytes().
Otherwise external timing changes the call order.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
They are invalid! This is because our BOLT11_FIELD_BYTE_LIMIT is not the limit,
it's one greater than the limit.
Reported-by: https://github.com/noblepayne
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Fixed: JSON-RPC: `invoice` no longer accepts 640-byte descriptions (it would produce malformed invoices).
This is important: if it's tor-only and we don't have a proxy, we will fail
to connect, but it's no indication that the node is unreachable. Same with
IPv6.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
In some cases it is helpful to know who offered us the HTLC.
Changelog-Changed: Plugins: The `htlc_accepted` hook now knows the
`peer_id` of the peer that offered us the HTLC.
Signed-off-by: Peter Neuroth <pet.v.ne@gmail.com>
This commit introduces a new field `invoice_msat` to the htlc_accepted
hook. If this field is specified it will replace the amount of the
invoice that belongs to the payment_hash of the HTLC on internal checks.
This is useful in scenarios where we actually expect a smaller amount
than initially specified in an invoice.
Changelog-Changed: Plugins: `htlc_accepted` hook can now override the
expected total amount of the invoice that belongs to the HTLC.
Signed-off-by: Peter Neuroth <pet.v.ne@gmail.com>
