Migrate to proper logging

src/gui/message.rs

@@ -11,6 +11,7 @@ use tokio::{
     sync::mpsc::{self, Sender},
     task::JoinHandle,
 };
+use tracing::{error, info};
 
 use crate::state::{ModData_v0_1_0 as ModData, ModOrGroup};
 use crate::{
@@ -155,7 +156,7 @@ impl ResolveMods {
                             LastActionStatus::Failure("no provider".to_string());
                     }
                     Err(e) => {
-                        app.log.println(format!("{:#?}\n{}", e, e.backtrace()));
+                        error!("{:#?}\n{}", e, e.backtrace());
                         app.last_action_status = LastActionStatus::Failure(e.to_string());
                     }
                 },
@@ -197,7 +198,7 @@ impl Integrate {
         if Some(self.rid) == app.integrate_rid.as_ref().map(|r| r.rid) {
             match self.result {
                 Ok(()) => {
-                    app.log.println("Integration complete");
+                    info!("integration complete");
                     app.last_action_status =
                         LastActionStatus::Success("integration complete".to_string());
                 }
@@ -209,7 +210,7 @@ impl Integrate {
                             LastActionStatus::Failure("no provider".to_string());
                     }
                     Err(e) => {
-                        app.log.println(format!("{:#?}\n{}", e, e.backtrace()));
+                        error!("{:#?}\n{}", e, e.backtrace());
                         app.last_action_status = LastActionStatus::Failure(e.to_string());
                     }
                 },
@@ -265,7 +266,7 @@ impl UpdateCache {
         if Some(self.rid) == app.update_rid.as_ref().map(|r| r.rid) {
             match self.result {
                 Ok(()) => {
-                    app.log.println("Cache update complete");
+                    info!("cache update complete");
                     app.last_action_status =
                         LastActionStatus::Success("successfully updated cache".to_string());
                 }
@@ -278,7 +279,7 @@ impl UpdateCache {
                             LastActionStatus::Failure("no provider".to_string());
                     }
                     Err(e) => {
-                        app.log.println(format!("{:#?}", e));
+                        error!("{:#?}\n{}", e, e.backtrace());
                         app.last_action_status = LastActionStatus::Failure(e.to_string());
                     }
                 },

src/gui/mod.rs

@@ -1,5 +1,4 @@
 mod find_string;
-mod log;
 mod message;
 mod named_combobox;
 mod request_counter;
@@ -21,6 +20,7 @@ use tokio::{
     sync::mpsc::{self, Receiver, Sender},
     task::JoinHandle,
 };
+use tracing::{debug, info};
 
 use crate::state::ModOrGroup;
 use crate::{
@@ -31,7 +31,6 @@ use crate::{
     state::{ModConfig, ModData_v0_1_0 as ModData, State},
 };
 use find_string::FindString;
-use log::Log;
 use message::MessageHandle;
 use request_counter::{RequestCounter, RequestID};
 
@@ -57,7 +56,6 @@ pub struct App {
     tx: Sender<message::Message>,
     rx: Receiver<message::Message>,
     state: State,
-    log: Log,
     resolve_mod: String,
     resolve_mod_rid: Option<MessageHandle<()>>,
     integrate_rid: Option<MessageHandle<HashMap<ModSpecification, SpecFetchProgress>>>,
@@ -84,24 +82,16 @@ enum LastActionStatus {
 impl App {
     fn new(args: Option<Vec<String>>) -> Result<Self> {
         let (tx, rx) = mpsc::channel(10);
-        let mut log = Log::default();
         let state = State::init()?;
-        log.println(format!(
-            "config dir: {}",
-            state.project_dirs.config_dir().display()
-        ));
-        log.println(format!(
-            "cache dir: {}",
-            state.project_dirs.cache_dir().display()
-        ));
+        info!("config dir = {}", state.project_dirs.config_dir().display());
+        info!("cache dir = {}", state.project_dirs.cache_dir().display());
 
         Ok(Self {
             args,
             tx,
             rx,
             request_counter: Default::default(),
             state,
-            log,
             resolve_mod: Default::default(),
             resolve_mod_rid: None,
             integrate_rid: None,
@@ -819,6 +809,7 @@ impl eframe::App for App {
                                         }
                                     });
 
+                                    debug!("uninstalling mods: pak_path = {}", pak_path.display());
                                     match uninstall(pak_path, mods) {
                                         Ok(()) => {
                                             self.last_action_status =

src/integrate.rs

@@ -6,6 +6,7 @@ use std::path::{Path, PathBuf};
 
 use anyhow::{Context, Result};
 use repak::PakWriter;
+use tracing::info;
 
 use crate::providers::{ModInfo, ReadSeek};
 use crate::splice::TrackedStatement;
@@ -39,6 +40,7 @@ use unreal_asset::{
 /// back to the config so they will be disabled when the game is launched again. Since we have
 /// Modio IDs anyway, with just a little more effort we can make the 'uninstall' button work as an
 /// 'install' button for the official integration. Best anti-feature ever.
+#[tracing::instrument(level = "debug", skip(path_pak))]
 pub fn uninstall<P: AsRef<Path>>(path_pak: P, modio_mods: HashSet<u32>) -> Result<()> {
     let installation = DRGInstallation::from_pak_path(path_pak)?;
     let path_mods_pak = installation.paks_path().join("mods_P.pak");
@@ -59,6 +61,7 @@ pub fn uninstall<P: AsRef<Path>>(path_pak: P, modio_mods: HashSet<u32>) -> Resul
     Ok(())
 }
 
+#[tracing::instrument(level = "debug")]
 fn uninstall_modio(installation: &DRGInstallation, modio_mods: HashSet<u32>) -> Result<()> {
     #[derive(Debug, serde::Deserialize)]
     struct ModioState {
@@ -419,7 +422,7 @@ pub fn integrate<P: AsRef<Path>>(path_pak: P, mods: Vec<(ModInfo, PathBuf)>) ->
 
     mod_pak.write_index()?;
 
-    println!(
+    info!(
         "{} mods installed to {}",
         mods.len(),
         path_mod_pak.display()

src/lib.rs

@@ -17,11 +17,14 @@ use anyhow::{bail, Context, Result};
 use error::IntegrationError;
 use providers::{ModSpecification, ProviderFactory};
 use state::State;
+use tracing::{info, warn};
 
+#[derive(Debug)]
 pub enum DRGInstallationType {
     Steam,
     Xbox,
 }
+
 impl DRGInstallationType {
     pub fn from_pak_path<P: AsRef<Path>>(pak: P) -> Result<Self> {
         let pak_name = pak
@@ -50,6 +53,7 @@ impl DRGInstallationType {
     }
 }
 
+#[derive(Debug)]
 pub struct DRGInstallation {
     pub root: PathBuf,
     pub installation_type: DRGInstallationType,
@@ -139,6 +143,7 @@ pub fn is_drg_pak<P: AsRef<Path>>(path: P) -> Result<()> {
     Ok(())
 }
 
+#[tracing::instrument(level = "debug", skip(path_game, state))]
 pub async fn resolve_and_integrate<P: AsRef<Path>>(
     path_game: P,
     state: &State,
@@ -163,9 +168,9 @@ pub async fn resolve_and_integrate<P: AsRef<Path>>(
         })
         .collect::<HashSet<_>>();
     if !missing_deps.is_empty() {
-        println!("WARNING: The following dependencies are missing:");
+        warn!("the following dependencies are missing:");
         for d in missing_deps {
-            println!("  {d}");
+            warn!("  {d}");
         }
     }
 
@@ -178,12 +183,13 @@ pub async fn resolve_and_integrate<P: AsRef<Path>>(
         .map(|m| &m.resolution)
         .collect::<Vec<_>>();
 
-    println!("fetching mods...");
+    info!("fetching mods...");
     let paths = state.store.fetch_mods(&urls, update, None).await?;
 
     integrate::integrate(path_game, to_integrate.into_iter().zip(paths).collect())
 }
 
+#[tracing::instrument(level = "debug", skip(path_game, state, init))]
 pub async fn resolve_and_integrate_with_provider_init<P, F>(
     path_game: P,
     state: &mut State,

src/main.rs

@@ -83,11 +83,14 @@ struct Args {
 fn main() -> Result<()> {
     std::env::set_var("RUST_BACKTRACE", "1");
     let _guard = setup_logging()?;
+    debug!("logging setup complete");
 
     let rt = tokio::runtime::Runtime::new().expect("Unable to create Runtime");
+    debug!("tokio runtime created");
     let _enter = rt.enter();
 
     let args = Args::parse();
+    debug!(?args);
 
     match args.action {
         Some(Action::Integrate(action)) => rt.block_on(async {
@@ -153,9 +156,7 @@ fn setup_logging() -> Result<WorkerGuard> {
         .with_writer(log_file_appender)
         .fmt_fields(NewType(Pretty::default()))
         .with_ansi(false)
-        .with_filter(filter::filter_fn(|metadata| {
-            *metadata.level() <= Level::DEBUG && metadata.target() == "drg_mod_integration"
-        }));
+        .with_filter(filter::Targets::new().with_target("drg_mod_integration", Level::DEBUG));
     let stdout_log = fmt::layer()
         .compact()
         .with_level(true)
@@ -184,8 +185,10 @@ fn setup_logging() -> Result<WorkerGuard> {
     Ok(guard)
 }
 
+#[tracing::instrument(skip(state))]
 fn init_provider(state: &mut State, url: String, factory: &ProviderFactory) -> Result<()> {
-    println!("Initializing provider for {:?}", url);
+    info!("initializing provider for {:?}", url);
+
     let params = state
         .config
         .provider_parameters
@@ -205,6 +208,7 @@ fn init_provider(state: &mut State, url: String, factory: &ProviderFactory) -> R
     state.store.add_provider(factory, params)
 }
 
+#[tracing::instrument]
 async fn action_integrate(action: ActionIntegrate) -> Result<()> {
     let path_game_pak = action
         .fsd_pak
@@ -214,6 +218,7 @@ async fn action_integrate(action: ActionIntegrate) -> Result<()> {
                 .map(DRGInstallation::main_pak)
         })
         .context("Could not find DRG pak file, please specify manually with the --fsd_pak flag")?;
+    debug!(?path_game_pak);
 
     let mut state = State::init()?;
 
@@ -233,6 +238,7 @@ async fn action_integrate(action: ActionIntegrate) -> Result<()> {
     .await
 }
 
+#[tracing::instrument]
 async fn action_integrate_profile(action: ActionIntegrateProfile) -> Result<()> {
     let path_game_pak = action
         .fsd_pak
@@ -242,6 +248,7 @@ async fn action_integrate_profile(action: ActionIntegrateProfile) -> Result<()>
                 .map(DRGInstallation::main_pak)
         })
         .context("Could not find DRG pak file, please specify manually with the --fsd_pak flag")?;
+    debug!(?path_game_pak);
 
     let mut state = State::init()?;
 

src/providers/http.rs

@@ -4,6 +4,7 @@ use std::{collections::HashMap, sync::Arc};
 use anyhow::{bail, Result};
 use serde::{Deserialize, Serialize};
 use tokio::sync::mpsc::Sender;
+use tracing::info;
 
 use super::{
     BlobCache, BlobRef, FetchProgress, ModInfo, ModProvider, ModProviderCache, ModResolution,
@@ -122,7 +123,7 @@ impl ModProvider for HttpProvider {
                 }
                 path
             } else {
-                println!("downloading mod {url}...");
+                info!("downloading mod {url}...");
                 let response = self.client.get(url).send().await?.error_for_status()?;
                 let size = response.content_length(); // TODO will be incorrect if compressed
                 if let Some(mime) = response

src/providers/modio.rs

@@ -8,6 +8,7 @@ use reqwest_middleware::{Middleware, Next};
 use serde::{Deserialize, Serialize};
 use task_local_extensions::Extensions;
 use tokio::sync::mpsc::Sender;
+use tracing::info;
 
 use super::{
     ApprovalStatus, BlobCache, BlobRef, FetchProgress, ModInfo, ModProvider, ModProviderCache,
@@ -176,16 +177,16 @@ impl Middleware for LoggingMiddleware {
         next: Next<'_>,
     ) -> reqwest_middleware::Result<Response> {
         loop {
-            println!(
-                "Request started {} {:?}",
+            info!(
+                "request started {} {:?}",
                 self.requests
                     .fetch_add(1, std::sync::atomic::Ordering::Relaxed),
                 req.url().path()
             );
             let res = next.clone().run(req.try_clone().unwrap(), extensions).await;
             if let Ok(res) = &res {
                 if let Some(retry) = res.headers().get("retry-after") {
-                    println!("retrying after: {}...", retry.to_str().unwrap());
+                    info!("retrying after: {}...", retry.to_str().unwrap());
                     tokio::time::sleep(tokio::time::Duration::from_secs(
                         retry.to_str().unwrap().parse::<u64>().unwrap(),
                     ))
@@ -510,7 +511,7 @@ impl ModProvider for ModioProvider {
                     let size = file.filesize;
                     let download: modio::download::DownloadAction = file.into();
 
-                    println!("downloading mod {url}...");
+                    info!("downloading mod {url}...");
 
                     use futures::stream::TryStreamExt;
                     use tokio::io::AsyncWriteExt;

src/splice.rs

@@ -90,13 +90,13 @@ pub fn read_asset<P: AsRef<Path>>(
     let mut out_uexp = Cursor::new(vec![]);
     asset.write_data(&mut out_uasset, Some(&mut out_uexp))?;
     if uasset.get_ref() != out_uasset.get_ref() || uexp.get_ref() != out_uexp.get_ref() {
-        println!(
-            "Binary equality not maintained: {}",
+        error!(
+            "binary equality not maintained: {}",
             path.as_ref().display()
         );
     } else {
-        println!(
-            "Preliminary binary equality check passed {}",
+        info!(
+            "preliminary binary equality check passed {}",
             path.as_ref().display()
         );
     }
@@ -741,7 +741,6 @@ fn resolve_tracked_statements<C: std::io::Read + std::io::Seek>(
 
     inst.into_iter()
         .map(|mut inst| {
-            //println!( "{:?} {} {:#?}", pi, export.get_base_export().object_name.get_content(), mappings.get(&pi));
             let dest = inst.points_to.as_ref().unwrap_or(&inst.origin);
             match &mut inst.ex {
                 // fix jumps into ubergraph
@@ -980,7 +979,7 @@ pub fn find_hooks<'a, C: std::io::Read + std::io::Seek>(
     /*
     for (a, bs) in &jumps {
         for b in bs {
-            println!("{}:{} -> {}:{}", a.0.index, a.1, b.0.index, b.1);
+            trace!("{}:{} -> {}:{}", a.0.index, a.1, b.0.index, b.1);
         }
     }
     */