DBG: Add LDK lightningdevkit#2064 and tracing logs

Author: MaxFangX

lightning/Cargo.toml

@@ -45,6 +45,7 @@ hashbrown = { version = "0.8", optional = true }
 hex = { version = "0.4", optional = true }
 regex = { version = "1.5.6", optional = true }
 backtrace = { version = "0.3", optional = true }
+tracing = "0.1"
 
 core2 = { version = "0.3.0", optional = true, default-features = false }
 

lightning/src/util/wakers.rs

@@ -21,6 +21,7 @@ use crate::prelude::*;
 
 #[cfg(any(test, feature = "std"))]
 use std::time::{Duration, Instant};
+use tracing::info;
 
 use core::future::Future as StdFuture;
 use core::task::{Context, Poll};
@@ -55,10 +56,14 @@ impl Notifier {
 		}
 	}
 
+    #[tracing::instrument(skip_all)]
 	fn propagate_future_state_to_notify_flag(&self) -> MutexGuard<(bool, Option<Arc<Mutex<FutureState>>>)> {
+        info!("Notifier::propagate_future_state_to_notify_flag called");
 		let mut lock = self.notify_pending.lock().unwrap();
 		if let Some(existing_state) = &lock.1 {
+            info!("Got inside if let Some(existing_state)");
 			if existing_state.lock().unwrap().callbacks_made {
+                info!("Got inside if existing_state.lock().unwrap().callbacks_made");
 				// If the existing `FutureState` has completed and actually made callbacks,
 				// consider the notification flag to have been cleared and reset the future state.
 				lock.1.take();
@@ -102,22 +107,34 @@ impl Notifier {
 	}
 
 	/// Wake waiters, tracking that wake needs to occur even if there are currently no waiters.
+    #[tracing::instrument(skip_all)]
 	pub(crate) fn notify(&self) {
+        info!("Notifier::notify called");
 		let mut lock = self.notify_pending.lock().unwrap();
 		if let Some(future_state) = &lock.1 {
-			future_state.lock().unwrap().complete();
+            info!("Got inside if let Some");
+			if future_state.lock().unwrap().complete() {
+                info!("Got inside if future_state.lock().unwrap().complete()");
+				lock.1 = None;
+				return;
+			}
 		}
+        info!("setting notified and waking condvar");
 		lock.0 = true;
 		mem::drop(lock);
 		self.condvar.notify_all();
 	}
 
 	/// Gets a [`Future`] that will get woken up with any waiters
+    #[tracing::instrument(skip_all)]
 	pub(crate) fn get_future(&self) -> Future {
+        info!("Notifier::get_future called");
 		let mut lock = self.propagate_future_state_to_notify_flag();
 		if let Some(existing_state) = &lock.1 {
+            info!("returning existing future");
 			Future { state: Arc::clone(&existing_state) }
 		} else {
+            info!("returning new future, pre-completed: {}", lock.0);
 			let state = Arc::new(Mutex::new(FutureState {
 				callbacks: Vec::new(),
 				complete: lock.0,
@@ -161,12 +178,16 @@ pub(crate) struct FutureState {
 }
 
 impl FutureState {
-	fn complete(&mut self) {
+    #[tracing::instrument(skip_all)]
+	fn complete(&mut self) -> bool {
+        info!("FutureState::complete called");
+        info!("future completing, calling back... {} callbacks", self.callbacks.len());
 		for (counts_as_call, callback) in self.callbacks.drain(..) {
 			callback.call();
 			self.callbacks_made |= counts_as_call;
 		}
 		self.complete = true;
+		self.callbacks_made
 	}
 }
 
@@ -180,7 +201,10 @@ impl Future {
 	/// completed, the callback will be called immediately.
 	///
 	/// (C-not exported) use the bindings-only `register_callback_fn` instead
+    #[tracing::instrument(skip_all)]
 	pub fn register_callback(&self, callback: Box<dyn FutureCallback>) {
+        info!("Future::register_callback called");
+        info!("got callback registration");
 		let mut state = self.state.lock().unwrap();
 		if state.complete {
 			state.callbacks_made = true;
@@ -205,19 +229,28 @@ impl Future {
 use core::task::Waker;
 struct StdWaker(pub Waker);
 impl FutureCallback for StdWaker {
-	fn call(&self) { self.0.wake_by_ref() }
+    #[tracing::instrument(skip_all)]
+	fn call(&self) {
+        info!("StdWaker::call called");
+        info!("futurecallback complete, waking poll'd context");
+		self.0.wake_by_ref()
+	}
 }
 
 /// (C-not exported) as Rust Futures aren't usable in language bindings.
 impl<'a> StdFuture for Future {
 	type Output = ();
 
+    #[tracing::instrument(skip_all)]
 	fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
+        info!("Future::poll called");
 		let mut state = self.state.lock().unwrap();
 		if state.complete {
+            info!("poll'ing future complete! marking called-back");
 			state.callbacks_made = true;
 			Poll::Ready(())
 		} else {
+            info!("poll'ing future not complete, tracking context to wake it later");
 			let waker = cx.waker().clone();
 			state.callbacks.push((false, Box::new(StdWaker(waker))));
 			Poll::Pending
@@ -469,4 +502,63 @@ mod tests {
 		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Ready(()));
 		assert!(!notifier.wait_timeout(Duration::from_millis(1)));
 	}
+
+	#[test]
+	fn test_poll_post_notify_completes() {
+		// Tests that if we have a future state that has completed, and we haven't yet requested a
+		// new future, if we get a notify prior to requesting that second future it is generated
+		// pre-completed.
+		let notifier = Notifier::new();
+
+		notifier.notify();
+		let mut future = notifier.get_future();
+		let (woken, waker) = create_waker();
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Ready(()));
+		assert!(!woken.load(Ordering::SeqCst));
+
+		notifier.notify();
+		let mut future = notifier.get_future();
+		let (woken, waker) = create_waker();
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Ready(()));
+		assert!(!woken.load(Ordering::SeqCst));
+
+		let mut future = notifier.get_future();
+		let (woken, waker) = create_waker();
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Pending);
+		assert!(!woken.load(Ordering::SeqCst));
+
+		notifier.notify();
+		assert!(woken.load(Ordering::SeqCst));
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Ready(()));
+	}
+
+	#[test]
+	fn test_poll_post_notify_completes_initial_notified() {
+		// Identical to the previous test, but the first future completes via a wake rather than an
+		// immediate `Poll::Ready`.
+		let notifier = Notifier::new();
+
+		let mut future = notifier.get_future();
+		let (woken, waker) = create_waker();
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Pending);
+
+		notifier.notify();
+		assert!(woken.load(Ordering::SeqCst));
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Ready(()));
+
+		notifier.notify();
+		let mut future = notifier.get_future();
+		let (woken, waker) = create_waker();
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Ready(()));
+		assert!(!woken.load(Ordering::SeqCst));
+
+		let mut future = notifier.get_future();
+		let (woken, waker) = create_waker();
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Pending);
+		assert!(!woken.load(Ordering::SeqCst));
+
+		notifier.notify();
+		assert!(woken.load(Ordering::SeqCst));
+		assert_eq!(Pin::new(&mut future).poll(&mut Context::from_waker(&waker)), Poll::Ready(()));
+	}
 }