Changes to logger and macro logger

Author: henghonglee

lightning-background-processor/src/lib.rs

@@ -272,9 +272,9 @@ macro_rules! define_run_body {
 	 $loop_exit_check: expr, $await: expr, $get_timer: expr, $timer_elapsed: expr,
 	 $check_slow_await: expr)
 	=> { {
-		log_trace!($logger, "Calling ChannelManager's timer_tick_occurred on startup");
+		log_trace!($logger, None, None, "Calling ChannelManager's timer_tick_occurred on startup");
 		$channel_manager.timer_tick_occurred();
-		log_trace!($logger, "Rebroadcasting monitor's pending claims on startup");
+		log_trace!($logger, None, None, "Rebroadcasting monitor's pending claims on startup");
 		$chain_monitor.rebroadcast_pending_claims();
 
 		let mut last_freshness_call = $get_timer(FRESHNESS_TIMER);
@@ -303,7 +303,7 @@ macro_rules! define_run_body {
 
 			// Exit the loop if the background processor was requested to stop.
 			if $loop_exit_check {
-				log_trace!($logger, "Terminating background processor.");
+				log_trace!($logger, None, None, "Terminating background processor.");
 				break;
 			}
 
@@ -316,17 +316,17 @@ macro_rules! define_run_body {
 
 			// Exit the loop if the background processor was requested to stop.
 			if $loop_exit_check {
-				log_trace!($logger, "Terminating background processor.");
+				log_trace!($logger, None, None, "Terminating background processor.");
 				break;
 			}
 
 			if updates_available {
-				log_trace!($logger, "Persisting ChannelManager...");
+				log_trace!($logger, None, None, "Persisting ChannelManager...");
 				$persister.persist_manager(&*$channel_manager)?;
-				log_trace!($logger, "Done persisting ChannelManager.");
+				log_trace!($logger, None, None, "Done persisting ChannelManager.");
 			}
 			if $timer_elapsed(&mut last_freshness_call, FRESHNESS_TIMER) {
-				log_trace!($logger, "Calling ChannelManager's timer_tick_occurred");
+				log_trace!($logger, None, None, "Calling ChannelManager's timer_tick_occurred");
 				$channel_manager.timer_tick_occurred();
 				last_freshness_call = $get_timer(FRESHNESS_TIMER);
 			}
@@ -343,11 +343,11 @@ macro_rules! define_run_body {
 				// may call Bitcoin Core RPCs during event handling, which very often takes
 				// more than a handful of seconds to complete, and shouldn't disconnect all our
 				// peers.
-				log_trace!($logger, "100ms sleep took more than a second, disconnecting peers.");
+				log_trace!($logger, None, None, "100ms sleep took more than a second, disconnecting peers.");
 				$peer_manager.as_ref().disconnect_all_peers();
 				last_ping_call = $get_timer(PING_TIMER);
 			} else if $timer_elapsed(&mut last_ping_call, PING_TIMER) {
-				log_trace!($logger, "Calling PeerManager's timer_tick_occurred");
+				log_trace!($logger, None, None, "Calling PeerManager's timer_tick_occurred");
 				$peer_manager.as_ref().timer_tick_occurred();
 				last_ping_call = $get_timer(PING_TIMER);
 			}
@@ -367,16 +367,16 @@ macro_rules! define_run_body {
 				// The network graph must not be pruned while rapid sync completion is pending
 				if let Some(network_graph) = $gossip_sync.prunable_network_graph() {
 					#[cfg(feature = "std")] {
-						log_trace!($logger, "Pruning and persisting network graph.");
+						log_trace!($logger, None, None, "Pruning and persisting network graph.");
 						network_graph.remove_stale_channels_and_tracking();
 					}
 					#[cfg(not(feature = "std"))] {
-						log_warn!($logger, "Not pruning network graph, consider enabling `std` or doing so manually with remove_stale_channels_and_tracking_with_time.");
-						log_trace!($logger, "Persisting network graph.");
+						log_warn!($logger, None, None, "Not pruning network graph, consider enabling `std` or doing so manually with remove_stale_channels_and_tracking_with_time.");
+						log_trace!($logger, None, None, "Persisting network graph.");
 					}
 
 					if let Err(e) = $persister.persist_graph(network_graph) {
-						log_error!($logger, "Error: Failed to persist network graph, check your disk and permissions {}", e)
+						log_error!($logger, None, None, "Error: Failed to persist network graph, check your disk and permissions {}", e)
 					}
 
 					have_pruned = true;
@@ -387,16 +387,16 @@ macro_rules! define_run_body {
 
 			if $timer_elapsed(&mut last_scorer_persist_call, SCORER_PERSIST_TIMER) {
 				if let Some(ref scorer) = $scorer {
-					log_trace!($logger, "Persisting scorer");
+					log_trace!($logger, None, None, "Persisting scorer");
 					if let Err(e) = $persister.persist_scorer(&scorer) {
-						log_error!($logger, "Error: Failed to persist scorer, check your disk and permissions {}", e)
+						log_error!($logger, None, None, "Error: Failed to persist scorer, check your disk and permissions {}", e)
 					}
 				}
 				last_scorer_persist_call = $get_timer(SCORER_PERSIST_TIMER);
 			}
 
 			if $timer_elapsed(&mut last_rebroadcast_call, REBROADCAST_TIMER) {
-				log_trace!($logger, "Rebroadcasting monitor's pending claims");
+				log_trace!($logger, None, None, "Rebroadcasting monitor's pending claims");
 				$chain_monitor.rebroadcast_pending_claims();
 				last_rebroadcast_call = $get_timer(REBROADCAST_TIMER);
 			}
@@ -633,9 +633,9 @@ where
 			}
 			if let Some(ref scorer) = scorer {
 				if update_scorer(scorer, &event) {
-					log_trace!(logger, "Persisting scorer after update");
+					log_trace!(logger, None, None, "Persisting scorer after update");
 					if let Err(e) = persister.persist_scorer(&scorer) {
-						log_error!(logger, "Error: Failed to persist scorer, check your disk and permissions {}", e)
+						log_error!(logger, None, None, "Error: Failed to persist scorer, check your disk and permissions {}", e)
 					}
 				}
 			}
@@ -768,9 +768,9 @@ impl BackgroundProcessor {
 				}
 				if let Some(ref scorer) = scorer {
 					if update_scorer(scorer, &event) {
-						log_trace!(logger, "Persisting scorer after update");
+						log_trace!(logger, None, None, "Persisting scorer after update");
 						if let Err(e) = persister.persist_scorer(&scorer) {
-							log_error!(logger, "Error: Failed to persist scorer, check your disk and permissions {}", e)
+							log_error!(logger, None, None, "Error: Failed to persist scorer, check your disk and permissions {}", e)
 						}
 					}
 				}

lightning-invoice/src/utils.rs

@@ -187,7 +187,7 @@ where
 		.map_err(|_| SignOrCreationError::CreationError(CreationError::InvalidAmount))?
 	};
 
-	log_trace!(logger, "Creating phantom invoice from {} participating nodes with payment hash {}",
+	log_trace!(logger, None, None, "Creating phantom invoice from {} participating nodes with payment hash {}",
 		phantom_route_hints.len(), log_bytes!(payment_hash.0));
 
 	let mut invoice = invoice
@@ -236,7 +236,7 @@ where
 	let mut phantom_hints: Vec<Vec<RouteHint>> = Vec::new();
 
 	for PhantomRouteHints { channels, phantom_scid, real_node_pubkey } in phantom_route_hints {
-		log_trace!(logger, "Generating phantom route hints for node {}",
+		log_trace!(logger, None, None, "Generating phantom route hints for node {}",
 			log_pubkey!(real_node_pubkey));
 		let mut route_hints = sort_and_filter_channels(channels, amt_msat, &logger);
 
@@ -513,7 +513,7 @@ fn _create_invoice_from_channelmanager_and_duration_since_epoch_with_payment_has
 		return Err(SignOrCreationError::CreationError(CreationError::MinFinalCltvExpiryDeltaTooShort));
 	}
 
-	log_trace!(logger, "Creating invoice with payment hash {}", log_bytes!(payment_hash.0));
+	log_trace!(logger, None, None, "Creating invoice with payment hash {}", log_bytes!(payment_hash.0));
 
 	let invoice = match description {
 		InvoiceDescription::Direct(description) => {
@@ -584,10 +584,10 @@ fn sort_and_filter_channels<L: Deref>(
 	let mut online_min_capacity_channel_exists = false;
 	let mut has_pub_unconf_chan = false;
 
-	log_trace!(logger, "Considering {} channels for invoice route hints", channels.len());
+	log_trace!(logger, None, None, "Considering {} channels for invoice route hints", channels.len());
 	for channel in channels.into_iter().filter(|chan| chan.is_channel_ready) {
 		if channel.get_inbound_payment_scid().is_none() || channel.counterparty.forwarding_info.is_none() {
-			log_trace!(logger, "Ignoring channel {} for invoice route hints", log_bytes!(channel.channel_id));
+			log_trace!(logger, None, None, "Ignoring channel {} for invoice route hints", log_bytes!(channel.channel_id));
 			continue;
 		}
 
@@ -600,15 +600,15 @@ fn sort_and_filter_channels<L: Deref>(
 			} else {
 				// If any public channel exists, return no hints and let the sender
 				// look at the public channels instead.
-				log_trace!(logger, "Not including channels in invoice route hints on account of public channel {}",
+				log_trace!(logger, None, None, "Not including channels in invoice route hints on account of public channel {}",
 					log_bytes!(channel.channel_id));
 				return vec![]
 			}
 		}
 
 		if channel.inbound_capacity_msat >= min_inbound_capacity {
 			if !min_capacity_channel_exists {
-				log_trace!(logger, "Channel with enough inbound capacity exists for invoice route hints");
+				log_trace!(logger, None, None, "Channel with enough inbound capacity exists for invoice route hints");
 				min_capacity_channel_exists = true;
 			}
 
@@ -618,7 +618,7 @@ fn sort_and_filter_channels<L: Deref>(
 		}
 
 		if channel.is_usable && !online_channel_exists {
-			log_trace!(logger, "Channel with connected peer exists for invoice route hints");
+			log_trace!(logger, None, None, "Channel with connected peer exists for invoice route hints");
 			online_channel_exists = true;
 		}
 
@@ -638,7 +638,7 @@ fn sort_and_filter_channels<L: Deref>(
 				let new_channel_preferable = channel.is_public == entry.get().is_public && !prefer_current;
 
 				if new_now_public || new_channel_preferable {
-					log_trace!(logger,
+					log_trace!(logger, None, None,
 						"Preferring counterparty {} channel {} (SCID {:?}, {} msats) over {} (SCID {:?}, {} msats) for invoice route hints",
 						log_pubkey!(channel.counterparty.node_id),
 						log_bytes!(channel.channel_id), channel.short_channel_id,
@@ -647,7 +647,7 @@ fn sort_and_filter_channels<L: Deref>(
 						current_max_capacity);
 					entry.insert(channel);
 				} else {
-					log_trace!(logger,
+					log_trace!(logger, None, None,
 						"Preferring counterparty {} channel {} (SCID {:?}, {} msats) over {} (SCID {:?}, {} msats) for invoice route hints",
 						log_pubkey!(channel.counterparty.node_id),
 						log_bytes!(entry.get().channel_id), entry.get().short_channel_id,
@@ -703,14 +703,14 @@ fn sort_and_filter_channels<L: Deref>(
 			} else { true };
 
 			if include_channel {
-				log_trace!(logger, "Including channel {} in invoice route hints",
+				log_trace!(logger, None, None, "Including channel {} in invoice route hints",
 					log_bytes!(channel.channel_id));
 			} else if !has_enough_capacity {
-				log_trace!(logger, "Ignoring channel {} without enough capacity for invoice route hints",
+				log_trace!(logger, None, None, "Ignoring channel {} without enough capacity for invoice route hints",
 					log_bytes!(channel.channel_id));
 			} else {
 				debug_assert!(!channel.is_usable || (has_pub_unconf_chan && !channel.is_public));
-				log_trace!(logger, "Ignoring channel {} with disconnected peer",
+				log_trace!(logger, None, None, "Ignoring channel {} with disconnected peer",
 					log_bytes!(channel.channel_id));
 			}
 

lightning-rapid-gossip-sync/src/processing.rs

@@ -59,7 +59,7 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
 		mut read_cursor: &mut R,
 		current_time_unix: Option<u64>
 	) -> Result<u32, GraphSyncError> {
-		log_trace!(self.logger, "Processing RGS data...");
+		log_trace!(self.logger, None, None, "Processing RGS data...");
 		let mut prefix = [0u8; 4];
 		read_cursor.read_exact(&mut prefix)?;
 
@@ -112,7 +112,7 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
 			let node_id_1 = node_ids[node_id_1_index.0 as usize];
 			let node_id_2 = node_ids[node_id_2_index.0 as usize];
 
-			log_gossip!(self.logger, "Adding channel {} from RGS announcement at {}",
+			log_gossip!(self.logger, None, None, "Adding channel {} from RGS announcement at {}",
 				short_channel_id, latest_seen_timestamp);
 
 			let announcement_result = network_graph.add_channel_from_partial_announcement(
@@ -126,7 +126,7 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
 				if let ErrorAction::IgnoreDuplicateGossip = lightning_error.action {
 					// everything is fine, just a duplicate channel announcement
 				} else {
-					log_warn!(self.logger, "Failed to process channel announcement: {:?}", lightning_error);
+					log_warn!(self.logger, None, None, "Failed to process channel announcement: {:?}", lightning_error);
 					return Err(lightning_error.into());
 				}
 			}
@@ -135,7 +135,7 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
 		previous_scid = 0; // updates start at a new scid
 
 		let update_count: u32 = Readable::read(read_cursor)?;
-		log_debug!(self.logger, "Processing RGS update from {} with {} nodes, {} channel announcements and {} channel updates.",
+		log_debug!(self.logger, None, None, "Processing RGS update from {} with {} nodes, {} channel announcements and {} channel updates.",
 			latest_seen_timestamp, node_id_count, announcement_count, update_count);
 		if update_count == 0 {
 			return Ok(latest_seen_timestamp);
@@ -188,7 +188,7 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
 					synthetic_update.fee_base_msat = directional_info.fees.base_msat;
 					synthetic_update.fee_proportional_millionths = directional_info.fees.proportional_millionths;
 				} else {
-					log_trace!(self.logger,
+					log_trace!(self.logger, None, None,
 						"Skipping application of channel update for chan {} with flags {} as original data is missing.",
 						short_channel_id, channel_flags);
 					skip_update_for_unknown_channel = true;
@@ -224,13 +224,13 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
 				continue;
 			}
 
-			log_gossip!(self.logger, "Updating channel {} with flags {} from RGS announcement at {}",
+			log_gossip!(self.logger, None, None, "Updating channel {} with flags {} from RGS announcement at {}",
 				short_channel_id, channel_flags, latest_seen_timestamp);
 			match network_graph.update_channel_unsigned(&synthetic_update) {
 				Ok(_) => {},
 				Err(LightningError { action: ErrorAction::IgnoreDuplicateGossip, .. }) => {},
 				Err(LightningError { action: ErrorAction::IgnoreAndLog(level), err }) => {
-					log_given_level!(self.logger, level, "Failed to apply channel update: {:?}", err);
+					log_given_level!(self.logger, level, None, None, "Failed to apply channel update: {:?}", err);
 				},
 				Err(LightningError { action: ErrorAction::IgnoreError, .. }) => {},
 				Err(e) => return Err(e.into()),
@@ -244,7 +244,7 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
 		}
 
 		self.is_initial_sync_complete.store(true, Ordering::Release);
-		log_trace!(self.logger, "Done processing RGS data from {}", latest_seen_timestamp);
+		log_trace!(self.logger, None, None, "Done processing RGS data from {}", latest_seen_timestamp);
 		Ok(latest_seen_timestamp)
 	}
 }

lightning-transaction-sync/src/esplora.rs

@@ -89,7 +89,7 @@ where
 		#[cfg(feature = "async-interface")]
 		let mut sync_state = self.sync_state.lock().await;
 
-		log_info!(self.logger, "Starting transaction sync.");
+		log_info!(self.logger, None, None, "Starting transaction sync.");
 
 		let mut tip_hash = maybe_await!(self.client.get_tip_hash())?;
 
@@ -120,7 +120,7 @@ where
 						},
 						Err(err) => {
 							// (Semi-)permanent failure, retry later.
-							log_error!(self.logger, "Failed during transaction sync, aborting.");
+							log_error!(self.logger, None, None, "Failed during transaction sync, aborting.");
 							sync_state.pending_sync = true;
 							return Err(TxSyncError::from(err));
 						}
@@ -130,7 +130,7 @@ where
 						Ok(()) => {}
 						Err(InternalError::Inconsistency) => {
 							// Immediately restart syncing when we encounter any inconsistencies.
-							log_debug!(self.logger, "Encountered inconsistency during transaction sync, restarting.");
+							log_debug!(self.logger, None, None, "Encountered inconsistency during transaction sync, restarting.");
 							sync_state.pending_sync = true;
 							continue;
 						}
@@ -160,13 +160,13 @@ where
 					}
 					Err(InternalError::Inconsistency) => {
 						// Immediately restart syncing when we encounter any inconsistencies.
-						log_debug!(self.logger, "Encountered inconsistency during transaction sync, restarting.");
+						log_debug!(self.logger, None, None, "Encountered inconsistency during transaction sync, restarting.");
 						sync_state.pending_sync = true;
 						continue;
 					}
 					Err(err) => {
 						// (Semi-)permanent failure, retry later.
-						log_error!(self.logger, "Failed during transaction sync, aborting.");
+						log_error!(self.logger, None, None, "Failed during transaction sync, aborting.");
 						sync_state.pending_sync = true;
 						return Err(TxSyncError::from(err));
 					}
@@ -175,7 +175,7 @@ where
 				sync_state.pending_sync = false;
 			}
 		}
-		log_info!(self.logger, "Finished transaction sync.");
+		log_info!(self.logger, None, None, "Finished transaction sync.");
 		Ok(())
 	}
 
@@ -273,7 +273,7 @@ where
 			let block_hash = block_header.block_hash();
 			if let Some(expected_block_hash) = expected_block_hash {
 				if expected_block_hash != block_hash {
-					log_trace!(self.logger, "Inconsistency: Tx {} expected in block {}, but is confirmed in {}", txid, expected_block_hash, block_hash);
+					log_trace!(self.logger, None, None, "Inconsistency: Tx {} expected in block {}, but is confirmed in {}", txid, expected_block_hash, block_hash);
 					return Err(InternalError::Inconsistency);
 				}
 			}
@@ -282,7 +282,7 @@ where
 			let mut indexes = Vec::new();
 			let _ = merkle_block.txn.extract_matches(&mut matches, &mut indexes);
 			if indexes.len() != 1 || matches.len() != 1 || matches[0] != *txid {
-				log_error!(self.logger, "Retrieved Merkle block for txid {} doesn't match expectations. This should not happen. Please verify server integrity.", txid);
+				log_error!(self.logger, None, None, "Retrieved Merkle block for txid {} doesn't match expectations. This should not happen. Please verify server integrity.", txid);
 				return Err(InternalError::Failed);
 			}
 
@@ -299,7 +299,7 @@ where
 				} else {
 					// If any previously-confirmed block suddenly is no longer confirmed, we found
 					// an inconsistency and should start over.
-					log_trace!(self.logger, "Inconsistency: Tx {} was unconfirmed during syncing.", txid);
+					log_trace!(self.logger, None, None, "Inconsistency: Tx {} was unconfirmed during syncing.", txid);
 					return Err(InternalError::Inconsistency);
 				}
 			}
@@ -330,7 +330,7 @@ where
 
 				unconfirmed_txs.push(txid);
 			} else {
-				log_error!(self.logger, "Untracked confirmation of funding transaction. Please ensure none of your channels had been created with LDK prior to version 0.0.113!");
+				log_error!(self.logger, None, None, "Untracked confirmation of funding transaction. Please ensure none of your channels had been created with LDK prior to version 0.0.113!");
 				panic!("Untracked confirmation of funding transaction. Please ensure none of your channels had been created with LDK prior to version 0.0.113!");
 			}
 		}