Merge pull request #4217 from joostjager/chan-logging

Log structured peer, channel and hash fields

Author: joostjager

fuzz/src/full_stack.rs

@@ -1609,14 +1609,7 @@ mod tests {
 				.unwrap()
 				.entry((record.module_path.to_string(), format!("{}", record.args)))
 				.or_insert(0) += 1;
-			println!(
-				"{:<5} [{} : {}, {}] {}",
-				record.level.to_string(),
-				record.module_path,
-				record.file,
-				record.line,
-				record.args
-			);
+			println!("{}", record);
 		}
 	}
 

fuzz/src/onion_message.rs

@@ -102,7 +102,11 @@ impl MessageRouter for TestMessageRouter {
 	fn find_path(
 		&self, _sender: PublicKey, _peers: Vec<PublicKey>, destination: Destination,
 	) -> Result<OnionMessagePath, ()> {
-		Ok(OnionMessagePath { intermediate_nodes: vec![], destination, first_node_addresses: vec![] })
+		Ok(OnionMessagePath {
+			intermediate_nodes: vec![],
+			destination,
+			first_node_addresses: vec![],
+		})
 	}
 
 	fn create_blinded_paths<T: secp256k1::Signing + secp256k1::Verification>(
@@ -328,14 +332,7 @@ mod tests {
 			let mut lines_lock = self.lines.lock().unwrap();
 			let key = (record.module_path.to_string(), format!("{}", record.args));
 			*lines_lock.entry(key).or_insert(0) += 1;
-			println!(
-				"{:<5} [{} : {}, {}] {}",
-				record.level.to_string(),
-				record.module_path,
-				record.file,
-				record.line,
-				record.args
-			);
+			println!("{}", record);
 		}
 	}
 

fuzz/src/utils/test_logger.rs

@@ -59,15 +59,6 @@ impl<'a, Out: Output> Write for LockedWriteAdapter<'a, Out> {
 
 impl<Out: Output> Logger for TestLogger<Out> {
 	fn log(&self, record: Record) {
-		write!(
-			LockedWriteAdapter(&self.out),
-			"{:<5} {} [{} : {}] {}\n",
-			record.level.to_string(),
-			self.id,
-			record.module_path,
-			record.line,
-			record.args
-		)
-		.unwrap();
+		write!(LockedWriteAdapter(&self.out), "{:<6} {}", self.id, record).unwrap();
 	}
 }

lightning-dns-resolver/src/lib.rs

@@ -192,7 +192,7 @@ mod test {
 	}
 	impl Logger for TestLogger {
 		fn log(&self, record: lightning::util::logger::Record) {
-			eprintln!("{}: {}", self.node, record.args);
+			eprintln!("{:<8} {}", self.node, record);
 		}
 	}
 	impl Deref for TestLogger {

lightning-net-tokio/src/lib.rs

@@ -629,14 +629,7 @@ mod tests {
 	pub struct TestLogger();
 	impl lightning::util::logger::Logger for TestLogger {
 		fn log(&self, record: lightning::util::logger::Record) {
-			println!(
-				"{:<5} [{} : {}, {}] {}",
-				record.level.to_string(),
-				record.module_path,
-				record.file,
-				record.line,
-				record.args
-			);
+			println!("{}", record);
 		}
 	}
 

lightning/src/chain/chainmonitor.rs

@@ -580,23 +580,17 @@ where
 
 		let has_pending_claims = monitor_state.monitor.has_pending_claims();
 		if has_pending_claims || get_partition_key(channel_id) % partition_factor == 0 {
-			log_trace!(
-				logger,
-				"Syncing Channel Monitor for channel {}",
-				log_funding_info!(monitor)
-			);
+			log_trace!(logger, "Syncing Channel Monitor");
 			// Even though we don't track monitor updates from chain-sync as pending, we still want
 			// updates per-channel to be well-ordered so that users don't see a
 			// `ChannelMonitorUpdate` after a channel persist for a channel with the same
 			// `latest_update_id`.
 			let _pending_monitor_updates = monitor_state.pending_monitor_updates.lock().unwrap();
 			match self.persister.update_persisted_channel(monitor.persistence_key(), None, monitor)
 			{
-				ChannelMonitorUpdateStatus::Completed => log_trace!(
-					logger,
-					"Finished syncing Channel Monitor for channel {} for block-data",
-					log_funding_info!(monitor)
-				),
+				ChannelMonitorUpdateStatus::Completed => {
+					log_trace!(logger, "Finished syncing Channel Monitor for block-data")
+				},
 				ChannelMonitorUpdateStatus::InProgress => {
 					log_trace!(
 						logger,
@@ -961,16 +955,12 @@ where
 		}
 		if have_monitors_to_prune {
 			let mut monitors = self.monitors.write().unwrap();
-			monitors.retain(|channel_id, monitor_holder| {
+			monitors.retain(|_channel_id, monitor_holder| {
 				let logger = WithChannelMonitor::from(&self.logger, &monitor_holder.monitor, None);
 				let (is_fully_resolved, _) =
 					monitor_holder.monitor.check_and_update_full_resolution_status(&logger);
 				if is_fully_resolved {
-					log_info!(
-						logger,
-						"Archiving fully resolved ChannelMonitor for channel ID {}",
-						channel_id
-					);
+					log_info!(logger, "Archiving fully resolved ChannelMonitor");
 					self.persister
 						.archive_persisted_channel(monitor_holder.monitor.persistence_key());
 					false
@@ -1106,11 +1096,7 @@ where
 			},
 			hash_map::Entry::Vacant(e) => e,
 		};
-		log_trace!(
-			logger,
-			"Loaded existing ChannelMonitor for channel {}",
-			log_funding_info!(monitor)
-		);
+		log_trace!(logger, "Loaded existing ChannelMonitor");
 		if let Some(ref chain_source) = self.chain_source {
 			monitor.load_outputs_to_watch(chain_source, &self.logger);
 		}
@@ -1366,25 +1352,17 @@ where
 			},
 			hash_map::Entry::Vacant(e) => e,
 		};
-		log_trace!(logger, "Got new ChannelMonitor for channel {}", log_funding_info!(monitor));
+		log_trace!(logger, "Got new ChannelMonitor");
 		let update_id = monitor.get_latest_update_id();
 		let mut pending_monitor_updates = Vec::new();
 		let persist_res = self.persister.persist_new_channel(monitor.persistence_key(), &monitor);
 		match persist_res {
 			ChannelMonitorUpdateStatus::InProgress => {
-				log_info!(
-					logger,
-					"Persistence of new ChannelMonitor for channel {} in progress",
-					log_funding_info!(monitor)
-				);
+				log_info!(logger, "Persistence of new ChannelMonitor in progress",);
 				pending_monitor_updates.push(update_id);
 			},
 			ChannelMonitorUpdateStatus::Completed => {
-				log_info!(
-					logger,
-					"Persistence of new ChannelMonitor for channel {} completed",
-					log_funding_info!(monitor)
-				);
+				log_info!(logger, "Persistence of new ChannelMonitor completed",);
 			},
 			ChannelMonitorUpdateStatus::UnrecoverableError => {
 				let err_str = "ChannelMonitor[Update] persistence failed unrecoverably. This indicates we cannot continue normal operation and must shut down.";
@@ -1426,12 +1404,7 @@ where
 			Some(monitor_state) => {
 				let monitor = &monitor_state.monitor;
 				let logger = WithChannelMonitor::from(&self.logger, &monitor, None);
-				log_trace!(
-					logger,
-					"Updating ChannelMonitor to id {} for channel {}",
-					update.update_id,
-					log_funding_info!(monitor)
-				);
+				log_trace!(logger, "Updating ChannelMonitor to id {}", update.update_id,);
 
 				// We hold a `pending_monitor_updates` lock through `update_monitor` to ensure we
 				// have well-ordered updates from the users' point of view. See the
@@ -1452,7 +1425,7 @@ where
 					// We don't want to persist a `monitor_update` which results in a failure to apply later
 					// while reading `channel_monitor` with updates from storage. Instead, we should persist
 					// the entire `channel_monitor` here.
-					log_warn!(logger, "Failed to update ChannelMonitor for channel {}. Going ahead and persisting the entire ChannelMonitor", log_funding_info!(monitor));
+					log_warn!(logger, "Failed to update ChannelMonitor. Going ahead and persisting the entire ChannelMonitor");
 					self.persister.update_persisted_channel(
 						monitor.persistence_key(),
 						None,
@@ -1468,18 +1441,17 @@ where
 				match persist_res {
 					ChannelMonitorUpdateStatus::InProgress => {
 						pending_monitor_updates.push(update_id);
-						log_debug!(logger,
-							"Persistence of ChannelMonitorUpdate id {:?} for channel {} in progress",
+						log_debug!(
+							logger,
+							"Persistence of ChannelMonitorUpdate id {:?} in progress",
 							update_id,
-							log_funding_info!(monitor)
 						);
 					},
 					ChannelMonitorUpdateStatus::Completed => {
 						log_debug!(
 							logger,
-							"Persistence of ChannelMonitorUpdate id {:?} for channel {} completed",
+							"Persistence of ChannelMonitorUpdate id {:?} completed",
 							update_id,
-							log_funding_info!(monitor)
 						);
 					},
 					ChannelMonitorUpdateStatus::UnrecoverableError => {

lightning/src/chain/channelmonitor.rs

@@ -4223,8 +4223,8 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
 			log_info!(logger, "Applying pre-0.1 force close update to monitor {} with {} change(s).",
 				log_funding_info!(self), updates.updates.len());
 		} else {
-			log_info!(logger, "Applying update to monitor {}, bringing update_id from {} to {} with {} change(s).",
-				log_funding_info!(self), self.latest_update_id, updates.update_id, updates.updates.len());
+			log_info!(logger, "Applying update, bringing update_id from {} to {} with {} change(s).",
+				self.latest_update_id, updates.update_id, updates.updates.len());
 		}
 
 		// ChannelMonitor updates may be applied after force close if we receive a preimage for a
@@ -4351,7 +4351,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
 						self.queue_latest_holder_commitment_txn_for_broadcast(broadcaster, &bounded_fee_estimator, logger, true);
 					} else if !self.holder_tx_signed {
 						log_error!(logger, "WARNING: You have a potentially-unsafe holder commitment transaction available to broadcast");
-						log_error!(logger, "    in channel monitor for channel {}!", &self.channel_id());
+						log_error!(logger, "    in channel monitor!");
 						log_error!(logger, "    Read the docs for ChannelMonitor::broadcast_latest_holder_commitment_txn to take manual action!");
 					} else {
 						// If we generated a MonitorEvent::HolderForceClosed, the ChannelManager
@@ -5479,7 +5479,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
 				} else {
 					"".to_string()
 				};
-				log_info!(logger, "{desc} for channel {} confirmed with txid {txid}{action}", self.channel_id());
+				log_info!(logger, "{desc} confirmed with txid {txid}{action}");
 
 				self.alternative_funding_confirmed = Some((txid, height));
 
@@ -5531,8 +5531,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
 							.map(|(txid, _)| txid)
 							.unwrap_or_else(|| self.funding.funding_txid())
 					);
-					log_info!(logger, "Channel {} closed by funding output spend in txid {txid}",
-						self.channel_id());
+					log_info!(logger, "Channel closed by funding output spend in txid {txid}");
 					if !self.funding_spend_seen {
 						self.pending_monitor_events.push(MonitorEvent::CommitmentTxConfirmed(()));
 					}

lightning/src/ln/chanmon_update_fail_tests.rs

@@ -150,8 +150,7 @@ fn test_monitor_and_persister_update_fail() {
 				}
 				logger.assert_log_regex(
 					"lightning::chain::chainmonitor",
-					regex::Regex::new("Failed to update ChannelMonitor for channel [0-9a-f]*.")
-						.unwrap(),
+					regex::Regex::new("Failed to update ChannelMonitor").unwrap(),
 					1,
 				);