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

@@ -321,12 +321,17 @@ pub(crate) fn check_mod_order(state: &ActionState) -> Result<()> {
         }
     }
 
-    state
+    if tracing::enabled!(tracing::Level::DEBUG) {
-        .mods
+        let order = state.mods.iter().filter(|i| i.enabled).enumerate().fold(
-        .iter()
+            String::new(),
-        .filter(|i| i.enabled)
+            |mut s, (i, info)| {
-        .enumerate()
+                s.push_str(&format!("{}: {} - {}\n", i, info.id, info.name));
-        .for_each(|(i, info)| tracing::debug!(i, ?info));
+                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 {

crates/dtmm/src/controller/game.rs

@@ -212,16 +212,25 @@ async fn build_bundles(state: Arc<ActionState>) -> Result<Vec<Bundle>> {
     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<ActionState>) -> Result<Vec<Bundle>> {
             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<ActionState>) -> Result<Vec<Bundle>> {
             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));

crates/dtmm/src/controller/worker.rs

@@ -36,6 +36,8 @@ async fn handle_action(
     action_queue: Arc<RwLock<UnboundedReceiver<AsyncAction>>>,
 ) {
     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 {

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 || {
+    std::thread::Builder::new()
-        let event_sink = Arc::new(RwLock::new(event_sink));
+        .name("work-thread".into())
-        let action_rx = Arc::new(RwLock::new(action_rx));
+        .spawn(move || {
-        let log_rx = Arc::new(RwLock::new(log_rx));
+            let event_sink = Arc::new(RwLock::new(event_sink));
-        loop {
+            let action_rx = Arc::new(RwLock::new(action_rx));
-            if let Err(err) = work_thread(event_sink.clone(), action_rx.clone(), log_rx.clone()) {
+            let log_rx = Arc::new(RwLock::new(log_rx));
-                tracing::error!("Work thread failed, restarting: {:?}", err);
+            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)
 }

crates/dtmm/src/state/delegate.rs

@@ -95,6 +95,27 @@ pub(crate) enum AsyncAction {
     Log((ActionState, Vec<u8>)),
 }
 
+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<AsyncAction>,
 }

crates/dtmm/src/util/log.rs

@@ -64,12 +64,7 @@ pub fn create_tracing_subscriber(tx: UnboundedSender<Vec<u8>>, level: Option<Log
         EnvFilter::new("error,dtmm=info")
     };
 
-    let stdout_layer = if cfg!(debug_assertions) {
+    let stdout_layer = fmt::layer().pretty();
-        let layer = fmt::layer().pretty();
-        Some(layer)
-    } else {
-        None
-    };
 
     let channel_layer = fmt::layer()
         .event_format(dtmt_shared::Formatter)

lib/sdk/src/filetype/lua.rs

@@ -30,6 +30,12 @@ where
     let name = name.into();
     let code = code.as_ref();
 
+    tracing::trace!(
+        "Compiling '{}', {} bytes of code",
+        name,
+        code.as_bytes().len()
+    );
+
     let bytecode = unsafe {
         let state = lua::luaL_newstate();
         lua::luaL_openlibs(state);