Background processor still not woken after async monitor persistence completion

[MaxFangX]

#2090 was supposed to fix #2052, but there still seems to be an unhandled case somewhere.

Currently, we have a workaround where our channel monitor persistence task will wake our BGP using a channel just after every persist is completed. You can see the code here, and the notification trigger is here.

After commenting out this channel, all of our integration tests which make payments fail:

failures:

---- payments::lsp_user_zeroconf_payments stdout ----
thread 'payments::lsp_user_zeroconf_payments' panicked at smoketest/src/harness.rs:726:13:
Node -1 failed to make progress: LSP failed to make progress: WaitAll([PaymentSent]): [102=Command]: (lsp) timed out waiting for test events: 0/1 PaymentSent; Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentClaimable, 0/1 PaymentClaimed
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

---- payments::user_errors stdout ----
thread 'payments::user_errors' panicked at smoketest/src/harness.rs:726:13:
Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentSent]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentSent; Node -1 failed to make progress: LSP failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed]): [102=Command]: (lsp) timed out waiting for test events: 0/1 PaymentClaimable, 0/1 PaymentClaimed

---- payments::lsp_pays_user_over_confirmed_channel stdout ----
thread 'payments::lsp_pays_user_over_confirmed_channel' panicked at smoketest/src/harness.rs:726:13:
Node -1 failed to make progress: LSP failed to make progress: WaitAll([PaymentSent]): [102=Command]: (lsp) timed out waiting for test events: 0/1 PaymentSent; Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentClaimable, 0/1 PaymentClaimed

---- payments::lsp_user_channel_config_update stdout ----
thread 'payments::lsp_user_channel_config_update' panicked at smoketest/src/harness.rs:726:13:
Node -1 failed to make progress: LSP failed to make progress: WaitAll([PaymentSent]): [102=Command]: (lsp) timed out waiting for test events: 0/1 PaymentSent; Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentClaimed, 0/1 PaymentClaimable

---- payments::online_jit_payment stdout ----
thread 'payments::online_jit_payment' panicked at smoketest/src/harness.rs:726:13:
Node -1 failed to make progress: LSP failed to make progress: WaitAll([FundingGenerationHandled, TxBroadcasted, ChannelPending, ChannelReady]): [102=Command]: (lsp) timed out waiting for test events: 0/1 FundingGenerationHandled, 0/1 ChannelPending, 0/1 TxBroadcasted, 0/1 ChannelReady; Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentSent]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentSent; Node 1 failed to make progress: User failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed, ChannelPending, ChannelReady]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentClaimed, 0/1 ChannelPending, 0/1 ChannelReady, 0/1 PaymentClaimable

---- payments::one_sat_jit_payment stdout ----
thread 'payments::one_sat_jit_payment' panicked at smoketest/src/harness.rs:726:13:
Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentSent]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentSent; Node 1 failed to make progress: User failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed, ChannelPending, ChannelReady]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentClaimable, 0/1 PaymentClaimed

---- payments::offline_jit_payment stdout ----
thread 'payments::offline_jit_payment' panicked at smoketest/src/harness.rs:726:13:
Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentSent]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentSent; Node 1 failed to make progress: User failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed, ChannelPending, ChannelReady]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentClaimable, 0/1 PaymentClaimed

---- payments::multi_jit_channel stdout ----
thread 'payments::multi_jit_channel' panicked at smoketest/src/harness.rs:726:13:
Node -1 failed to make progress: LSP failed to make progress: WaitAll([FundingGenerationHandled, TxBroadcasted, ChannelPending, ChannelReady]): [102=Command]: (lsp) timed out waiting for test events: 0/1 ChannelPending, 0/1 ChannelReady, 0/1 TxBroadcasted, 0/1 FundingGenerationHandled; Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentSent]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentSent; Node 1 failed to make progress: User failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed, ChannelPending, ChannelReady]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentClaimed, 0/1 PaymentClaimable, 0/1 ChannelReady, 0/1 ChannelPending

---- payments::user_lsp_simple_payments stdout ----
thread 'payments::user_lsp_simple_payments' panicked at smoketest/src/harness.rs:726:13:
Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentSent]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentSent; Node -1 failed to make progress: LSP failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed]): [102=Command]: (lsp) timed out waiting for test events: 0/1 PaymentClaimable, 0/1 PaymentClaimed

---- payments::user_pays_offline_user stdout ----
thread 'payments::user_pays_offline_user' panicked at smoketest/src/harness.rs:726:13:
Node -1 failed to make progress: LSP failed to make progress: WaitAll([PaymentSent]): [102=Command]: (lsp) timed out waiting for test events: 0/1 PaymentSent; Node 0 failed to make progress: User failed to make progress: WaitAll([PaymentClaimable, PaymentClaimed]): [106=Command]: (node) timed out waiting for test events: 0/1 PaymentClaimed, 0/1 PaymentClaimable


failures:
    payments::lsp_pays_user_over_confirmed_channel
    payments::lsp_user_channel_config_update
    payments::lsp_user_zeroconf_payments
    payments::multi_jit_channel
    payments::offline_jit_payment
    payments::one_sat_jit_payment
    payments::online_jit_payment
    payments::user_errors
    payments::user_lsp_simple_payments
    payments::user_pays_offline_user

test result: FAILED. 5 passed; 10 failed; 1 ignored; 0 measured; 0 filtered out; finished in 46.87s

I don't know what specifically the issue is, but one thing all these tests have in common is they wait for LDK to emit a PaymentSent for us to handle.

I'm including a more detailed log from one of the integration tests that you can pore through if it would help.

12_46_49.redacted.log (EDIT: Here's a gist containing the same info)

(P.S. our code has since been updated to also await on the onion messenger's get_update_future(), but after commenting out the channel receiver the problem still persists, so we've ruled out that as the cause).

[wpaulino]

From your logs, two updates get queued back-to-back due to handling the incoming revoke_and_ack and commitment_signed:

2025-03-06T20:47:21.309712Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Received message UpdateAddHTLC(UpdateAddHTLC { channel_id: ChannelId([21, 34, 242, 2, 153, 249, 89, 128, 224, 49, 156, 204, 200, 236, 126, 193, 90, 59, 114, 216, 177, 244, 218, 138, 59, 54, 190, 179, 168, 150, 192, 233]), htlc_id: 0, amount_msat: 2000000000, payment_hash: 81d61e043aa755b5171f7206aa9d1784461af48c6c17801ecc4aa3511697042d, cltv_expiry: 214, skimmed_fee_msat: None, onion_routing_packet: OnionPacket version 0 with hmac [231, 103, 36, 148, 36, 183, 248, 74, 64, 108, 189, 126, 222, 199, 69, 22, 65, 22, 163, 176, 34, 70, 150, 169, 223, 49, 181, 196, 39, 189, 82, 227], blinding_point: None }) from 031e18d11d9fdbc175f2fd73cfab07346146069fcf1ecfbeef6e55632a3bda7fe5 module="lightning::ln::peer_handler" line=1744 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310138Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Received message CommitmentSigned(CommitmentSigned { channel_id: ChannelId([21, 34, 242, 2, 153, 249, 89, 128, 224, 49, 156, 204, 200, 236, 126, 193, 90, 59, 114, 216, 177, 244, 218, 138, 59, 54, 190, 179, 168, 150, 192, 233]), signature: 304402200d1db4bdff3b44835eeba954ba53d856843deca6afd93f5fe0070f6b2f4bb8d802202f9bf466cf81742e7a8f1d4f991943b4da19f12db3ffb604d658cd053b69324d, htlc_signatures: [3044022047fbb0bf83118451e6aca215a45474fc15b7cee22e4aa53d7f609ad91c23a83a02205f401efa84dc4ee742a515b7e948e1d45d7a6709a7cf91d8274320d006d36f7f], batch: None }) from 031e18d11d9fdbc175f2fd73cfab07346146069fcf1ecfbeef6e55632a3bda7fe5 module="lightning::ln::peer_handler" line=1744 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310322Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Building commitment transaction number 281474976710654 (really 1 xor 11450651307159) for channel 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9 for us, generated by remote with fee 253... module="lightning::ln::channel" line=2602 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310358Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk:    ...including inbound RemoteAnnounced HTLC 0 (hash 81d61e043aa755b5171f7206aa9d1784461af48c6c17801ecc4aa3511697042d) with value 2000000000 module="lightning::ln::channel" line=2666 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310389Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk:    ...including to_remote output with value 7999774 module="lightning::ln::channel" line=2773 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310531Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Checking commitment tx signature 0d1db4bdff3b44835eeba954ba53d856843deca6afd93f5fe0070f6b2f4bb8d82f9bf466cf81742e7a8f1d4f991943b4da19f12db3ffb604d658cd053b69324d by key 02b12abf257bda01efc56bcab1d7bcc4663d0164186fc30a27a1834f1c63cb2146 against tx 02000000011522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e80100000000106a0a800280841e0000000000220020eb7cc06236652ad6a0ff18225eca52b3d8f0e8a713063db9d1ffc7fded7565851e117a00000000001600143ea76e123b5ece228d93ec7a81f5947a97ef57b296ec0020 (sighash ee37aa41cdf273f7a59d4911b64e0ef40dd12abf829f59f02fb2416b9f25b1ab) with redeemscript 4752210285acb87b4486e9dc3050549d060f16f508bff6ef855c416c3e7b28762479d8362102b12abf257bda01efc56bcab1d7bcc4663d0164186fc30a27a1834f1c63cb214652ae in channel 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9 module="lightning::ln::channel" line=4506 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310653Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Checking HTLC tx signature 47fbb0bf83118451e6aca215a45474fc15b7cee22e4aa53d7f609ad91c23a83a5f401efa84dc4ee742a515b7e948e1d45d7a6709a7cf91d8274320d006d36f7f by key 032e772813672f017540ebce837a31fa8a93abf2f0683cbecafebb0b0a14d05164 against tx 02000000015074492968021a8d0d97c95199211b9d8c1ad22055d85239fcebf6d1f589e0c200000000000000000001cf831e0000000000220020597e00bc6a47cd7cec25787566bcbe9e20f4b2e66b73c74d2fbaa2fb5a7bee7f00000000 (sighash f012bf876c3cde18dd49bf2bb3a280dab5ade8766867129a98a7980cb474d96b) with redeemscript 8a76a914ea55a78fc1172db9ecaff7368c34d5569ff5f5938763ac6721032e772813672f017540ebce837a31fa8a93abf2f0683cbecafebb0b0a14d051647c8201208763a914577da3ba1e858416ad4b6b1539bce8f0d3e6e20388527c2103a916f4ef2e07d394b3c37ce62544d15e9adca9204f7d0c73ff39f175b877458452ae677502d600b175ac6868 in channel 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9. module="lightning::ln::channel" line=4577 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310719Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Updating HTLC 81d61e043aa755b5171f7206aa9d1784461af48c6c17801ecc4aa3511697042d to AwaitingRemoteRevokeToAnnounce due to commitment_signed in channel 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9. module="lightning::ln::channel" line=4622 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310775Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Retrieved next per-commitment point 281474976710652 module="lightning::ln::channel" line=1009 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310810Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Updating HTLC state for a newly-sent commitment_signed... module="lightning::ln::channel" line=7346 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310825Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk:  ...promoting inbound AwaitingRemoteRevokeToAnnounce 81d61e043aa755b5171f7206aa9d1784461af48c6c17801ecc4aa3511697042d to AwaitingAnnouncedRemoteRevoke module="lightning::ln::channel" line=7355 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310974Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Building commitment transaction number 281474976710654 (really 1 xor 11450651307159) for channel 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9 for remote, generated by us with fee 253... module="lightning::ln::channel" line=2602 user_pk=a9edf959 id=0
2025-03-06T20:47:21.310993Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk:    ...including inbound AwaitingAnnouncedRemoteRevoke HTLC 0 (hash 81d61e043aa755b5171f7206aa9d1784461af48c6c17801ecc4aa3511697042d) with value 2000000000 module="lightning::ln::channel" line=2666 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311014Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk:    ...including to_remote output with value 7999774 module="lightning::ln::channel" line=2767 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311055Z DEBUG (lsp):(p2p-listener):(p2p-conn): ldk: Received valid commitment_signed from peer in channel 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9, updating HTLC state and responding with our own commitment_signed and a revoke_and_ack. module="lightning::ln::channel" line=4712 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311112Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Updating ChannelMonitor to id 1 for channel 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9 module="lightning::chain::chainmonitor" line=812 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311142Z  INFO (lsp):(p2p-listener):(p2p-conn): ldk: Applying update to monitor 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9, bringing update_id from 0 to 1 with 2 change(s). module="lightning::chain::channelmonitor" line=3088 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311159Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Updating ChannelMonitor with latest holder commitment transaction info module="lightning::chain::channelmonitor" line=3129 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311198Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Updating ChannelMonitor with latest counterparty commitment transaction info module="lightning::chain::channelmonitor" line=3138 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311218Z TRACE (lsp):(p2p-listener):(p2p-conn): ldk: Tracking new counterparty commitment transaction with txid c9e1985c86f9c6fb12c64bb15eaf61dff96884006516cc4b92cafa6b79a61dbd at commitment number 281474976710654 with 1 HTLC outputs module="lightning::chain::channelmonitor" line=2809 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311373Z  INFO (lsp):(p2p-listener):(p2p-conn): lsp::persister: Updating persisted channel funding_txo=e8c096a8b3be363b8adaf4b1d8723b5ac17eecc8cc9c31e08059f99902f22215_1 update_id=1 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311750Z DEBUG (lsp):(p2p-listener):(p2p-conn): ldk: Persistence of ChannelMonitorUpdate id 1 for channel 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9 in progress module="lightning::chain::chainmonitor" line=835 user_pk=a9edf959 id=0
2025-03-06T20:47:21.311778Z DEBUG (lsp):(p2p-listener):(p2p-conn): ldk: ChannelMonitor update for 1522f20299f95980e0319cccc8ec7ec15a3b72d8b1f4da8a3b36beb3a896c0e9 in flight, holding messages until the update completes. module="lightning::ln::channelmanager" line=8075 user_pk=a9edf959 id=0

We only notify again once all pending monitor updates complete. The node only seems to complete the first one (for the revoke_and_ack), but not the second one. It's hung here waiting for events to be processed so that it can handle the next monitor update, but there aren't any to be processed until we handle the next monitor update.

2025-03-06T20:47:21.333398Z DEBUG (node): ldk: Completed off-chain monitor update 2 for channel with funding outpoint OutPoint { txid: e8c096a8b3be363b8adaf4b1d8723b5ac17eecc8cc9c31e08059f99902f22215, index: 1 }, still have pending off-chain updates module="lightning::chain::chainmonitor" line=503 user_pk=bbf6c8a9 user_idx=0
2025-03-06T20:47:21.333421Z DEBUG (node): lexe_ln::channel_monitor: Triggering BGP via process_events_tx user_pk=bbf6c8a9 user_idx=0

[MaxFangX]

Thanks for looking through the logs.

It's hung here waiting for events to be processed so that it can handle the next monitor update, but there aren't any to be processed until we handle the next monitor update

You're right, I didn't comment out these lines when testing whether #2090 worked - my working assumption was that events should be processed after every monitor update instead of after all updates were complete. So our monitor persister task would hang waiting for events to be processed.

I've confirmed that all of our integration tests pass if our monitor persister task doesn't also wait on BGP event processing. So it looks like #2090 works after all, just not in the way that I expected. Thanks for your insight @wpaulino, closing this now.