Merge #151

151: Context and logging r=TheNeikos a=matthiasbeyer

Extracted from #133 

Adds error contexts and logging to behaviour test implementations.

Co-authored-by: Matthias Beyer <mail@beyermatthias.de>

11 files changed, 74 insertions, 21 deletions

diff --git a/mqtt-tester/Cargo.toml b/mqtt-tester/Cargo.toml
index b2a1ed8..57c22a2 100644
--- a/mqtt-tester/Cargo.toml
+++ b/mqtt-tester/Cargo.toml
@@ -17,5 +17,5 @@ nom = { version = "7.1.3" }
 textwrap = "0.16.0"
 tokio = { version = "1.24", features = ["macros", "process", "rt", "rt-multi-thread", "io-util", "time"] }
 static_assertions = "1.1.0"
-tracing = "0.1"
+tracing = { version = "0.1", features = ["attributes"] }
 tracing-subscriber = { version = "0.3.11", features = ["env-filter"] }
diff --git a/mqtt-tester/src/behaviour/connack_flags_are_set_as_reserved.rs b/mqtt-tester/src/behaviour/connack_flags_are_set_as_reserved.rs
index 49012c1..7229f94 100644
--- a/mqtt-tester/src/behaviour/connack_flags_are_set_as_reserved.rs
+++ b/mqtt-tester/src/behaviour/connack_flags_are_set_as_reserved.rs
@@ -4,6 +4,8 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
+
 use crate::{
     behaviour_test::BehaviourTest,
     command::{Input, Output},
@@ -19,6 +21,7 @@ impl BehaviourTest for ConnackFlagsAreSetAsReserved {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, mut input: Input, _output: Output) -> Result<(), miette::Error> {
         input
             .send(&[
@@ -27,7 +30,8 @@ impl BehaviourTest for ConnackFlagsAreSetAsReserved {
                 0b0000_0000,               // No session present
                 0b0000_0000,               // Connection accepted
             ])
-            .await?;
+            .await
+            .context("Sending bytes")?;
         Ok(())
     }
 
diff --git a/mqtt-tester/src/behaviour/first_packet_from_client_is_connect.rs b/mqtt-tester/src/behaviour/first_packet_from_client_is_connect.rs
index 17525b6..5f114c2 100644
--- a/mqtt-tester/src/behaviour/first_packet_from_client_is_connect.rs
+++ b/mqtt-tester/src/behaviour/first_packet_from_client_is_connect.rs
@@ -4,6 +4,7 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
 use mqtt_format::v3::packet::MPacket;
 
 use crate::{
@@ -21,6 +22,7 @@ impl BehaviourTest for FirstPacketFromClientIsConnect {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, _input: Input, mut output: Output) -> Result<(), miette::Error> {
         output
             .wait_and_check(
@@ -36,7 +38,8 @@ impl BehaviourTest for FirstPacketFromClientIsConnect {
                     std::matches!(packet, MPacket::Connect { .. })
                 }),
             )
-            .await?;
+            .await
+            .context("Waiting for bytes to check")?;
 
         Ok(())
     }
diff --git a/mqtt-tester/src/behaviour/invalid_first_packet_is_rejected.rs b/mqtt-tester/src/behaviour/invalid_first_packet_is_rejected.rs
index a4c95ad..d3f1a4a 100644
--- a/mqtt-tester/src/behaviour/invalid_first_packet_is_rejected.rs
+++ b/mqtt-tester/src/behaviour/invalid_first_packet_is_rejected.rs
@@ -4,6 +4,7 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
 use mqtt_format::v3::{packet::MConnect, strings::MString};
 
 use crate::{
@@ -21,6 +22,7 @@ impl BehaviourTest for InvalidFirstPacketIsRejected {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, mut input: Input, _output: Output) -> Result<(), miette::Error> {
         input
             .send_packet(MConnect {
@@ -33,7 +35,8 @@ impl BehaviourTest for InvalidFirstPacketIsRejected {
                 keep_alive: 0,
                 client_id: MString { value: "client" },
             })
-            .await?;
+            .await
+            .context("Sending bytes")?;
         Ok(())
     }
 
diff --git a/mqtt-tester/src/behaviour/invalid_utf8_is_rejected.rs b/mqtt-tester/src/behaviour/invalid_utf8_is_rejected.rs
index efe7a6d..b937ab1 100644
--- a/mqtt-tester/src/behaviour/invalid_utf8_is_rejected.rs
+++ b/mqtt-tester/src/behaviour/invalid_utf8_is_rejected.rs
@@ -4,6 +4,7 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
 use mqtt_format::v3::{connect_return::MConnectReturnCode, packet::MConnack};
 
 use crate::{
@@ -21,13 +22,15 @@ impl BehaviourTest for InvalidUtf8IsRejected {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, mut input: Input, _output: Output) -> Result<(), miette::Error> {
         input
             .send_packet(MConnack {
                 session_present: false,
                 connect_return_code: MConnectReturnCode::Accepted,
             })
-            .await?;
+            .await
+            .context("Sending packet: CONNACK")?;
 
         input
             .send(&[
@@ -42,7 +45,8 @@ impl BehaviourTest for InvalidUtf8IsRejected {
                 0b0000_0001,
                 0x1, // Payload
             ])
-            .await?;
+            .await
+            .context("Sending bytes")?;
         Ok(())
     }
 
diff --git a/mqtt-tester/src/behaviour/publish_qos_2_is_acked.rs b/mqtt-tester/src/behaviour/publish_qos_2_is_acked.rs
index 95dfeae..d18871c 100644
--- a/mqtt-tester/src/behaviour/publish_qos_2_is_acked.rs
+++ b/mqtt-tester/src/behaviour/publish_qos_2_is_acked.rs
@@ -4,6 +4,7 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
 use mqtt_format::v3::{
     connect_return::MConnectReturnCode,
     identifier::MPacketIdentifier,
@@ -27,13 +28,15 @@ impl BehaviourTest for PublishQos2IsAcked {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, mut input: Input, _output: Output) -> Result<(), miette::Error> {
         input
             .send_packet(MConnack {
                 session_present: false,
                 connect_return_code: MConnectReturnCode::Accepted,
             })
-            .await?;
+            .await
+            .context("Sending packet CONNACK")?;
 
         input
             .send_packet(MPublish {
@@ -44,7 +47,8 @@ impl BehaviourTest for PublishQos2IsAcked {
                 id: Some(MPacketIdentifier(1)),
                 payload: &[0x00],
             })
-            .await?;
+            .await
+            .context("Sending packet PUBLISH")?;
 
         Ok(())
     }
diff --git a/mqtt-tester/src/behaviour/publish_qos_zero_with_ident_fails.rs b/mqtt-tester/src/behaviour/publish_qos_zero_with_ident_fails.rs
index fe5544d..64cbddd 100644
--- a/mqtt-tester/src/behaviour/publish_qos_zero_with_ident_fails.rs
+++ b/mqtt-tester/src/behaviour/publish_qos_zero_with_ident_fails.rs
@@ -4,6 +4,7 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
 use mqtt_format::v3::{
     connect_return::MConnectReturnCode,
     identifier::MPacketIdentifier,
@@ -27,13 +28,15 @@ impl BehaviourTest for PublishQosZeroWithIdentFails {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, mut input: Input, _output: Output) -> Result<(), miette::Error> {
         input
             .send_packet(MConnack {
                 session_present: false,
                 connect_return_code: MConnectReturnCode::Accepted,
             })
-            .await?;
+            .await
+            .context("Sending packet CONNACK")?;
 
         input
             .send_packet(MPublish {
@@ -44,7 +47,8 @@ impl BehaviourTest for PublishQosZeroWithIdentFails {
                 id: Some(MPacketIdentifier(1)),
                 payload: &[0x00],
             })
-            .await?;
+            .await
+            .context("Sending packet PUBLISH")?;
         Ok(())
     }
 
diff --git a/mqtt-tester/src/behaviour/receiving_server_packet.rs b/mqtt-tester/src/behaviour/receiving_server_packet.rs
index f88888e..d2fdc03 100644
--- a/mqtt-tester/src/behaviour/receiving_server_packet.rs
+++ b/mqtt-tester/src/behaviour/receiving_server_packet.rs
@@ -4,6 +4,7 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
 use mqtt_format::v3::{
     connect_return::MConnectReturnCode,
     identifier::MPacketIdentifier,
@@ -26,13 +27,15 @@ impl BehaviourTest for ReceivingServerPacket {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, mut input: Input, _output: Output) -> Result<(), miette::Error> {
         input
             .send_packet(MConnack {
                 session_present: false,
                 connect_return_code: MConnectReturnCode::Accepted,
             })
-            .await?;
+            .await
+            .context("Sending packet CONNACK")?;
 
         input
             .send_packet(MSubscribe {
@@ -42,7 +45,8 @@ impl BehaviourTest for ReceivingServerPacket {
                     data: b"a/b",
                 },
             })
-            .await?;
+            .await
+            .context("Sending packet SUBSCRIBE")?;
         Ok(())
     }
 
diff --git a/mqtt-tester/src/behaviour/utf8_with_nullchar_is_rejected.rs b/mqtt-tester/src/behaviour/utf8_with_nullchar_is_rejected.rs
index 32283b6..3192b12 100644
--- a/mqtt-tester/src/behaviour/utf8_with_nullchar_is_rejected.rs
+++ b/mqtt-tester/src/behaviour/utf8_with_nullchar_is_rejected.rs
@@ -4,6 +4,7 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
 use mqtt_format::v3::{
     connect_return::MConnectReturnCode, header::MPacketKind, packet::MConnack,
     qos::MQualityOfService,
@@ -24,13 +25,15 @@ impl BehaviourTest for Utf8WithNullcharIsRejected {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, mut input: Input, _output: Output) -> Result<(), miette::Error> {
         input
             .send_packet(MConnack {
                 session_present: false,
                 connect_return_code: MConnectReturnCode::Accepted,
             })
-            .await?;
+            .await
+            .context("Sending packet CONNACK")?;
 
         input
             .send(&[
@@ -50,7 +53,8 @@ impl BehaviourTest for Utf8WithNullcharIsRejected {
                 0b0000_0001,
                 0x1, // Payload
             ])
-            .await?;
+            .await
+            .context("Sending broken packet PUBLISH")?;
         Ok(())
     }
 
diff --git a/mqtt-tester/src/behaviour/wait_for_connect.rs b/mqtt-tester/src/behaviour/wait_for_connect.rs
index ab16677..e63c415 100644
--- a/mqtt-tester/src/behaviour/wait_for_connect.rs
+++ b/mqtt-tester/src/behaviour/wait_for_connect.rs
@@ -4,6 +4,8 @@
 //   file, You can obtain one at http://mozilla.org/MPL/2.0/.
 //
 
+use miette::Context;
+
 use crate::{
     behaviour_test::BehaviourTest,
     command::{Input, Output},
@@ -19,6 +21,7 @@ impl BehaviourTest for WaitForConnect {
         vec![]
     }
 
+    #[tracing::instrument(skip_all)]
     async fn execute(&self, _input: Input, mut output: Output) -> Result<(), miette::Error> {
         output
             .wait_and_check(
@@ -40,6 +43,8 @@ impl BehaviourTest for WaitForConnect {
                 }),
             )
             .await
+            .context("Waiting for bytes to check")
+            .map_err(miette::Error::from)
     }
 
     fn report_name(&self) -> &str {
diff --git a/mqtt-tester/src/client_report.rs b/mqtt-tester/src/client_report.rs
index c99c734..36bdee3 100644
--- a/mqtt-tester/src/client_report.rs
+++ b/mqtt-tester/src/client_report.rs
@@ -9,6 +9,7 @@ use std::sync::Arc;
 
 use futures::FutureExt;
 
+use miette::Context;
 use mqtt_format::v3::packet::{MConnect, MPacket};
 
 use crate::behaviour_test::BehaviourTest;
@@ -57,8 +58,10 @@ pub async fn create_client_report(
 
         let (client, input, mut output) = executable
             .call(&commands)
-            .map(crate::command::Command::new)?
-            .spawn()?;
+            .map(crate::command::Command::new)
+            .context("Creating client executable call")?
+            .spawn()
+            .context("Spawning client executable")?;
 
         output.with_invariants(invariants.iter().cloned());
 
@@ -110,7 +113,14 @@ pub async fn create_client_report(
                     let res = flow.translate_client_exit_code(out.status.success());
                     (res, Some(out.stderr))
                 }
-                (Err(_), _) | (_, Err(_)) => (ReportResult::Failure, None),
+                (Err(e), _) => {
+                    tracing::error!("Error during behaviour testing: {:?}", e);
+                    (ReportResult::Failure, None)
+                }
+                (_, Err(e)) => {
+                    tracing::error!("Error during behaviour testing: {:?}", e);
+                    (ReportResult::Failure, None)
+                }
             }
         };
 
@@ -199,6 +209,7 @@ macro_rules! wait_for_output {
     }};
 }
 
+#[tracing::instrument(skip_all)]
 async fn check_connect_packet_reserved_flag_zero(
     executable: &ClientExecutable,
 ) -> miette::Result<Report> {
@@ -213,7 +224,8 @@ async fn check_connect_packet_reserved_flag_zero(
                 bytes[0] == 0b0001_0000 // CONNECT packet with flags set to 0000
             }),
         )
-        .await?;
+        .await
+        .context("Waiting for bytes to check")?;
 
     let output = client.wait_with_output();
     let (result, output) = wait_for_output! {
@@ -252,6 +264,7 @@ fn find_connect_flags(bytes: &[u8]) -> Option<u8> {
     Some(getbyte!(connect_flag_position))
 }
 
+#[tracing::instrument(skip_all)]
 async fn check_connect_flag_username_set_username_present(
     executable: &ClientExecutable,
 ) -> miette::Result<Report> {
@@ -288,7 +301,8 @@ async fn check_connect_flag_username_set_username_present(
                 }
             }),
         )
-        .await?;
+        .await
+        .context("Waiting for bytes to check")?;
 
     let output = client.wait_with_output();
     let (result, output) = wait_for_output! {
@@ -307,6 +321,7 @@ async fn check_connect_flag_username_set_username_present(
     })
 }
 
+#[tracing::instrument(skip_all)]
 async fn check_connect_flag_password_set_password_present(
     executable: &ClientExecutable,
 ) -> miette::Result<Report> {
@@ -343,7 +358,8 @@ async fn check_connect_flag_password_set_password_present(
                 }
             }),
         )
-        .await?;
+        .await
+        .context("Waiting for bytes to check")?;
 
     let output = client.wait_with_output();
     let (result, output) = wait_for_output! {
@@ -362,6 +378,7 @@ async fn check_connect_flag_password_set_password_present(
     })
 }
 
+#[tracing::instrument(skip_all)]
 async fn check_connect_flag_username_zero_means_password_zero(
     executable: &ClientExecutable,
 ) -> miette::Result<Report> {
@@ -389,7 +406,8 @@ async fn check_connect_flag_username_zero_means_password_zero(
                 }
             }),
         )
-        .await?;
+        .await
+        .context("Waiting for bytes to check")?;
 
     let output = client.wait_with_output();
     let (result, output) = wait_for_output! {