diff --git a/test-harness/src/checkpoint.rs b/test-harness/src/checkpoint.rs new file mode 100644 index 00000000..d4b024c0 --- /dev/null +++ b/test-harness/src/checkpoint.rs @@ -0,0 +1,104 @@ +use std::fmt::Debug; +use std::fmt::Display; +use std::ops::Range; +use std::ops::RangeFrom; +use std::ops::RangeFull; +use std::ops::RangeInclusive; +use std::ops::RangeTo; +use std::ops::RangeToInclusive; +use std::slice::SliceIndex; + +use crate::Event; + +/// A checkpoint in a `ghcid-ng` run. +/// +/// [`crate::GhcidNg`] provides methods for asserting that events are logged, or waiting for +/// events to be logged in the future. +/// +/// To avoid searching thousands of log events for each assertion, and to provide greater +/// granularity for assertions, you can additionally assert that events are logged between +/// particular checkpoints. +/// +/// Checkpoints can be constructed with [`crate::GhcidNg::first_checkpoint`], +/// [`crate::GhcidNg::current_checkpoint`], and [`crate::GhcidNg::checkpoint`]. +#[derive(Debug, Clone, Copy)] +pub struct Checkpoint(pub(crate) usize); + +impl Checkpoint { + /// Convert this checkpoint into an index. + pub fn into_index(self) -> usize { + self.0 + } +} + +impl Display for Checkpoint { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "{}", self.0) + } +} + +/// A type that can be used to index a set of checkpoints. +pub trait CheckpointIndex: Clone { + /// The resulting index type. + type Index: SliceIndex<[Vec], Output = [Vec]> + Debug; + + /// Convert the value into an index. + fn into_index(self) -> Self::Index; +} + +impl CheckpointIndex for Checkpoint { + type Index = RangeInclusive; + + fn into_index(self) -> Self::Index { + let index = self.into_index(); + index..=index + } +} + +impl CheckpointIndex for Range { + type Index = Range; + + fn into_index(self) -> Self::Index { + self.start.into_index()..self.end.into_index() + } +} + +impl CheckpointIndex for RangeFrom { + type Index = RangeFrom; + + fn into_index(self) -> Self::Index { + self.start.into_index().. + } +} + +impl CheckpointIndex for RangeFull { + type Index = RangeFull; + + fn into_index(self) -> Self::Index { + self + } +} + +impl CheckpointIndex for RangeInclusive { + type Index = RangeInclusive; + + fn into_index(self) -> Self::Index { + self.start().into_index()..=self.end().into_index() + } +} + +impl CheckpointIndex for RangeTo { + type Index = RangeTo; + + fn into_index(self) -> Self::Index { + ..self.end.into_index() + } +} + +impl CheckpointIndex for RangeToInclusive { + type Index = RangeToInclusive; + + fn into_index(self) -> Self::Index { + ..=self.end.into_index() + } +} diff --git a/test-harness/src/ghcid_ng.rs b/test-harness/src/ghcid_ng.rs index a340edf2..a37a9592 100644 --- a/test-harness/src/ghcid_ng.rs +++ b/test-harness/src/ghcid_ng.rs @@ -13,9 +13,10 @@ use miette::IntoDiagnostic; use tokio::process::Command; use crate::matcher::Matcher; -use crate::matcher::OptionMatcher; use crate::tracing_reader::TracingReader; use crate::BaseMatcher; +use crate::Checkpoint; +use crate::CheckpointIndex; use crate::Event; use crate::GhcVersion; use crate::IntoMatcher; @@ -30,6 +31,8 @@ pub struct GhcidNgBuilder { args: Vec, #[allow(clippy::type_complexity)] before_start: Option BoxFuture<'static, miette::Result<()>> + Send>>, + default_timeout: Duration, + startup_timeout: Duration, } impl GhcidNgBuilder { @@ -39,6 +42,8 @@ impl GhcidNgBuilder { project_directory: project_directory.as_ref().to_owned(), args: Default::default(), before_start: None, + default_timeout: Duration::from_secs(10), + startup_timeout: Duration::from_secs(60), } } @@ -65,6 +70,24 @@ impl GhcidNgBuilder { self } + /// Set the default timeout to wait for log messages in [`GhcidNg::wait_for_log`], + /// [`GhcidNg::assert_logged_or_wait`], and similar. + /// + /// The timeout defaults to 10 seconds. + pub fn with_default_timeout(mut self, default_timeout: Duration) -> Self { + self.default_timeout = default_timeout; + self + } + + /// Set the default timeout to wait for `ghci` to start up in + /// [`GhcidNg::wait_until_started`] and [`GhcidNg::wait_until_ready`]. + /// + /// The timeout defaults to 60 seconds. + pub fn with_startup_timeout(mut self, startup_timeout: Duration) -> Self { + self.startup_timeout = startup_timeout; + self + } + /// Start `ghcid-ng`. pub async fn start(self) -> miette::Result { GhcidNg::from_builder(self).await @@ -80,8 +103,17 @@ pub struct GhcidNg { cwd: PathBuf, /// A stream of tracing events from `ghcid-ng`. tracing_reader: TracingReader, + /// All logged events read so far. + /// + /// TODO: Make this a `Vec>` with "checkpoints" and allow searching in given + /// checkpoint ranges. + events: Vec>, /// The major version of GHC this test is running under. ghc_version: GhcVersion, + /// The default timeout for waiting for log messages. + default_timeout: Duration, + /// The timeout for waiting for `ghci to finish starting up. + startup_timeout: Duration, } impl GhcidNg { @@ -156,7 +188,7 @@ impl GhcidNg { // Wait for `ghcid-ng` to create the `log_path` let creates_log_path = - tokio::time::timeout(Duration::from_secs(10), crate::fs::wait_for_path(&log_path)); + tokio::time::timeout(builder.default_timeout, crate::fs::wait_for_path(&log_path)); tokio::select! { child_result = child.wait() => { return match child_result { @@ -180,10 +212,18 @@ impl GhcidNg { let tracing_reader = TracingReader::new(log_path.clone()).await?; + // Most tests won't use checkpoints, so we'll only have a couple checkpoint slots + // and many event slots in the first checkpoint chunk. + let mut events = Vec::with_capacity(8); + events.push(Vec::with_capacity(1024)); + Ok(Self { cwd, tracing_reader, + events, ghc_version, + default_timeout: builder.default_timeout, + startup_timeout: builder.startup_timeout, }) } @@ -192,33 +232,109 @@ impl GhcidNg { GhcidNgBuilder::new(project_directory).start().await } - /// Wait until a matching log event is found. + /// Get the first [`Checkpoint`]. + /// + /// There is always an initial checkpoint which events are logged into before other + /// checkpoints are created. + /// + /// Note that `first_checkpoint()..=current_checkpoint()` is equivalent to `..`. + pub fn first_checkpoint(&self) -> Checkpoint { + Checkpoint(0) + } + + /// Get the current [`Checkpoint`]. + /// + /// Events read by [`GhcidNg::wait_for_log_with_timeout`] and friends will add events to + /// this checkpoint. + pub fn current_checkpoint(&self) -> Checkpoint { + Checkpoint(self.events.len() - 1) + } + + /// Create and return a new [`Checkpoint`]. + /// + /// New log events will be stored in this checkpoint. + /// + /// Later, you can check for log events in checkpoints with + /// [`Self::assert_logged_in_checkpoint`] and friends. + pub fn checkpoint(&mut self) -> Checkpoint { + self.events.push(Vec::with_capacity(512)); + self.current_checkpoint() + } + + /// Get the `Vec` of events since the last checkpoint. + fn current_chunk_mut(&mut self) -> &mut Vec { + self.events + .last_mut() + .expect("There is always an initial checkpoint") + } + + /// Get an iterator over the events in the given checkpoints. + /// + /// The `index` can be an individual [`Checkpoint`] or any [`std::ops::Range`] of checkpoints. + fn events_in_checkpoints(&self, index: impl CheckpointIndex) -> impl Iterator { + self.events[index.into_index()].iter().flatten() + } + + /// Read an event from the `ghcid-ng` session. + async fn read_event(&mut self) -> miette::Result<&Event> { + let event = self.tracing_reader.next_event().await?; + let chunk = self.current_chunk_mut(); + chunk.push(event); + Ok(chunk.last().expect("We just inserted this event")) + } + + /// Assert that a matching event was logged in one of the given `checkpoints`. + pub fn assert_logged_in_checkpoint( + &self, + checkpoints: impl CheckpointIndex, + matcher: impl IntoMatcher, + ) -> miette::Result<&Event> { + let mut matcher = matcher.into_matcher()?; + for event in self.events_in_checkpoints(checkpoints.clone()) { + if matcher.matches(event)? { + return Ok(event); + } + } + + Err(miette!( + "No log message matching {matcher} found in checkpoint {:?}", + checkpoints.into_index() + )) + } + + /// Assert that a matching event was logged since the last [`Checkpoint`]. + pub fn assert_logged(&self, matcher: impl IntoMatcher) -> miette::Result<&Event> { + self.assert_logged_in_checkpoint(self.current_checkpoint(), matcher) + } + + /// Match a log message in the given checkpoints or wait until a matching log event is + /// found. /// - /// If `negative_matcher` is given, no log events may match it until an event matching the - /// regular `matcher` is found. + /// If `checkpoints` is `None`, do not check the `matcher` against any previously logged + /// events. /// /// Errors if waiting for the event takes longer than the given `timeout`. - pub async fn assert_logged_with_timeout( + pub async fn wait_for_log_with_timeout( &mut self, - mut negative_matcher: OptionMatcher, - matcher: impl IntoMatcher, + matcher: M, + checkpoints: Option, timeout_duration: Duration, ) -> miette::Result { let mut matcher = matcher.into_matcher()?; + // First check if it was logged in `checkpoints`. + if let Some(checkpoints) = checkpoints { + if let Ok(event) = self.assert_logged_in_checkpoint(checkpoints, &mut matcher) { + return Ok(event.clone()); + } + } + + // Otherwise, wait for a log message. match tokio::time::timeout(timeout_duration, async { loop { - match self.tracing_reader.next_event().await { - Err(err) => { - return Err(err); - } - Ok(event) => { - if matcher.matches(&event)? { - return Ok(event); - } else if negative_matcher.matches(&event)? { - return Err(miette!("Found a log event matching {negative_matcher}")); - } - } + let event = self.read_event().await?; + if matcher.matches(event)? { + return Ok(event.clone()); } } }) @@ -227,63 +343,92 @@ impl GhcidNg { Ok(Ok(event)) => Ok(event), Ok(Err(err)) => Err(err), Err(_) => Err(miette!( - "Waiting for a log message matching {matcher} timed out after {timeout_duration:.2?}" + "Waiting for a log message matching {matcher} \ + timed out after {timeout_duration:.2?}" )), } } - /// Wait until a matching log event is found, with a default 10-second timeout. - pub async fn assert_logged(&mut self, matcher: impl IntoMatcher) -> miette::Result { - self.assert_logged_with_timeout(OptionMatcher::none(), matcher, Duration::from_secs(10)) + /// Assert that a message matching `matcher` has been logged in the given [`Checkpoint`]s or + /// wait for the `default_timeout` for a matching message to be logged. + pub async fn assert_logged_in_checkpoint_or_wait( + &mut self, + checkpoints: impl CheckpointIndex, + matcher: impl IntoMatcher, + ) -> miette::Result { + self.wait_for_log_with_timeout(matcher, Some(checkpoints), self.default_timeout) .await } - /// Wait until a matching log event is found, with a default 10-second timeout. - /// - /// Error if a log event matching `negative_matcher` is found before an event matching - /// `matcher`. - pub async fn assert_not_logged( + /// Assert that a message matching `matcher` has been logged in the most recent [`Checkpoint`] + /// or wait for the `default_timeout` for a matching message to be logged. + pub async fn assert_logged_or_wait( &mut self, - negative_matcher: impl IntoMatcher, matcher: impl IntoMatcher, ) -> miette::Result { - self.assert_logged_with_timeout( - OptionMatcher::some(negative_matcher.into_matcher()?), + self.wait_for_log_with_timeout( matcher, - Duration::from_secs(10), + Some(self.current_checkpoint()), + self.default_timeout, ) .await } - /// Wait until `ghcid-ng` completes its initial load and is ready to receive file events. - pub async fn wait_until_started(&mut self) -> miette::Result { - self.assert_logged_with_timeout( - OptionMatcher::none(), + /// Wait until a matching log event is found with the `default_timeout`. + pub async fn wait_for_log(&mut self, matcher: impl IntoMatcher) -> miette::Result { + self.wait_for_log_with_timeout(matcher, None::, self.default_timeout) + .await + } + + /// Wait until `ghcid-ng` completes its initial load. + /// + /// Returns immediately if `ghcid-ng` has already completed its initial load in the current + /// checkpoint. + pub async fn wait_until_started(&mut self) -> miette::Result<()> { + self.wait_for_log_with_timeout( BaseMatcher::ghci_started(), - Duration::from_secs(60), + Some(self.current_checkpoint()), + self.startup_timeout, ) .await - .wrap_err("ghcid-ng didn't start in time") + .wrap_err("ghcid-ng didn't start in time")?; + Ok(()) } /// Wait until `ghcid-ng` is ready to receive file events. - pub async fn wait_until_watcher_started(&mut self) -> miette::Result { - self.assert_logged(BaseMatcher::watcher_started()) - .await - .wrap_err("notify watcher didn't start in time") + /// + /// Returns immediately if `ghcid-ng` has already become ready to receive file events in the + /// current checkpoint. + pub async fn wait_until_watcher_started(&mut self) -> miette::Result<()> { + self.wait_for_log_with_timeout( + BaseMatcher::watcher_started(), + Some(self.current_checkpoint()), + self.default_timeout, + ) + .await + .wrap_err("notify watcher didn't start in time")?; + Ok(()) } /// Wait until `ghcid-ng` completes its initial load and is ready to receive file events. + /// + /// Returns immediately if `ghcid-ng` has already completed its inital load and become ready to + /// receive file events in the current checkpoint. pub async fn wait_until_ready(&mut self) -> miette::Result<()> { - self.wait_until_started().await?; - self.wait_until_watcher_started().await?; + self.wait_for_log_with_timeout( + BaseMatcher::ghci_started().and(BaseMatcher::watcher_started()), + Some(self.current_checkpoint()), + self.startup_timeout, + ) + .await + .wrap_err("ghcid-ng didn't start in time")?; Ok(()) } /// Wait until `ghcid-ng` reloads the `ghci` session due to changed modules. pub async fn wait_until_reload(&mut self) -> miette::Result<()> { // TODO: It would be nice to verify which modules are changed. - self.assert_logged(BaseMatcher::ghci_reload()) + self.wait_for_log(BaseMatcher::ghci_reload()) .await .map(|_| ()) } @@ -291,17 +436,15 @@ impl GhcidNg { /// Wait until `ghcid-ng` adds new modules to the `ghci` session. pub async fn wait_until_add(&mut self) -> miette::Result<()> { // TODO: It would be nice to verify which modules are being added. - self.assert_logged(BaseMatcher::ghci_add()) - .await - .map(|_| ()) + self.wait_for_log(BaseMatcher::ghci_add()).await?; + Ok(()) } /// Wait until `ghcid-ng` restarts the `ghci` session. pub async fn wait_until_restart(&mut self) -> miette::Result<()> { // TODO: It would be nice to verify which modules have been deleted/moved. - self.assert_logged(BaseMatcher::ghci_restart()) - .await - .map(|_| ()) + self.wait_for_log(BaseMatcher::ghci_restart()).await?; + Ok(()) } /// Get a path relative to the project root. diff --git a/test-harness/src/lib.rs b/test-harness/src/lib.rs index 71f9c68c..7ae1b872 100644 --- a/test-harness/src/lib.rs +++ b/test-harness/src/lib.rs @@ -27,3 +27,7 @@ pub use ghcid_ng::GhcidNgBuilder; mod ghc_version; pub use ghc_version::GhcVersion; + +mod checkpoint; +pub use checkpoint::Checkpoint; +pub use checkpoint::CheckpointIndex; diff --git a/test-harness/src/matcher/and_matcher.rs b/test-harness/src/matcher/and_matcher.rs index 953374a7..d7f1fc50 100644 --- a/test-harness/src/matcher/and_matcher.rs +++ b/test-harness/src/matcher/and_matcher.rs @@ -41,7 +41,10 @@ mod tests { #[test] fn test_and_matcher() { - let mut matcher = "puppy".into_matcher().unwrap().and("doggy").unwrap(); + let mut matcher = "puppy" + .into_matcher() + .unwrap() + .and("doggy".into_matcher().unwrap()); let event = Event { message: "puppy".to_owned(), timestamp: "2023-08-25T22:14:30.067641Z".to_owned(), diff --git a/test-harness/src/matcher/into_matcher.rs b/test-harness/src/matcher/into_matcher.rs index c67ade2f..71e43a36 100644 --- a/test-harness/src/matcher/into_matcher.rs +++ b/test-harness/src/matcher/into_matcher.rs @@ -1,3 +1,5 @@ +use miette::Diagnostic; + use crate::BaseMatcher; use crate::Matcher; @@ -36,3 +38,15 @@ impl IntoMatcher for &str { Ok(BaseMatcher::message(self)) } } + +impl IntoMatcher for Result +where + M: IntoMatcher, + E: Diagnostic + Send + Sync + 'static, +{ + type Matcher = ::Matcher; + + fn into_matcher(self) -> miette::Result { + self.map_err(|err| miette::Report::new(err))?.into_matcher() + } +} diff --git a/test-harness/src/matcher/mod.rs b/test-harness/src/matcher/mod.rs index 8c68db85..fbb28e78 100644 --- a/test-harness/src/matcher/mod.rs +++ b/test-harness/src/matcher/mod.rs @@ -23,6 +23,9 @@ pub use option_matcher::OptionMatcher; mod never_matcher; pub use never_matcher::NeverMatcher; +mod negative_matcher; +pub use negative_matcher::NegativeMatcher; + /// A type which can match log events. pub trait Matcher: Display { /// Feeds an event to the matcher and determines if the matcher has finished. @@ -32,25 +35,22 @@ pub trait Matcher: Display { /// Construct a matcher that matches when this matcher or the `other` matcher have /// finished matching. - fn or(self, other: O) -> miette::Result::Matcher>> + fn or(self, other: O) -> OrMatcher where - O: IntoMatcher, + O: Matcher, Self: Sized, { - Ok(OrMatcher(self, other.into_matcher()?)) + OrMatcher(self, other) } /// Construct a matcher that matches when this matcher and the `other` matcher have /// finished matching. - fn and( - self, - other: O, - ) -> miette::Result, FusedMatcher<::Matcher>>> + fn and(self, other: O) -> AndMatcher, FusedMatcher> where - O: IntoMatcher, + O: Matcher, Self: Sized, { - Ok(AndMatcher(self.fused(), other.into_matcher()?.fused())) + AndMatcher(self.fused(), other.fused()) } /// Construct a matcher that stops calling [`Matcher::matches`] on this matcher after it @@ -61,6 +61,16 @@ pub trait Matcher: Display { { FusedMatcher::new(self) } + + /// Construct a matcher that matches when this matcher matches and errors when the `other` + /// matcher matches. + fn but_not(self, other: O) -> NegativeMatcher + where + O: Matcher, + Self: Sized, + { + NegativeMatcher::new(self, other) + } } impl Matcher for &mut M diff --git a/test-harness/src/matcher/negative_matcher.rs b/test-harness/src/matcher/negative_matcher.rs new file mode 100644 index 00000000..2958a8b7 --- /dev/null +++ b/test-harness/src/matcher/negative_matcher.rs @@ -0,0 +1,88 @@ +use std::fmt::Display; + +use miette::miette; + +use crate::Event; +use crate::Matcher; + +/// Wraps two matchers. The first matcher is used as normal, except if the negative matcher +/// matches an event, [`Matcher::matches`] errors. +pub struct NegativeMatcher { + inner: M, + negative: N, +} + +impl NegativeMatcher { + /// Construct a matcher that matches if `inner` matches and errors if `negative` matches. + pub fn new(inner: M, negative: N) -> Self { + Self { inner, negative } + } +} + +impl Display for NegativeMatcher +where + A: Display, + B: Display, +{ + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "{} but not {}", self.inner, self.negative) + } +} + +impl Matcher for NegativeMatcher +where + A: Display + Matcher, + B: Display + Matcher, +{ + fn matches(&mut self, event: &Event) -> miette::Result { + if self.negative.matches(event)? { + Err(miette!("Log event matched {}: {}", self.negative, event)) + } else if self.inner.matches(event)? { + Ok(true) + } else { + Ok(false) + } + } +} + +#[cfg(test)] +mod tests { + use tracing::Level; + + use crate::tracing_json::Span; + use crate::IntoMatcher; + + use super::*; + + #[test] + fn test_negative_matcher() { + let event = Event { + message: "puppy".to_owned(), + timestamp: "2023-08-25T22:14:30.067641Z".to_owned(), + level: Level::INFO, + fields: Default::default(), + target: "ghcid_ng::ghci".to_owned(), + span: Some(Span { + name: "ghci".to_owned(), + rest: Default::default(), + }), + spans: vec![Span { + name: "ghci".to_owned(), + rest: Default::default(), + }], + }; + + let mut matcher = "puppy" + .into_matcher() + .unwrap() + .but_not("doggy".into_matcher().unwrap()); + + assert!(matcher.matches(&event).unwrap()); + assert!(matcher + .matches(&Event { + message: "doggy".to_owned(), + ..event + }) + .is_err()); + } +} diff --git a/test-harness/src/matcher/or_matcher.rs b/test-harness/src/matcher/or_matcher.rs index a9167355..5f2f1844 100644 --- a/test-harness/src/matcher/or_matcher.rs +++ b/test-harness/src/matcher/or_matcher.rs @@ -41,7 +41,10 @@ mod tests { #[test] fn test_or_matcher() { - let mut matcher = "puppy".into_matcher().unwrap().or("doggy").unwrap(); + let mut matcher = "puppy" + .into_matcher() + .unwrap() + .or("doggy".into_matcher().unwrap()); let event = Event { message: "puppy".to_owned(), timestamp: "2023-08-25T22:14:30.067641Z".to_owned(), diff --git a/tests/error_log.rs b/tests/error_log.rs index ff116b9d..6589100b 100644 --- a/tests/error_log.rs +++ b/tests/error_log.rs @@ -66,7 +66,7 @@ async fn can_write_error_log_compilation_errors() { .expect("ghcid-ng loads new modules"); session - .assert_logged(BaseMatcher::span_close().in_span("error_log_write")) + .wait_for_log(BaseMatcher::span_close().in_span("error_log_write")) .await .expect("ghcid-ng writes ghcid.txt"); @@ -111,7 +111,7 @@ async fn can_write_error_log_compilation_errors() { .expect("ghcid-ng reloads on changes"); session - .assert_logged(BaseMatcher::span_close().in_span("error_log_write")) + .wait_for_log(BaseMatcher::span_close().in_span("error_log_write")) .await .expect("ghcid-ng writes ghcid.txt"); diff --git a/tests/eval.rs b/tests/eval.rs index 03fbdfeb..98bd2ad2 100644 --- a/tests/eval.rs +++ b/tests/eval.rs @@ -4,6 +4,7 @@ use test_harness::fs; use test_harness::test; use test_harness::BaseMatcher; use test_harness::GhcidNgBuilder; +use test_harness::Matcher; /// Test that `ghcid-ng` can eval commands and invalidate its cache of eval commands. #[test] @@ -27,11 +28,13 @@ async fn can_eval_commands() { let eval_message = BaseMatcher::message(r"MyModule.hs:\d+:\d+: example \+\+ example"); session - .assert_logged(&eval_message) + .assert_logged_or_wait(&eval_message) .await .expect("ghcid-ng evals commands"); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "exampleexample")) + .assert_logged_or_wait( + BaseMatcher::message("Read line").with_field("line", "exampleexample"), + ) .await .expect("ghcid-ng evals commands"); @@ -40,11 +43,11 @@ async fn can_eval_commands() { session.wait_until_reload().await.expect("ghcid-ng reloads"); session - .assert_not_logged( - &eval_message, + .wait_for_log( BaseMatcher::span_close() .in_span("reload") - .in_module("ghcid_ng::ghci"), + .in_module("ghcid_ng::ghci") + .but_not(eval_message), ) .await .unwrap(); @@ -79,11 +82,11 @@ async fn can_load_new_eval_commands_multiline() { let eval_message = BaseMatcher::message(&format!(r"MyModule.hs:\d+:\d+: {}", regex::escape(cmd))); session - .assert_logged(&eval_message) + .wait_for_log(&eval_message) .await .expect("ghcid-ng evals commands"); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Read line").with_field("line", r#"^"exampleexampleexample"$"#), ) .await @@ -94,11 +97,11 @@ async fn can_load_new_eval_commands_multiline() { session.wait_until_reload().await.expect("ghcid-ng reloads"); session - .assert_not_logged( - &eval_message, + .wait_for_log( BaseMatcher::span_close() .in_span("reload") - .in_module("ghcid_ng::ghci"), + .in_module("ghcid_ng::ghci") + .but_not(eval_message), ) .await .unwrap(); diff --git a/tests/failed_modules.rs b/tests/failed_modules.rs index 9812e428..7a135028 100644 --- a/tests/failed_modules.rs +++ b/tests/failed_modules.rs @@ -18,7 +18,7 @@ async fn can_start_with_failed_modules() { let module_path = session.path(module_path); session - .assert_logged("Compilation failed") + .wait_for_log("Compilation failed") .await .expect("ghcid-ng fails to load with errors"); @@ -29,7 +29,7 @@ async fn can_start_with_failed_modules() { .unwrap(); session - .assert_logged("Compilation succeeded") + .wait_for_log("Compilation succeeded") .await .expect("ghcid-ng reloads fixed modules"); } diff --git a/tests/hooks.rs b/tests/hooks.rs index 24ad7f96..a9890380 100644 --- a/tests/hooks.rs +++ b/tests/hooks.rs @@ -38,26 +38,26 @@ async fn can_run_hooks() { .expect("ghcid-ng starts"); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running after-startup command") .with_field("command", "putStrLn \"after-startup-1\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^after-startup-1$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^after-startup-1$")) .await .unwrap(); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running after-startup command") .with_field("command", "putStrLn \"after-startup-2\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^after-startup-2$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^after-startup-2$")) .await .unwrap(); @@ -67,102 +67,102 @@ async fn can_run_hooks() { // Before reload session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running before-reload command") .with_field("command", "putStrLn \"before-reload-1\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^before-reload-1$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^before-reload-1$")) .await .unwrap(); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running before-reload command") .with_field("command", "putStrLn \"before-reload-2\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^before-reload-2$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^before-reload-2$")) .await .unwrap(); // After reload session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running after-reload command") .with_field("command", "putStrLn \"after-reload-1\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^after-reload-1$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^after-reload-1$")) .await .unwrap(); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running after-reload command") .with_field("command", "putStrLn \"after-reload-2\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^after-reload-2$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^after-reload-2$")) .await .unwrap(); fs::remove(session.path("src/MyModule.hs")).await.unwrap(); // Before restart session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running before-restart command") .with_field("command", "putStrLn \"before-restart-1\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^before-restart-1$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^before-restart-1$")) .await .unwrap(); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running before-restart command") .with_field("command", "putStrLn \"before-restart-2\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^before-restart-2$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^before-restart-2$")) .await .unwrap(); // After restart session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running after-restart command") .with_field("command", "putStrLn \"after-restart-1\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^after-restart-1$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^after-restart-1$")) .await .unwrap(); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Running after-restart command") .with_field("command", "putStrLn \"after-restart-2\""), ) .await .unwrap(); session - .assert_logged(BaseMatcher::message("Read line").with_field("line", "^after-restart-2$")) + .wait_for_log(BaseMatcher::message("Read line").with_field("line", "^after-restart-2$")) .await .unwrap(); } diff --git a/tests/reload.rs b/tests/reload.rs index 9beb056d..3db451ee 100644 --- a/tests/reload.rs +++ b/tests/reload.rs @@ -32,7 +32,7 @@ async fn can_reload() { .await .expect("ghcid-ng reloads on changes"); session - .assert_logged( + .wait_for_log( BaseMatcher::span_close() .in_module("ghcid_ng::ghci") .in_spans(["on_action", "reload"]), @@ -69,7 +69,7 @@ async fn can_reload_after_error() { .await .expect("ghcid-ng loads new modules"); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Compilation failed").in_spans(["reload", "add_module"]), ) .await @@ -84,7 +84,7 @@ async fn can_reload_after_error() { .await .expect("ghcid-ng reloads on changes"); session - .assert_logged(BaseMatcher::message("Compilation succeeded").in_span("reload")) + .wait_for_log(BaseMatcher::message("Compilation succeeded").in_span("reload")) .await .unwrap(); } diff --git a/tests/restart.rs b/tests/restart.rs index 18c4fb40..fa0af11c 100644 --- a/tests/restart.rs +++ b/tests/restart.rs @@ -52,7 +52,7 @@ async fn can_restart_after_module_move() { .expect("ghcid-ng restarts ghci"); session - .assert_logged( + .wait_for_log( BaseMatcher::message("Compiling") .in_span("reload") .with_field("module", r"My\.CoolModule"), @@ -61,7 +61,7 @@ async fn can_restart_after_module_move() { .unwrap(); session - .assert_logged(BaseMatcher::message("Compilation succeeded").in_span("reload")) + .wait_for_log(BaseMatcher::message("Compilation succeeded").in_span("reload")) .await .unwrap(); } diff --git a/tests/test.rs b/tests/test.rs index 6d3a879f..a6671abf 100644 --- a/tests/test.rs +++ b/tests/test.rs @@ -24,11 +24,11 @@ async fn can_run_test_suite_on_reload() { .expect("Can touch file"); session - .assert_logged(BaseMatcher::span_close().in_span("error_log_write")) + .wait_for_log(BaseMatcher::span_close().in_span("error_log_write")) .await .expect("ghcid-ng writes ghcid.txt"); session - .assert_logged("Finished running tests") + .wait_for_log("Finished running tests") .await .expect("ghcid-ng runs the test suite");