Log chain calls in ChainMonitor, reducing logs in ChannelMonitor

For users with many ChannelMonitors, we log a large volume per
block simply because each ChannelMonitor lots several times per
block. Instead, we move to log only once at the TRACE level per
block call in ChannelMonitors, relying instead on a DEBUG level
log in ChainMonitor before we call any ChannelMonitor functions.

For most users, this will reduce redundant logging and also log at
the DEBUG level for block events, which is appropriate.

Fixes #980.

diff --git a/lightning/src/chain/chainmonitor.rs b/lightning/src/chain/chainmonitor.rs
index 12bfebbc4aeee8941b6ad4734cd1f539f8816360..8969427a0f960bc5766c153c8479a46974035b93 100644 (file)
--- a/lightning/src/chain/chainmonitor.rs
+++ b/lightning/src/chain/chainmonitor.rs
@@ -162,6 +162,7 @@ where
        fn block_connected(&self, block: &Block, height: u32) {
                let header = &block.header;
                let txdata: Vec<_> = block.txdata.iter().enumerate().collect();
+               log_debug!(self.logger, "New best block {} at height {} provided via block_connected", header.block_hash(), height);
                self.process_chain_data(header, &txdata, |monitor, txdata| {
                        monitor.block_connected(
                                header, txdata, height, &*self.broadcaster, &*self.fee_estimator, &*self.logger)
@@ -170,6 +171,7 @@ where
 
        fn block_disconnected(&self, header: &BlockHeader, height: u32) {
                let monitors = self.monitors.read().unwrap();
+               log_debug!(self.logger, "Latest block {} at height {} removed via block_disconnected", header.block_hash(), height);
                for monitor in monitors.values() {
                        monitor.block_disconnected(
                                header, height, &*self.broadcaster, &*self.fee_estimator, &*self.logger);
@@ -187,6 +189,7 @@ where
        P::Target: channelmonitor::Persist<ChannelSigner>,
 {
        fn transactions_confirmed(&self, header: &BlockHeader, txdata: &TransactionData, height: u32) {
+               log_debug!(self.logger, "{} provided transactions confirmed at height {} in block {}", txdata.len(), height, header.block_hash());
                self.process_chain_data(header, txdata, |monitor, txdata| {
                        monitor.transactions_confirmed(
                                header, txdata, height, &*self.broadcaster, &*self.fee_estimator, &*self.logger)
@@ -194,6 +197,7 @@ where
        }
 
        fn transaction_unconfirmed(&self, txid: &Txid) {
+               log_debug!(self.logger, "Transaction {} reorganized out of chain", txid);
                let monitors = self.monitors.read().unwrap();
                for monitor in monitors.values() {
                        monitor.transaction_unconfirmed(txid, &*self.broadcaster, &*self.fee_estimator, &*self.logger);
@@ -201,6 +205,7 @@ where
        }
 
        fn best_block_updated(&self, header: &BlockHeader, height: u32) {
+               log_debug!(self.logger, "New best block {} at height {} provided via best_block_updated", header.block_hash(), height);
                self.process_chain_data(header, &[], |monitor, txdata| {
                        // While in practice there shouldn't be any recursive calls when given empty txdata,
                        // it's still possible if a chain::Filter implementation returns a transaction.

diff --git a/lightning/src/chain/channelmonitor.rs b/lightning/src/chain/channelmonitor.rs
index 9c381a350309f1f94d099203f6926156aceca9d9..dc009c4d52cf3e5ef228e505abda9bf3b25d5ea2 100644 (file)
--- a/lightning/src/chain/channelmonitor.rs
+++ b/lightning/src/chain/channelmonitor.rs
@@ -1913,7 +1913,6 @@ impl<Signer: Sign> ChannelMonitorImpl<Signer> {
                                        L::Target: Logger,
        {
                let block_hash = header.block_hash();
-               log_trace!(logger, "New best block {} at height {}", block_hash, height);
                self.best_block = BestBlock::new(block_hash, height);
 
                self.transactions_confirmed(header, txdata, height, broadcaster, fee_estimator, logger)
@@ -1933,7 +1932,6 @@ impl<Signer: Sign> ChannelMonitorImpl<Signer> {
                L::Target: Logger,
        {
                let block_hash = header.block_hash();
-               log_trace!(logger, "New best block {} at height {}", block_hash, height);
 
                if height > self.best_block.height() {
                        self.best_block = BestBlock::new(block_hash, height);
@@ -1971,7 +1969,6 @@ impl<Signer: Sign> ChannelMonitorImpl<Signer> {
                }
 
                let block_hash = header.block_hash();
-               log_trace!(logger, "Block {} at height {} connected with {} txn matched", block_hash, height, txn_matched.len());
 
                let mut watch_outputs = Vec::new();
                let mut claimable_outpoints = Vec::new();
@@ -2044,6 +2041,7 @@ impl<Signer: Sign> ChannelMonitorImpl<Signer> {
                F::Target: FeeEstimator,
                L::Target: Logger,
        {
+               log_trace!(logger, "Processing {} matched transactions for block at height {}.", txn_matched.len(), conf_height);
                debug_assert!(self.best_block.height() >= conf_height);
 
                let should_broadcast = self.should_broadcast_holder_commitment_txn(logger);