From 690098d7c7cad55b09d4ed279a3a255eec04c919 Mon Sep 17 00:00:00 2001 From: Lucas Schwiderski Date: Sun, 9 Apr 2023 14:33:55 +0200 Subject: [PATCH] feat(dtmm): Improve debug logging This re-enables stdout/stderr logging for release binaries for DTMM. As a GUI application, it usually won't be started from a CLI, and there should be no negative impact from that. But since stdout logging is synchronous and much faster than the async action that writes to the log file, it might get to log more when the application panics. --- crates/dtmm/src/controller/app.rs | 17 +++++++++++------ crates/dtmm/src/controller/game.rs | 21 +++++++++++++++++++++ crates/dtmm/src/controller/worker.rs | 2 ++ crates/dtmm/src/main.rs | 24 ++++++++++++++---------- crates/dtmm/src/state/delegate.rs | 21 +++++++++++++++++++++ crates/dtmm/src/util/log.rs | 7 +------ lib/sdk/src/filetype/lua.rs | 6 ++++++ 7 files changed, 76 insertions(+), 22 deletions(-) diff --git a/crates/dtmm/src/controller/app.rs b/crates/dtmm/src/controller/app.rs index d732801..5c5d980 100644 --- a/crates/dtmm/src/controller/app.rs +++ b/crates/dtmm/src/controller/app.rs @@ -321,12 +321,17 @@ pub(crate) fn check_mod_order(state: &ActionState) -> Result<()> { } } - state - .mods - .iter() - .filter(|i| i.enabled) - .enumerate() - .for_each(|(i, info)| tracing::debug!(i, ?info)); + if tracing::enabled!(tracing::Level::DEBUG) { + let order = state.mods.iter().filter(|i| i.enabled).enumerate().fold( + String::new(), + |mut s, (i, info)| { + s.push_str(&format!("{}: {} - {}\n", i, info.id, info.name)); + s + }, + ); + + tracing::debug!("Mod order:\n{}", order); + } for (i, mod_info) in state.mods.iter().filter(|i| i.enabled).enumerate() { for dep in &mod_info.depends { diff --git a/crates/dtmm/src/controller/game.rs b/crates/dtmm/src/controller/game.rs index d83d361..4f5633e 100644 --- a/crates/dtmm/src/controller/game.rs +++ b/crates/dtmm/src/controller/game.rs @@ -212,16 +212,25 @@ async fn build_bundles(state: Arc) -> Result> { let mut bundles = Vec::new(); { + tracing::trace!("Building mod data script"); + let span = tracing::debug_span!("Building mod data script"); let _enter = span.enter(); let lua = build_mod_data_lua(state.clone()); + + tracing::trace!("Compiling mod data script"); + let file = lua::compile(MOD_DATA_SCRIPT, &lua).wrap_err("Failed to compile mod data Lua file")?; + tracing::trace!("Compile mod data script"); + mod_bundle.add_file(file); } + tracing::trace!("Preparing tasks to deploy bundle files"); + for mod_info in state.mods.iter().filter(|m| m.id != "dml" && m.enabled) { let span = tracing::trace_span!("building mod packages", name = mod_info.name); let _enter = span.enter(); @@ -231,6 +240,12 @@ async fn build_bundles(state: Arc) -> Result> { let span = tracing::trace_span!("building package", name = pkg_info.name); let _enter = span.enter(); + tracing::trace!( + "Building package {} for mod {}", + pkg_info.name, + mod_info.name + ); + let pkg = make_package(pkg_info).wrap_err("Failed to make package")?; let mut variant = BundleFileVariant::new(); let bin = pkg @@ -240,6 +255,12 @@ async fn build_bundles(state: Arc) -> Result> { let mut file = BundleFile::new(pkg_info.name.clone(), BundleFileType::Package); file.add_variant(variant); + tracing::trace!( + "Compiled package {} for mod {}", + pkg_info.name, + mod_info.name + ); + mod_bundle.add_file(file); let bundle_name = format!("{:016x}", Murmur64::hash(&pkg_info.name)); diff --git a/crates/dtmm/src/controller/worker.rs b/crates/dtmm/src/controller/worker.rs index db3c0f8..238b3f3 100644 --- a/crates/dtmm/src/controller/worker.rs +++ b/crates/dtmm/src/controller/worker.rs @@ -36,6 +36,8 @@ async fn handle_action( action_queue: Arc>>, ) { while let Some(action) = action_queue.write().await.recv().await { + tracing::debug!(?action); + let event_sink = event_sink.clone(); match action { AsyncAction::DeployMods(state) => tokio::spawn(async move { diff --git a/crates/dtmm/src/main.rs b/crates/dtmm/src/main.rs index f60bfd8..9ba838c 100644 --- a/crates/dtmm/src/main.rs +++ b/crates/dtmm/src/main.rs @@ -8,7 +8,7 @@ use std::sync::Arc; use clap::parser::ValueSource; use clap::{command, value_parser, Arg}; -use color_eyre::eyre; +use color_eyre::eyre::{self, Context}; use color_eyre::{Report, Result}; use druid::AppLauncher; use tokio::sync::RwLock; @@ -83,16 +83,20 @@ fn main() -> Result<()> { let event_sink = launcher.get_external_handle(); - std::thread::spawn(move || { - let event_sink = Arc::new(RwLock::new(event_sink)); - let action_rx = Arc::new(RwLock::new(action_rx)); - let log_rx = Arc::new(RwLock::new(log_rx)); - loop { - if let Err(err) = work_thread(event_sink.clone(), action_rx.clone(), log_rx.clone()) { - tracing::error!("Work thread failed, restarting: {:?}", err); + std::thread::Builder::new() + .name("work-thread".into()) + .spawn(move || { + let event_sink = Arc::new(RwLock::new(event_sink)); + let action_rx = Arc::new(RwLock::new(action_rx)); + let log_rx = Arc::new(RwLock::new(log_rx)); + loop { + if let Err(err) = work_thread(event_sink.clone(), action_rx.clone(), log_rx.clone()) + { + tracing::error!("Work thread failed, restarting: {:?}", err); + } } - } - }); + }) + .wrap_err("Work thread panicked")?; launcher.launch(State::new()).map_err(Report::new) } diff --git a/crates/dtmm/src/state/delegate.rs b/crates/dtmm/src/state/delegate.rs index d5ae042..2e12bd0 100644 --- a/crates/dtmm/src/state/delegate.rs +++ b/crates/dtmm/src/state/delegate.rs @@ -95,6 +95,27 @@ pub(crate) enum AsyncAction { Log((ActionState, Vec)), } +impl std::fmt::Debug for AsyncAction { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + AsyncAction::DeployMods(_) => write!(f, "AsyncAction::DeployMods(_state)"), + AsyncAction::ResetDeployment(_) => write!(f, "AsyncAction::ResetDeployment(_state)"), + AsyncAction::AddMod(_, info) => write!(f, "AsyncAction::AddMod(_state, {:?})", info), + AsyncAction::DeleteMod(_, info) => { + write!(f, "AsyncAction::DeleteMod(_state, {:?})", info) + } + AsyncAction::SaveSettings(_) => write!(f, "AsyncAction::SaveSettings(_state)"), + AsyncAction::CheckUpdates(_) => write!(f, "AsyncAction::CheckUpdates(_state)"), + AsyncAction::LoadInitial((path, is_default)) => write!( + f, + "AsyncAction::LoadInitial(({:?}, {:?}))", + path, is_default + ), + AsyncAction::Log(_) => write!(f, "AsyncAction::Log(_)"), + } + } +} + pub(crate) struct Delegate { sender: UnboundedSender, } diff --git a/crates/dtmm/src/util/log.rs b/crates/dtmm/src/util/log.rs index b01ef5f..09fc9a6 100644 --- a/crates/dtmm/src/util/log.rs +++ b/crates/dtmm/src/util/log.rs @@ -64,12 +64,7 @@ pub fn create_tracing_subscriber(tx: UnboundedSender>, level: Option