test: add nice debug traces to assertions (#34)

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

src/macros.rs

@@ -17,6 +17,7 @@ macro_rules! test_println {
         }
     }
 }
+
 macro_rules! test_dbg {
     ($e:expr) => {
         match $e {
@@ -29,6 +30,42 @@ macro_rules! test_dbg {
     };
 }
 
+#[cfg(test)]
+macro_rules! assert_dbg {
+    ($e:expr) => {
+        assert_dbg!(@ $e, "")
+    };
+    ($e:expr, $($msg:tt)+) => {
+        assert_dbg!(@ $e, " ({})", format_args!($($msg)+))
+    };
+    (@$e:expr, $($msg:tt)+) => {
+        {
+            #[cfg(any(test, all(thingbuf_trace, feature = "std")))]
+            test_println!("ASSERT: {}{}", stringify!($e), format_args!($($msg)*));
+            assert!($e, $($msg)*);
+            test_println!("-> ok");
+        }
+    }
+}
+
+#[cfg(test)]
+macro_rules! assert_eq_dbg {
+    ($a:expr, $b:expr) => {
+        assert_eq_dbg!(@ $a, $b, "")
+    };
+    ($a:expr, $b:expr, $($msg:tt)+) => {
+       assert_eq_dbg!(@ $a, $b, " ({})", format_args!($($msg)+))
+    };
+    (@ $a:expr, $b:expr, $($msg:tt)+) => {
+        {
+            #[cfg(any(test, all(thingbuf_trace, feature = "std")))]
+            test_println!("ASSERT: {} == {}{}", stringify!($a), stringify!($b), format_args!($($msg)*));
+            assert_eq!($a, $b, $($msg)*);
+            test_println!("-> ok");
+        }
+    }
+}
+
 macro_rules! feature {
     (
         #![$meta:meta]

src/mpsc/tests/mpsc_async.rs

@@ -27,7 +27,7 @@ fn mpsc_try_send_recv() {
         });
 
         vals.sort_unstable();
-        assert_eq!(vals, vec![1, 2, 3]);
+        assert_eq_dbg!(vals, vec![1, 2, 3]);
 
         p1.join().unwrap();
         p2.join().unwrap();
@@ -63,7 +63,7 @@ fn rx_closes() {
                 let n = rx.recv().await;
 
                 test_println!("recv {:?}\n", n);
-                assert_eq!(n, Some(i));
+                assert_eq_dbg!(n, Some(i));
             }
         });
 
@@ -85,7 +85,7 @@ fn rx_close_unconsumed_spsc() {
                 // recieve one message
                 let msg = rx.recv().await;
                 test_println!("recv {:?}", msg);
-                assert!(msg.is_some());
+                assert_dbg!(msg.is_some());
                 // drop the receiver...
             })
         });
@@ -125,7 +125,7 @@ fn rx_close_unconsumed_mpsc() {
                 // recieve one message
                 let msg = rx.recv().await;
                 test_println!("recv {:?}", msg);
-                assert!(msg.is_some());
+                assert_dbg!(msg.is_some());
                 // drop the receiver...
             })
         });
@@ -148,7 +148,7 @@ fn spsc_recv_then_send() {
         let (tx, rx) = channel::<i32>(4);
         let consumer = thread::spawn(move || {
             future::block_on(async move {
-                assert_eq!(rx.recv().await.unwrap(), 10);
+                assert_eq_dbg!(rx.recv().await.unwrap(), 10);
             })
         });
 
@@ -167,7 +167,7 @@ fn spsc_recv_then_close() {
 
         future::block_on(async move {
             let recv = rx.recv().await;
-            assert_eq!(recv, None);
+            assert_eq_dbg!(recv, None);
         });
 
         producer.join().unwrap();
@@ -180,9 +180,9 @@ fn spsc_recv_then_send_then_close() {
         let (tx, rx) = channel::<i32>(2);
         let consumer = thread::spawn(move || {
             future::block_on(async move {
-                assert_eq!(rx.recv().await.unwrap(), 10);
-                assert_eq!(rx.recv().await.unwrap(), 20);
-                assert_eq!(rx.recv().await, None);
+                assert_eq_dbg!(rx.recv().await.unwrap(), 10);
+                assert_eq_dbg!(rx.recv().await.unwrap(), 20);
+                assert_eq_dbg!(rx.recv().await, None);
             })
         });
 
@@ -201,9 +201,9 @@ fn spsc_send_recv_in_order_no_wrap() {
         let consumer = thread::spawn(move || {
             future::block_on(async move {
                 for i in 1..=N_SENDS {
-                    assert_eq!(rx.recv().await, Some(i));
+                    assert_eq_dbg!(rx.recv().await, Some(i));
                 }
-                assert_eq!(rx.recv().await, None);
+                assert_eq_dbg!(rx.recv().await, None);
             })
         });
         future::block_on(async move {
@@ -223,9 +223,9 @@ fn spsc_send_recv_in_order_wrap() {
         let consumer = thread::spawn(move || {
             future::block_on(async move {
                 for i in 1..=N_SENDS {
-                    assert_eq!(rx.recv().await, Some(i));
+                    assert_eq_dbg!(rx.recv().await, Some(i));
                 }
-                assert_eq!(rx.recv().await, None);
+                assert_eq_dbg!(rx.recv().await, None);
             })
         });
         future::block_on(async move {
@@ -257,14 +257,14 @@ fn mpsc_send_recv_wrap() {
         producer1.join().expect("producer 1 panicked");
         producer2.join().expect("producer 2 panicked");
 
-        assert_eq!(results.len(), 2);
-        assert!(
+        assert_eq_dbg!(results.len(), 2);
+        assert_dbg!(
             results.contains(&10),
             "missing value from producer 1; results={:?}",
             results
         );
 
-        assert!(
+        assert_dbg!(
             results.contains(&20),
             "missing value from producer 2; results={:?}",
             results
@@ -291,14 +291,14 @@ fn mpsc_send_recv_no_wrap() {
         producer1.join().expect("producer 1 panicked");
         producer2.join().expect("producer 2 panicked");
 
-        assert_eq!(results.len(), 2);
-        assert!(
+        assert_eq_dbg!(results.len(), 2);
+        assert_dbg!(
             results.contains(&10),
             "missing value from producer 1; results={:?}",
             results
         );
 
-        assert!(
+        assert_dbg!(
             results.contains(&20),
             "missing value from producer 2; results={:?}",
             results
@@ -322,7 +322,7 @@ fn tx_close_wakes() {
         let (tx, rx) = channel::<i32>(2);
         let consumer = thread::spawn(move || {
             future::block_on(async move {
-                assert_eq!(rx.recv().await, None);
+                assert_eq_dbg!(rx.recv().await, None);
             })
         });
         drop(tx);
@@ -345,7 +345,7 @@ fn tx_close_drains_queue() {
 
         future::block_on(async move {
             for i in 0..LEN {
-                assert_eq!(rx.recv().await, Some(i))
+                assert_eq_dbg!(rx.recv().await, Some(i))
             }
         });
 

src/mpsc/tests/mpsc_sync.rs

@@ -33,7 +33,7 @@ fn mpsc_try_send_recv() {
         }
 
         vals.sort_unstable();
-        assert_eq!(vals, vec![1, 2, 3]);
+        assert_eq_dbg!(vals, vec![1, 2, 3]);
 
         p1.join().unwrap();
         p2.join().unwrap();
@@ -67,7 +67,7 @@ fn rx_closes() {
             let n = rx.recv();
 
             test_println!("recv {:?}\n", n);
-            assert_eq!(n, Some(i));
+            assert_eq_dbg!(n, Some(i));
         }
         drop(rx);
 
@@ -88,7 +88,7 @@ fn rx_close_unconsumed_spsc() {
             // recieve one message
             let msg = rx.recv();
             test_println!("recv {:?}", msg);
-            assert!(msg.is_some());
+            assert_dbg!(msg.is_some());
             // drop the receiver...
         });
 
@@ -127,7 +127,7 @@ fn rx_close_unconsumed_mpsc() {
             // recieve one message
             let msg = rx.recv();
             test_println!("recv {:?}", msg);
-            assert!(msg.is_some());
+            assert_dbg!(msg.is_some());
             // drop the receiver...
         });
 
@@ -145,7 +145,7 @@ fn spsc_recv_then_try_send() {
     loom::model(|| {
         let (tx, rx) = sync::channel::<i32>(4);
         let consumer = thread::spawn(move || {
-            assert_eq!(rx.recv().unwrap(), 10);
+            assert_eq_dbg!(rx.recv().unwrap(), 10);
         });
 
         tx.try_send(10).unwrap();
@@ -161,7 +161,7 @@ fn spsc_recv_then_close() {
             drop(tx);
         });
 
-        assert_eq!(rx.recv(), None);
+        assert_eq_dbg!(rx.recv(), None);
 
         producer.join().unwrap();
     });
@@ -172,9 +172,9 @@ fn spsc_recv_then_try_send_then_close() {
     loom::model(|| {
         let (tx, rx) = sync::channel::<i32>(2);
         let consumer = thread::spawn(move || {
-            assert_eq!(rx.recv().unwrap(), 10);
-            assert_eq!(rx.recv().unwrap(), 20);
-            assert_eq!(rx.recv(), None);
+            assert_eq_dbg!(rx.recv().unwrap(), 10);
+            assert_eq_dbg!(rx.recv().unwrap(), 20);
+            assert_eq_dbg!(rx.recv(), None);
         });
 
         tx.try_send(10).unwrap();
@@ -209,14 +209,14 @@ fn mpsc_send_recv_wrap() {
         producer1.join().expect("producer 1 panicked");
         producer2.join().expect("producer 2 panicked");
 
-        assert_eq!(results.len(), 2);
-        assert!(
+        assert_eq_dbg!(results.len(), 2);
+        assert_dbg!(
             results.contains(&10),
             "missing value from producer 1; results={:?}",
             results
         );
 
-        assert!(
+        assert_dbg!(
             results.contains(&20),
             "missing value from producer 2; results={:?}",
             results
@@ -240,14 +240,14 @@ fn mpsc_send_recv_no_wrap() {
         producer1.join().expect("producer 1 panicked");
         producer2.join().expect("producer 2 panicked");
 
-        assert_eq!(results.len(), 2);
-        assert!(
+        assert_eq_dbg!(results.len(), 2);
+        assert_dbg!(
             results.contains(&10),
             "missing value from producer 1; results={:?}",
             results
         );
 
-        assert!(
+        assert_dbg!(
             results.contains(&20),
             "missing value from producer 2; results={:?}",
             results
@@ -270,9 +270,9 @@ fn spsc_send_recv_in_order_no_wrap() {
         let (tx, rx) = sync::channel::<usize>(N_SENDS);
         let consumer = thread::spawn(move || {
             for i in 1..=N_SENDS {
-                assert_eq!(rx.recv(), Some(i));
+                assert_eq_dbg!(rx.recv(), Some(i));
             }
-            assert_eq!(rx.recv(), None);
+            assert_eq_dbg!(rx.recv(), None);
         });
 
         for i in 1..=N_SENDS {
@@ -299,9 +299,9 @@ fn spsc_send_recv_in_order_wrap() {
         let (tx, rx) = sync::channel::<usize>(N_SENDS / 2);
         let consumer = thread::spawn(move || {
             for i in 1..=N_SENDS {
-                assert_eq!(rx.recv(), Some(i));
+                assert_eq_dbg!(rx.recv(), Some(i));
             }
-            assert_eq!(rx.recv(), None);
+            assert_eq_dbg!(rx.recv(), None);
         });
 
         for i in 1..=N_SENDS {
@@ -317,7 +317,7 @@ fn tx_close_wakes() {
     loom::model(|| {
         let (tx, rx) = sync::channel::<i32>(2);
         let consumer = thread::spawn(move || {
-            assert_eq!(rx.recv(), None);
+            assert_eq_dbg!(rx.recv(), None);
         });
         drop(tx);
         consumer.join().unwrap();
@@ -336,7 +336,7 @@ fn tx_close_drains_queue() {
         });
 
         for i in 0..LEN {
-            assert_eq!(rx.recv(), Some(i))
+            assert_eq_dbg!(rx.recv(), Some(i))
         }
 
         producer.join().unwrap();

src/thingbuf/tests.rs

@@ -47,7 +47,7 @@ fn push_many_mpsc() {
 
         test_dbg!(&all_vals);
         for &val in T1_VALS.iter().chain(T2_VALS.iter()) {
-            assert!(all_vals.contains(&test_dbg!(val).to_string()))
+            assert_dbg!(all_vals.contains(&test_dbg!(val).to_string()))
         }
 
         assert_eq!(all_vals.len(), T1_VALS.len() + T2_VALS.len());

src/wait/queue.rs

@@ -674,29 +674,29 @@ mod tests {
         let mut waiter1 = Box::pin(Waiter::new());
         let mut waiter2 = Box::pin(Waiter::new());
 
-        assert_eq!(q.start_wait(waiter1.as_mut(), &notify1), WaitResult::Wait);
-        assert!(waiter1.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter1.as_mut(), &notify1), WaitResult::Wait);
+        assert_dbg!(waiter1.is_linked());
 
-        assert_eq!(q.start_wait(waiter2.as_mut(), &notify2), WaitResult::Wait);
-        assert!(waiter2.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter2.as_mut(), &notify2), WaitResult::Wait);
+        assert_dbg!(waiter2.is_linked());
 
-        assert!(!notify1.was_notified());
-        assert!(!notify2.was_notified());
+        assert_dbg!(!notify1.was_notified());
+        assert_dbg!(!notify2.was_notified());
 
-        assert!(q.notify());
+        assert_dbg!(q.notify());
 
-        assert!(notify1.was_notified());
-        assert!(!waiter1.is_linked());
+        assert_dbg!(notify1.was_notified());
+        assert_dbg!(!waiter1.is_linked());
 
-        assert!(!notify2.was_notified());
-        assert!(waiter2.is_linked());
+        assert_dbg!(!notify2.was_notified());
+        assert_dbg!(waiter2.is_linked());
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter2.as_mut(), &notify2),
             WaitResult::Wait
         );
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter1.as_mut(), &notify1),
             WaitResult::Notified
         );
@@ -712,29 +712,29 @@ mod tests {
         let mut waiter1 = Box::pin(Waiter::new());
         let mut waiter2 = Box::pin(Waiter::new());
 
-        assert_eq!(q.start_wait(waiter1.as_mut(), &notify1), WaitResult::Wait);
-        assert!(waiter1.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter1.as_mut(), &notify1), WaitResult::Wait);
+        assert_dbg!(waiter1.is_linked());
 
-        assert_eq!(q.start_wait(waiter2.as_mut(), &notify2), WaitResult::Wait);
-        assert!(waiter2.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter2.as_mut(), &notify2), WaitResult::Wait);
+        assert_dbg!(waiter2.is_linked());
 
-        assert!(!notify1.was_notified());
-        assert!(!notify2.was_notified());
+        assert_dbg!(!notify1.was_notified());
+        assert_dbg!(!notify2.was_notified());
 
         q.close();
 
-        assert!(notify1.was_notified());
-        assert!(!waiter1.is_linked());
+        assert_dbg!(notify1.was_notified());
+        assert_dbg!(!waiter1.is_linked());
 
-        assert!(notify2.was_notified());
-        assert!(!waiter2.is_linked());
+        assert_dbg!(notify2.was_notified());
+        assert_dbg!(!waiter2.is_linked());
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter2.as_mut(), &notify2),
             WaitResult::Closed
         );
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter1.as_mut(), &notify1),
             WaitResult::Closed
         );
@@ -752,37 +752,37 @@ mod tests {
         let mut waiter2 = Box::pin(Waiter::new());
         let mut waiter3 = Box::pin(Waiter::new());
 
-        assert_eq!(q.start_wait(waiter1.as_mut(), &notify1), WaitResult::Wait);
-        assert!(waiter1.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter1.as_mut(), &notify1), WaitResult::Wait);
+        assert_dbg!(waiter1.is_linked());
 
-        assert_eq!(q.start_wait(waiter2.as_mut(), &notify2), WaitResult::Wait);
-        assert!(waiter2.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter2.as_mut(), &notify2), WaitResult::Wait);
+        assert_dbg!(waiter2.is_linked());
 
-        assert_eq!(q.start_wait(waiter3.as_mut(), &notify3), WaitResult::Wait);
-        assert!(waiter2.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter3.as_mut(), &notify3), WaitResult::Wait);
+        assert_dbg!(waiter2.is_linked());
 
-        assert!(!notify1.was_notified());
-        assert!(!notify2.was_notified());
-        assert!(!notify3.was_notified());
+        assert_dbg!(!notify1.was_notified());
+        assert_dbg!(!notify2.was_notified());
+        assert_dbg!(!notify3.was_notified());
 
         waiter2.as_mut().remove(&q);
-        assert!(!notify2.was_notified());
+        assert_dbg!(!notify2.was_notified());
         drop(waiter2);
 
-        assert!(q.notify());
+        assert_dbg!(q.notify());
 
-        assert!(notify1.was_notified());
-        assert!(!waiter1.is_linked());
+        assert_dbg!(notify1.was_notified());
+        assert_dbg!(!waiter1.is_linked());
 
-        assert!(!notify3.was_notified());
-        assert!(waiter3.is_linked());
+        assert_dbg!(!notify3.was_notified());
+        assert_dbg!(waiter3.is_linked());
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter3.as_mut(), &notify3),
             WaitResult::Wait
         );
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter1.as_mut(), &notify1),
             WaitResult::Notified
         );
@@ -800,53 +800,53 @@ mod tests {
         let mut waiter2 = Box::pin(Waiter::new());
         let mut waiter3 = Box::pin(Waiter::new());
 
-        assert_eq!(q.start_wait(waiter1.as_mut(), &notify1), WaitResult::Wait);
-        assert!(waiter1.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter1.as_mut(), &notify1), WaitResult::Wait);
+        assert_dbg!(waiter1.is_linked());
 
-        assert_eq!(q.start_wait(waiter2.as_mut(), &notify2), WaitResult::Wait);
-        assert!(waiter2.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter2.as_mut(), &notify2), WaitResult::Wait);
+        assert_dbg!(waiter2.is_linked());
 
-        assert_eq!(q.start_wait(waiter3.as_mut(), &notify3), WaitResult::Wait);
-        assert!(waiter2.is_linked());
+        assert_eq_dbg!(q.start_wait(waiter3.as_mut(), &notify3), WaitResult::Wait);
+        assert_dbg!(waiter2.is_linked());
 
-        assert!(!notify1.was_notified());
-        assert!(!notify2.was_notified());
-        assert!(!notify3.was_notified());
+        assert_dbg!(!notify1.was_notified());
+        assert_dbg!(!notify2.was_notified());
+        assert_dbg!(!notify3.was_notified());
 
-        assert!(q.notify());
+        assert_dbg!(q.notify());
 
-        assert!(notify1.was_notified());
-        assert!(!waiter1.is_linked());
+        assert_dbg!(notify1.was_notified());
+        assert_dbg!(!waiter1.is_linked());
 
-        assert!(!notify2.was_notified());
-        assert!(waiter2.is_linked());
+        assert_dbg!(!notify2.was_notified());
+        assert_dbg!(waiter2.is_linked());
 
-        assert!(!notify3.was_notified());
-        assert!(waiter3.is_linked());
+        assert_dbg!(!notify3.was_notified());
+        assert_dbg!(waiter3.is_linked());
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter3.as_mut(), &notify3),
             WaitResult::Wait
         );
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter2.as_mut(), &notify2),
             WaitResult::Wait
         );
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter1.as_mut(), &notify1),
             WaitResult::Notified
         );
 
         waiter2.as_mut().remove(&q);
-        assert!(!notify2.was_notified());
+        assert_dbg!(!notify2.was_notified());
         drop(waiter2);
 
-        assert!(!notify3.was_notified());
-        assert!(waiter3.is_linked());
+        assert_dbg!(!notify3.was_notified());
+        assert_dbg!(waiter3.is_linked());
 
-        assert_eq!(
+        assert_eq_dbg!(
             q.continue_wait(waiter3.as_mut(), &notify3),
             WaitResult::Wait
         );