From: Matt Corallo <git@bluematt.me>
Date: Tue, 17 Aug 2021 00:46:21 +0000 (+0000)
Subject: Log chain calls in ChainMonitor, reducing logs in ChannelMonitor
X-Git-Tag: v0.0.101~34^2~1
X-Git-Url: http://git.bitcoin.ninja/?a=commitdiff_plain;h=1e7d4798eb531ae3255b2fb82f07af81b56019a3;p=rust-lightning

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 12bfebbc4..8969427a0 100644
--- 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 9c381a350..dc009c4d5 100644
--- 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);