tests: improve patchbay test setup (#4078)

## Description

* ignore tests currently known as being flaky
* no longer retry failed tests. the reruns would write into the same
testdir, making debugging the failures very hard especially if the retry
succeeded
* improve logging in case of failures

---------

Co-authored-by: Friedel Ziegelmayer <me@dignifiedquire.com>

Author: Frando

.config/nextest.toml

@@ -20,7 +20,6 @@ slow-timeout = { period = "10s", terminate-after = 3 }
 
 [profile.patchbay]
 fail-fast = false
-retries = 1
 test-threads = 4
 default-filter = 'binary(patchbay)'
 slow-timeout = { period = "30s", terminate-after = 4 }

iroh/tests/patchbay.rs

@@ -74,7 +74,10 @@ async fn holepunch_simple() -> Result {
         .client(client, async move |_dev, _ep, conn| {
             let mut paths = conn.paths();
             assert!(paths.selected().is_relay(), "connection started relayed");
-            paths.wait_ip(timeout).await?;
+            paths
+                .wait_ip(timeout)
+                .await
+                .context("holepunch to direct")?;
             info!("connection became direct");
             Ok(())
         })
@@ -133,7 +136,10 @@ async fn switch_uplink_v4() -> Result {
             assert!(paths.selected().is_relay(), "connection started relayed");
 
             // Wait for conn to become direct.
-            paths.wait_ip(timeout).await.context("become direct")?;
+            paths
+                .wait_ip(timeout)
+                .await
+                .context("holepunch to direct")?;
 
             // Wait a little more and then switch wifis.
             tokio::time::sleep(Duration::from_secs(1)).await;
@@ -225,17 +231,24 @@ async fn switch_uplink_v6() -> Result {
             assert!(paths.selected().is_relay(), "connection started relayed");
 
             // Wait for conn to become direct.
-            paths.wait_ip(timeout).await.context("become direct")?;
+            paths
+                .wait_ip(timeout)
+                .await
+                .context("holepunch to direct")?;
 
-            ping_open(&conn, timeout).await.context("ping_open 1")?;
+            ping_open(&conn, timeout)
+                .await
+                .context("ping before switch")?;
 
-            info!("switch IP uplink");
+            info!("switch IP uplink to v6");
             dev.replug_iface("eth0", mobile.id()).await?;
 
             // We don't assert any path changes here, because the remote stays identical,
             // and PathInfo does not contain info on local addrs. Instead, the remote
             // only accepts our ping after the path changed.
-            ping_open(&conn, timeout).await.context("ping_open 2")?;
+            ping_open(&conn, timeout)
+                .await
+                .context("ping after v6 switch")?;
             Ok(())
         })
         .run()
@@ -253,6 +266,7 @@ async fn switch_uplink_v6() -> Result {
 /// faster LAN address. A ping verifies the new path works.
 #[tokio::test]
 #[traced_test]
+#[ignore = "sometimes is flaky (does not become direct after the link_up)"]
 async fn change_ifaces() -> Result {
     let (lab, relay_map, _relay_guard, guard) = lab_with_relay(testdir!()).await?;
     let nat1 = lab.add_router("nat1").nat(Nat::Home).build().await?;
@@ -275,7 +289,7 @@ async fn change_ifaces() -> Result {
         .await?;
     client.link_down("eth1").await?;
 
-    let timeout = Duration::from_secs(10);
+    let timeout = Duration::from_secs(15);
     Pair::new(relay_map)
         .server(server, async move |_dev, _ep, conn| {
             ping_accept(&conn, timeout).await.context("ping_accept")?;
@@ -478,14 +492,19 @@ async fn run_degrade_level(impaired_side: Side, level: usize) -> Result<TestGuar
         timeout * 2,
         Pair::new(relay_map)
             .server(server, async move |_dev, _ep, conn| {
-                ping_accept(&conn, timeout).await?;
+                ping_accept(&conn, timeout).await.context("ping_accept")?;
                 conn.closed().await;
                 Ok(())
             })
             .client(client, async move |_dev, _ep, conn| {
                 let mut paths = conn.paths();
-                paths.wait_ip(timeout).await?;
-                ping_open(&conn, timeout).await?;
+                paths
+                    .wait_ip(timeout)
+                    .await
+                    .context("holepunch to direct")?;
+                info!("direct path established, sending ping");
+                ping_open(&conn, timeout).await.context("ping_open")?;
+                info!("ping complete");
                 Ok(())
             })
             .run(),
@@ -545,6 +564,7 @@ async fn degrade_server_2_bad() -> Result {
 
 #[tokio::test]
 #[traced_test]
+#[ignore = "not yet passing reliably"]
 async fn degrade_server_3_terrible() -> Result {
     run_degrade_level(Side::Server, 3).await?.ok();
     Ok(())
@@ -589,6 +609,7 @@ async fn degrade_client_2_bad() -> Result {
 
 #[tokio::test]
 #[traced_test]
+#[ignore = "not yet passing reliably"]
 async fn degrade_client_3_terrible() -> Result {
     run_degrade_level(Side::Client, 3).await?.ok();
     Ok(())

iroh/tests/patchbay/util.rs

@@ -57,6 +57,7 @@ async fn spawn_relay(lab: &Lab) -> Result<(RelayMap, AbortOnDropHandle<()>)> {
     let relay_v6 = dev_relay.ip6().expect("relay has IPv6");
     lab.dns_entry("relay.test", relay_v4.into())?;
     lab.dns_entry("relay.test", relay_v6.into())?;
+    info!(%relay_v4, %relay_v6, "DNS entries for relay.test registered");
 
     let (relay_map_tx, relay_map_rx) = oneshot::channel();
     let task_relay = dev_relay.spawn(async move |_ctx| {
@@ -147,13 +148,16 @@ impl Pair {
         let server_task = server_device.spawn(|dev| {
             let barrier = barrier2;
             async move {
-                let endpoint = endpoint_builder(&dev, relay_map2).bind().await?;
+                let endpoint = endpoint_builder(&dev, relay_map2).bind().await
+                    .context("server endpoint bind")?;
                 info!(id=%endpoint.id().fmt_short(), bound_sockets=?endpoint.bound_sockets(), "server endpoint bound");
                 endpoint.online().await;
                 info!("endpoint online");
                 // Send address to client task. Make it a relay-only address, like in the default address lookup services.
                 addr_tx.send(addr_relay_only(endpoint.addr())).unwrap();
-                let conn = endpoint.accept().await.unwrap().accept().anyerr()?.await?;
+                let incoming = endpoint.accept().await.context("server accept incoming")?;
+                let conn = incoming.accept().anyerr()?.await
+                    .context("server accept handshake")?;
                 info!(remote=%conn.remote_id().fmt_short(), "accepted, executing run function");
                 watch_selected_path(&conn);
                 let res = server_run(dev.clone(), endpoint.clone(), conn).await;
@@ -172,11 +176,13 @@ impl Pair {
         })?;
         let client_task = client_device.spawn(move |dev| {
             async move {
-                let endpoint = endpoint_builder(&dev, self.relay_map).bind().await?;
+                let endpoint = endpoint_builder(&dev, self.relay_map).bind().await
+                    .context("client endpoint bind")?;
                 info!(id=%endpoint.id().fmt_short(), bound_sockets=?endpoint.bound_sockets(), "client endpoint bound");
                 let addr = addr_rx.await.std_context("server did not send its address")?;
                 info!(?addr, "connecting to server");
-                let conn = endpoint.connect(addr, TEST_ALPN).await?;
+                let conn = endpoint.connect(addr, TEST_ALPN).await
+                    .context("client connect")?;
                 watch_selected_path(&conn);
                 info!(remote=%conn.remote_id().fmt_short(), "connected, executing run function");
                 let res = client_run(dev.clone(), endpoint.clone(), conn).await;
@@ -256,12 +262,16 @@ pub trait PathWatcherExt {
 
     /// Wait until the selected path is a direct (IP) path.
     async fn wait_ip(&mut self, timeout: Duration) -> Result<PathInfo> {
-        self.wait_selected(timeout, PathInfo::is_ip).await
+        self.wait_selected(timeout, PathInfo::is_ip)
+            .await
+            .context("wait_ip")
     }
 
     /// Wait until the selected path is a relay path.
     async fn wait_relay(&mut self, timeout: Duration) -> Result<PathInfo> {
-        self.wait_selected(timeout, PathInfo::is_relay).await
+        self.wait_selected(timeout, PathInfo::is_relay)
+            .await
+            .context("wait_relay")
     }
 }
 
@@ -289,36 +299,45 @@ impl PathWatcherExt for PathWatcher {
             }
         })
         .await
-        .anyerr()?
+        .std_context("wait_selected timed out")?
     }
 }
 
 /// Opens a bidi stream, sends 8 bytes of data, and waits to receive the same data back.
 pub async fn ping_open(conn: &Connection, timeout: Duration) -> Result {
     tokio::time::timeout(timeout, async {
         let data: [u8; 8] = rand::random();
+        debug!("open_bi");
         let (mut send, mut recv) = conn.open_bi().await.anyerr()?;
+        debug!("write_all");
         send.write_all(&data).await.anyerr()?;
         send.finish().anyerr()?;
+        debug!("read_to_end");
         let r = recv.read_to_end(8).await.anyerr()?;
         ensure_any!(r == data, "reply matches");
+        debug!("done");
         Ok(())
     })
     .await
-    .anyerr()?
+    .std_context("ping_open timed out")?
 }
 
 /// Accepts a bidi stream, reads 8 bytes of data, and sends the same data back.
 pub async fn ping_accept(conn: &Connection, timeout: Duration) -> Result {
     tokio::time::timeout(timeout, async {
+        debug!("accept_bi");
         let (mut send, mut recv) = conn.accept_bi().await.anyerr()?;
+        debug!("read_to_end");
         let data = recv.read_to_end(8).await.anyerr()?;
+        debug!("write_all");
         send.write_all(&data).await.anyerr()?;
         send.finish().anyerr()?;
+        debug!("done");
         Ok(())
     })
+    .instrument(error_span!("ping_accept"))
     .await
-    .anyerr()?
+    .std_context("ping_accept timed out")?
 }
 
 fn watch_selected_path(conn: &Connection) {