Optimize block connection logging using LazyTxid#4659
Conversation
Upgrade best_block_updated log from TRACE to INFO so chain tip updates are visible without enabling full trace logging. Add per-txid DEBUG logs in transactions_confirmed to make it easier to identify which transactions triggered channel updates.
…gging Use a lazy Display wrapper to format confirmed txids, preventing unconditional hashing when DEBUG logging is disabled.
|
I've assigned @valentinewallace as a reviewer! |
| for (_, tx) in txdata.iter() { | ||
| log_debug!(self.logger, "Confirmed transaction {} in block {} at height {}", LazyTxid(tx), block_hash, height); | ||
| } |
There was a problem hiding this comment.
This loop logs every transaction in txdata, but txdata is not necessarily filtered to only channel-relevant transactions. In the Listen::block_connected → filtered_block_connected → transactions_confirmed path, txdata contains all transactions in the block (see block_connected default impl in chain/mod.rs:190-192). Even with BIP 157/158 compact block filters, the filtering is block-level, not transaction-level, so a matching block still delivers all its transactions here.
On mainnet blocks with ~2000-3000 transactions, this produces thousands of DEBUG log lines per block (~every 10 minutes), almost all for transactions completely unrelated to the node's channels. If DEBUG is enabled, each line also triggers a compute_txid() (double-SHA256 of the serialized transaction).
Consider either:
- Moving this logging after channel processing so you only log transactions that actually triggered a channel update, or
- Gating this on TRACE instead of DEBUG, consistent with the existing aggregate log on the line above.
Review SummaryInline comments posted:
No other issues found. The |
|
🔔 1st Reminder Hey @valentinewallace! This PR has been waiting for your review. |
shaavan
left a comment
There was a problem hiding this comment.
Thanks for the PR!
I was wondering about a slightly different approach here. Since we care about both block sync and transaction sync, and want to log relevant chain activity only once, would it make sense to introduce the logging closer to the point where relevant activity is first identified and handed off for processing, for example:
lightning-transaction-sync/src/common.rsinSyncState::sync_confirmed_transactionslightning-transaction-sync/src/common.rsinSyncState::sync_unconfirmed_transactionslightning-transaction-sync/src/common.rsinFilterQueue::process_queues
One thing that stood out to me is that transactions_confirmed may receive the full transaction set for a connected block. If we log at that level, we may end up logging every transaction in the block rather than only the transactions that are relevant to LDK. My reading of the issue is that it's primarily about improving visibility into the transactions that sync identifies as relevant.
I also noticed a couple of pieces that seem to still be missing relative to the issue description:
- logging for transactions that become unconfirmed during sync / reorg handling
- logging for txs / outputs that are newly added to the watch set / filter
Another detail the issue calls out is that we only want to list transaction IDs when the set is reasonably small. For larger batches, a summary log such as Confirmed 42 transactions at block height X is probably sufficient. As written, this would log one line per transaction, which could get fairly noisy.
One possible direction could be:
- log confirmed transaction summaries at the sync layer
- log unconfirmed transaction summaries at the sync layer
- log newly watched txs / outputs when processing filter registrations
- include explicit txids only when the set is small, otherwise log counts
To me, that seems to align more closely with the issue description while also avoiding duplicate logging and keeping log volume manageable.
Also, one small note on the commit structure: it looks like the first two commits introduce the feature changes, while the top commit is a rebase onto main. We usually prefer rebasing first and then placing the feature commits on top so the history reads a bit more naturally.
Here's a guide on rebasing that may be helpful. Thanks again for working on this!
This PR replaces PR #4586. I am resubmitting it from this account because my previous account (Alkamal01) is currently experiencing unexpected visibility restrictions from GitHub's automated filters, making the original PR inaccessible to reviewers. This contains the same code and logic as originally proposed.
Fixes #2348. Supersedes #4420.
best_block_updatedwas logging at TRACE, making it impossible to track chain tip progress without enabling full trace logging. This upgrades it to INFO.Also adds per-txid DEBUG logs in
transactions_confirmedso individual transactions triggering channel updates are visible at a useful log level.The original PR #4420 also added an INFO log in
filtered_block_connected, but that duplicates the one inbest_block_updated(whichfiltered_block_connectedcalls directly). That log is left out here.