diff --git a/crates/cli/src/repo/handlers/advance_next.rs b/crates/cli/src/repo/handlers/advance_next.rs index 1d90fcc..e8f773c 100644 --- a/crates/cli/src/repo/handlers/advance_next.rs +++ b/crates/cli/src/repo/handlers/advance_next.rs @@ -1,7 +1,7 @@ // use actix::prelude::*; -use tracing::warn; +use tracing::{warn, Instrument}; use crate::{ repo::{ @@ -34,11 +34,12 @@ impl Handler for RepoActor { let addr = ctx.address(); let (commit, force) = find_next_commit_on_dev(&next, &main, &dev_commit_history); - self.update_tui(RepoUpdate::AdvancingNext { - commit: commit.clone(), - force: force.clone(), - }); - + if let Some(commit) = &commit { + self.update_tui(RepoUpdate::AdvancingNext { + commit: commit.clone(), + force: force.clone(), + }); + }; match advance_next( commit, force, @@ -49,10 +50,20 @@ impl Handler for RepoActor { ) { Ok(message_token) => { // pause to allow any CI checks to be started - std::thread::sleep(self.sleep_duration); - do_send(&addr, ValidateRepo::new(message_token), self.log.as_ref()); + let sleep_duration = self.sleep_duration; + let log = self.log.clone(); + async move { + std::thread::sleep(sleep_duration); + do_send(&addr, ValidateRepo::new(message_token), log.as_ref()); + } + .in_current_span() + .into_actor(self) + .wait(ctx); + } + Err(err) => { + warn!("advance next: {err}"); + self.alert_tui(err.to_string()); } - Err(err) => warn!("advance next: {err}"), } } } diff --git a/crates/cli/src/repo/handlers/receive_ci_status.rs b/crates/cli/src/repo/handlers/receive_ci_status.rs index 1294f67..6d65299 100644 --- a/crates/cli/src/repo/handlers/receive_ci_status.rs +++ b/crates/cli/src/repo/handlers/receive_ci_status.rs @@ -2,11 +2,11 @@ use actix::prelude::*; use git_next_core::git::{forge::commit::Status, graph, UserNotification}; -use tracing::debug; +use tracing::{debug, Instrument as _}; use crate::{ repo::{ - delay_send, do_send, logger, + do_send, logger, messages::{AdvanceMain, ReceiveCIStatus, ValidateRepo}, notify_user, RepoActor, }, @@ -53,12 +53,16 @@ impl Handler for RepoActor { }, log.as_ref(), ); - delay_send( - &addr, - sleep_duration, - ValidateRepo::new(message_token), - self.log.as_ref(), - ); + async move { + debug!("sleeping before retrying..."); + logger(log.as_ref(), "before sleep"); + actix_rt::time::sleep(sleep_duration).await; + logger(log.as_ref(), "after sleep"); + do_send(&addr, ValidateRepo::new(message_token), log.as_ref()); + } + .in_current_span() + .into_actor(self) + .wait(ctx); } } } diff --git a/crates/cli/src/repo/handlers/validate_repo.rs b/crates/cli/src/repo/handlers/validate_repo.rs index a31572d..095c070 100644 --- a/crates/cli/src/repo/handlers/validate_repo.rs +++ b/crates/cli/src/repo/handlers/validate_repo.rs @@ -1,7 +1,7 @@ // use actix::prelude::*; -use tracing::{debug, instrument, Instrument as _}; +use tracing::{info, instrument, Instrument as _}; use crate::{ repo::{ @@ -13,6 +13,7 @@ use crate::{ }; use git_next_core::git::{ + push::Force, validation::positions::{validate, Error, Positions}, UserNotification, }; @@ -74,11 +75,18 @@ impl Handler for RepoActor { }, git_log, )) => { - debug!(%main, %next, %dev, "positions"); + info!(%main, %next, %dev, "positions"); self.update_tui_log(git_log); if next_is_valid && next != main { + info!("Checking CI"); + self.update_tui(RepoUpdate::CheckingCI); do_send(&ctx.address(), CheckCIStatus::new(next), self.log.as_ref()); } else if next != dev { + info!("Advance next"); + self.update_tui(RepoUpdate::AdvancingNext { + commit: next.clone(), + force: Force::No, + }); do_send( &ctx.address(), AdvanceNext::new(AdvanceNextPayload { @@ -89,10 +97,12 @@ impl Handler for RepoActor { self.log.as_ref(), ); } else { + info!("do nothing"); self.update_tui(RepoUpdate::Okay { main, next, dev }); } } Err(Error::Retryable(message)) => { + info!(?message, "Retryable"); self.alert_tui(format!("[retryable: {message}]")); logger(self.log.as_ref(), message); let addr = ctx.address(); @@ -100,7 +110,7 @@ impl Handler for RepoActor { let sleep_duration = self.sleep_duration; let log = self.log.clone(); async move { - debug!("sleeping before retrying..."); + info!("sleeping before retrying..."); logger(log.as_ref(), "before sleep"); actix_rt::time::sleep(sleep_duration).await; logger(log.as_ref(), "after sleep"); @@ -111,6 +121,7 @@ impl Handler for RepoActor { .wait(ctx); } Err(Error::UserIntervention(user_notification)) => { + info!(?user_notification, "User Intervention"); self.alert_tui(format!("[USER INTERVENTION: {user_notification}]")); if let UserNotification::CICheckFailed { log, .. } | UserNotification::DevNotBasedOnMain { log, .. } = &user_notification @@ -124,6 +135,7 @@ impl Handler for RepoActor { ); } Err(Error::NonRetryable(message)) => { + info!(?message, "NonRetryable"); self.alert_tui(format!("[Error: {message}]")); logger(self.log.as_ref(), message); } diff --git a/crates/cli/src/repo/mod.rs b/crates/cli/src/repo/mod.rs index 32105a6..391ba1a 100644 --- a/crates/cli/src/repo/mod.rs +++ b/crates/cli/src/repo/mod.rs @@ -7,7 +7,6 @@ use crate::{ }; use derive_more::Deref; use kxio::network::Network; -use std::time::Duration; use tracing::{info, instrument, warn, Instrument}; use git_next_core::{ @@ -172,19 +171,6 @@ impl Actor for RepoActor { } } -pub fn delay_send(addr: &Addr, delay: Duration, msg: M, log: Option<&ActorLog>) -where - M: actix::Message + Send + 'static + std::fmt::Debug, - RepoActor: actix::Handler, - ::Result: Send, -{ - let log_message = format!("send-after-delay: {msg:?}"); - tracing::debug!(log_message); - logger(log, log_message); - std::thread::sleep(delay); - do_send(addr, msg, log); -} - pub fn do_send(addr: &Addr, msg: M, log: Option<&ActorLog>) where M: actix::Message + Send + 'static + std::fmt::Debug, @@ -192,7 +178,7 @@ where ::Result: Send, { let log_message = format!("send: {msg:?}"); - tracing::debug!(log_message); + info!(log_message); logger(log, log_message); if cfg!(not(test)) { // #[cfg(not(test))] diff --git a/crates/cli/src/repo/tests/handlers/advance_next.rs b/crates/cli/src/repo/tests/handlers/advance_next.rs index f5168e3..44ae8f6 100644 --- a/crates/cli/src/repo/tests/handlers/advance_next.rs +++ b/crates/cli/src/repo/tests/handlers/advance_next.rs @@ -1,9 +1,11 @@ +use std::time::Duration; + use crate::repo::messages::AdvanceNextPayload; // use super::*; -#[actix::test] +#[test_log::test(actix::test)] async fn should_fetch_then_push_then_revalidate() -> TestResult { //given let fs = given::a_filesystem(); @@ -41,14 +43,11 @@ async fn should_fetch_then_push_then_revalidate() -> TestResult { }, )) .await?; + actix_rt::time::sleep(Duration::from_millis(1)).await; System::current().stop(); //then tracing::debug!(?log, ""); - log.read().map_err(|e| e.to_string()).map(|l| { - assert!(l - .iter() - .any(|message| message.contains("send: ValidateRepo"))); - })?; + log.require_message_containing("send: ValidateRepo")?; Ok(()) } diff --git a/crates/cli/src/repo/tests/handlers/receive_ci_status.rs b/crates/cli/src/repo/tests/handlers/receive_ci_status.rs index d564349..79a9439 100644 --- a/crates/cli/src/repo/tests/handlers/receive_ci_status.rs +++ b/crates/cli/src/repo/tests/handlers/receive_ci_status.rs @@ -1,3 +1,5 @@ +use std::time::Duration; + // use super::*; @@ -79,7 +81,7 @@ async fn when_fail_should_recheck_after_delay() -> TestResult { git::forge::commit::Status::Fail, ))) .await?; - actix_rt::time::sleep(std::time::Duration::from_millis(2)).await; + actix_rt::time::sleep(Duration::from_millis(20)).await; System::current().stop(); //then diff --git a/crates/cli/src/server/actor/messages.rs b/crates/cli/src/server/actor/messages.rs index 552897d..ed5503c 100644 --- a/crates/cli/src/server/actor/messages.rs +++ b/crates/cli/src/server/actor/messages.rs @@ -70,7 +70,7 @@ pub enum RepoUpdate { }, CheckingCI, AdvancingNext { - commit: Option, + commit: git::Commit, force: git::push::Force, }, AdvancingMain { diff --git a/crates/cli/src/tui/actor/handlers/server_update.rs b/crates/cli/src/tui/actor/handlers/server_update.rs index ec43830..1ff9c5a 100644 --- a/crates/cli/src/tui/actor/handlers/server_update.rs +++ b/crates/cli/src/tui/actor/handlers/server_update.rs @@ -47,10 +47,9 @@ impl Handler for Tui { RepoUpdate::CheckingCI => { repo_state.update_message("Checking CI status"); } - RepoUpdate::AdvancingNext { - commit: _, - force: _, - } => (), + RepoUpdate::AdvancingNext { commit, force: _ } => { + repo_state.update_message(format!("advancing next to {commit}")); + } RepoUpdate::AdvancingMain { commit } => { repo_state.update_message(format!("advancing main to {commit}")); } diff --git a/crates/cli/src/tui/actor/model.rs b/crates/cli/src/tui/actor/model.rs index 0d77fd5..b64e740 100644 --- a/crates/cli/src/tui/actor/model.rs +++ b/crates/cli/src/tui/actor/model.rs @@ -233,12 +233,12 @@ impl RepoState { #[tracing::instrument] pub fn update_message(&mut self, msg: impl Into + std::fmt::Debug) { - tracing::info!("new tui message"); let msg: String = msg.into(); match self { Self::Identified { message, .. } | Self::Configured { message, .. } | Self::Ready { message, .. } => { + info!(?msg, "updating ui"); *message = msg; } }