Improve logging for de/ser failures and start/stop

Author: tnull

src/io/utils.rs

@@ -92,7 +92,7 @@ where
 }
 
 /// Read a previously persisted [`NetworkGraph`] from the store.
-pub(crate) fn read_network_graph<K: Deref, L: Deref>(
+pub(crate) fn read_network_graph<K: Deref, L: Deref + Clone>(
 	kv_store: K, logger: L,
 ) -> Result<NetworkGraph<L>, std::io::Error>
 where
@@ -101,14 +101,15 @@ where
 {
 	let mut reader =
 		kv_store.read(NETWORK_GRAPH_PERSISTENCE_NAMESPACE, NETWORK_GRAPH_PERSISTENCE_KEY)?;
-	let graph = NetworkGraph::read(&mut reader, logger).map_err(|_| {
-		std::io::Error::new(std::io::ErrorKind::InvalidData, "Failed to deserialize NetworkGraph")
+	let graph = NetworkGraph::read(&mut reader, logger.clone()).map_err(|e| {
+		log_error!(logger, "Failed to deserialize network graph: {}", e);
+		std::io::Error::new(std::io::ErrorKind::InvalidData, "Failed to deserialize network graph")
 	})?;
 	Ok(graph)
 }
 
 /// Read a previously persisted [`Scorer`] from the store.
-pub(crate) fn read_scorer<K: Deref, G: Deref<Target = NetworkGraph<L>>, L: Deref>(
+pub(crate) fn read_scorer<K: Deref, G: Deref<Target = NetworkGraph<L>>, L: Deref + Clone>(
 	kv_store: K, network_graph: G, logger: L,
 ) -> Result<ProbabilisticScorer<G, L>, std::io::Error>
 where
@@ -117,15 +118,16 @@ where
 {
 	let params = ProbabilisticScoringParameters::default();
 	let mut reader = kv_store.read(SCORER_PERSISTENCE_NAMESPACE, SCORER_PERSISTENCE_KEY)?;
-	let args = (params, network_graph, logger);
-	let scorer = ProbabilisticScorer::read(&mut reader, args).map_err(|_| {
+	let args = (params, network_graph, logger.clone());
+	let scorer = ProbabilisticScorer::read(&mut reader, args).map_err(|e| {
+		log_error!(logger, "Failed to deserialize scorer: {}", e);
 		std::io::Error::new(std::io::ErrorKind::InvalidData, "Failed to deserialize Scorer")
 	})?;
 	Ok(scorer)
 }
 
 /// Read previously persisted events from the store.
-pub(crate) fn read_event_queue<K: Deref, L: Deref>(
+pub(crate) fn read_event_queue<K: Deref, L: Deref + Clone>(
 	kv_store: K, logger: L,
 ) -> Result<EventQueue<K, L>, std::io::Error>
 where
@@ -134,53 +136,63 @@ where
 {
 	let mut reader =
 		kv_store.read(EVENT_QUEUE_PERSISTENCE_NAMESPACE, EVENT_QUEUE_PERSISTENCE_KEY)?;
-	let event_queue = EventQueue::read(&mut reader, (kv_store, logger)).map_err(|_| {
+	let event_queue = EventQueue::read(&mut reader, (kv_store, logger.clone())).map_err(|e| {
+		log_error!(logger, "Failed to deserialize event queue: {}", e);
 		std::io::Error::new(std::io::ErrorKind::InvalidData, "Failed to deserialize EventQueue")
 	})?;
 	Ok(event_queue)
 }
 
 /// Read previously persisted peer info from the store.
-pub(crate) fn read_peer_info<K: Deref, L: Deref>(
+pub(crate) fn read_peer_info<K: Deref, L: Deref + Clone>(
 	kv_store: K, logger: L,
 ) -> Result<PeerStore<K, L>, std::io::Error>
 where
 	K::Target: KVStore,
 	L::Target: Logger,
 {
 	let mut reader = kv_store.read(PEER_INFO_PERSISTENCE_NAMESPACE, PEER_INFO_PERSISTENCE_KEY)?;
-	let peer_info = PeerStore::read(&mut reader, (kv_store, logger)).map_err(|_| {
+	let peer_info = PeerStore::read(&mut reader, (kv_store, logger.clone())).map_err(|e| {
+		log_error!(logger, "Failed to deserialize peer store: {}", e);
 		std::io::Error::new(std::io::ErrorKind::InvalidData, "Failed to deserialize PeerStore")
 	})?;
 	Ok(peer_info)
 }
 
 /// Read previously persisted payments information from the store.
-pub(crate) fn read_payments<K: Deref>(kv_store: K) -> Result<Vec<PaymentDetails>, std::io::Error>
+pub(crate) fn read_payments<K: Deref, L: Deref>(
+	kv_store: K, logger: L,
+) -> Result<Vec<PaymentDetails>, std::io::Error>
 where
 	K::Target: KVStore,
+	L::Target: Logger,
 {
 	let mut res = Vec::new();
 
 	for stored_key in kv_store.list(PAYMENT_INFO_PERSISTENCE_NAMESPACE)? {
 		let payment = PaymentDetails::read(
 			&mut kv_store.read(PAYMENT_INFO_PERSISTENCE_NAMESPACE, &stored_key)?,
 		)
-		.map_err(|_| {
+		.map_err(|e| {
+			log_error!(logger, "Failed to deserialize Payment: {}", e);
 			std::io::Error::new(std::io::ErrorKind::InvalidData, "Failed to deserialize Payment")
 		})?;
 		res.push(payment);
 	}
 	Ok(res)
 }
 
-pub(crate) fn read_latest_rgs_sync_timestamp<K: Deref>(kv_store: K) -> Result<u32, std::io::Error>
+pub(crate) fn read_latest_rgs_sync_timestamp<K: Deref, L: Deref>(
+	kv_store: K, logger: L,
+) -> Result<u32, std::io::Error>
 where
 	K::Target: KVStore,
+	L::Target: Logger,
 {
 	let mut reader =
 		kv_store.read(LATEST_RGS_SYNC_TIMESTAMP_NAMESPACE, LATEST_RGS_SYNC_TIMESTAMP_KEY)?;
-	u32::read(&mut reader).map_err(|_| {
+	u32::read(&mut reader).map_err(|e| {
+		log_error!(logger, "Failed to deserialize latest RGS sync timestamp: {}", e);
 		std::io::Error::new(
 			std::io::ErrorKind::InvalidData,
 			"Failed to deserialize latest RGS sync timestamp",
@@ -229,18 +241,24 @@ where
 	})
 }
 
-pub(crate) fn read_latest_node_ann_bcast_timestamp<K: Deref>(
-	kv_store: K,
+pub(crate) fn read_latest_node_ann_bcast_timestamp<K: Deref, L: Deref>(
+	kv_store: K, logger: L,
 ) -> Result<u64, std::io::Error>
 where
 	K::Target: KVStore,
+	L::Target: Logger,
 {
 	let mut reader = kv_store
 		.read(LATEST_NODE_ANN_BCAST_TIMSTAMP_NAMESPACE, LATEST_NODE_ANN_BCAST_TIMSTAMP_KEY)?;
-	u64::read(&mut reader).map_err(|_| {
+	u64::read(&mut reader).map_err(|e| {
+		log_error!(
+			logger,
+			"Failed to deserialize latest node announcement broadcast timestamp: {}",
+			e
+		);
 		std::io::Error::new(
 			std::io::ErrorKind::InvalidData,
-			"Failed to deserialize latest node announcment broadcast timestamp",
+			"Failed to deserialize latest node announcement broadcast timestamp",
 		)
 	})
 }

src/lib.rs

@@ -423,7 +423,6 @@ impl Builder {
 					if e.kind() == std::io::ErrorKind::NotFound {
 						Arc::new(NetworkGraph::new(config.network, Arc::clone(&logger)))
 					} else {
-						log_error!(logger, "Failed to read network graph: {}", e.to_string());
 						panic!("Failed to read network graph: {}", e.to_string());
 					}
 				}
@@ -444,7 +443,6 @@ impl Builder {
 						Arc::clone(&logger),
 					)))
 				} else {
-					log_error!(logger, "Failed to read scorer: {}", e.to_string());
 					panic!("Failed to read scorer: {}", e.to_string());
 				}
 			}
@@ -562,8 +560,11 @@ impl Builder {
 				p2p_source
 			}
 			GossipSourceConfig::RapidGossipSync(rgs_server) => {
-				let latest_sync_timestamp =
-					io::utils::read_latest_rgs_sync_timestamp(Arc::clone(&kv_store)).unwrap_or(0);
+				let latest_sync_timestamp = io::utils::read_latest_rgs_sync_timestamp(
+					Arc::clone(&kv_store),
+					Arc::clone(&logger),
+				)
+				.unwrap_or(0);
 				Arc::new(GossipSource::new_rgs(
 					rgs_server.clone(),
 					latest_sync_timestamp,
@@ -601,15 +602,17 @@ impl Builder {
 		));
 
 		// Init payment info storage
-		let payment_store = match io::utils::read_payments(Arc::clone(&kv_store)) {
-			Ok(payments) => {
-				Arc::new(PaymentStore::new(payments, Arc::clone(&kv_store), Arc::clone(&logger)))
-			}
-			Err(e) => {
-				log_error!(logger, "Failed to read payment information: {}", e.to_string());
-				panic!("Failed to read payment information: {}", e.to_string());
-			}
-		};
+		let payment_store =
+			match io::utils::read_payments(Arc::clone(&kv_store), Arc::clone(&logger)) {
+				Ok(payments) => Arc::new(PaymentStore::new(
+					payments,
+					Arc::clone(&kv_store),
+					Arc::clone(&logger),
+				)),
+				Err(e) => {
+					panic!("Failed to read payment information: {}", e.to_string());
+				}
+			};
 
 		let event_queue =
 			match io::utils::read_event_queue(Arc::clone(&kv_store), Arc::clone(&logger)) {
@@ -618,7 +621,6 @@ impl Builder {
 					if e.kind() == std::io::ErrorKind::NotFound {
 						Arc::new(EventQueue::new(Arc::clone(&kv_store), Arc::clone(&logger)))
 					} else {
-						log_error!(logger, "Failed to read event queue: {}", e.to_string());
 						panic!("Failed to read event queue: {}", e.to_string());
 					}
 				}
@@ -631,7 +633,6 @@ impl Builder {
 				if e.kind() == std::io::ErrorKind::NotFound {
 					Arc::new(PeerStore::new(Arc::clone(&kv_store), Arc::clone(&logger)))
 				} else {
-					log_error!(logger, "Failed to read peer store: {}", e.to_string());
 					panic!("Failed to read peer store: {}", e.to_string());
 				}
 			}
@@ -700,6 +701,8 @@ impl Node {
 			return Err(Error::AlreadyRunning);
 		}
 
+		log_info!(self.logger, "Starting up LDK Node...");
+
 		let runtime = tokio::runtime::Builder::new_multi_thread().enable_all().build().unwrap();
 
 		let event_handler = Arc::new(EventHandler::new(
@@ -922,7 +925,7 @@ impl Node {
 							return;
 						}
 						_ = interval.tick() => {
-							let skip_broadcast = match io::utils::read_latest_node_ann_bcast_timestamp(Arc::clone(&bcast_store)) {
+							let skip_broadcast = match io::utils::read_latest_node_ann_bcast_timestamp(Arc::clone(&bcast_store), Arc::clone(&bcast_logger)) {
 								Ok(latest_bcast_time_secs) => {
 									// Skip if the time hasn't elapsed yet.
 									let next_bcast_unix_time = SystemTime::UNIX_EPOCH + Duration::from_secs(latest_bcast_time_secs) + NODE_ANN_BCAST_INTERVAL;
@@ -1002,6 +1005,8 @@ impl Node {
 		});
 
 		*runtime_lock = Some(runtime);
+
+		log_info!(self.logger, "Startup complete.");
 		Ok(())
 	}
 
@@ -1010,6 +1015,9 @@ impl Node {
 	/// After this returns most API methods will return [`Error::NotRunning`].
 	pub fn stop(&self) -> Result<(), Error> {
 		let runtime = self.runtime.write().unwrap().take().ok_or(Error::NotRunning)?;
+
+		log_info!(self.logger, "Shutting down LDK Node...");
+
 		// Stop the runtime.
 		match self.stop_sender.send(()) {
 			Ok(_) => (),
@@ -1027,6 +1035,8 @@ impl Node {
 		self.peer_manager.disconnect_all_peers();
 
 		runtime.shutdown_timeout(Duration::from_secs(10));
+
+		log_info!(self.logger, "Shutdown complete.");
 		Ok(())
 	}