Replace dbg macros with tracing events

Cargo.lock

@@ -28,6 +28,15 @@ dependencies = [
  "memchr",
 ]
 
+[[package]]
+name = "ansi_term"
+version = "0.12.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2"
+dependencies = [
+ "winapi",
+]
+
 [[package]]
 name = "anyhow"
 version = "1.0.40"
@@ -905,6 +914,15 @@ dependencies = [
  "tendril",
 ]
 
+[[package]]
+name = "matchers"
+version = "0.0.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1"
+dependencies = [
+ "regex-automata",
+]
+
 [[package]]
 name = "matches"
 version = "0.1.8"
@@ -987,6 +1005,9 @@ dependencies = [
  "tempfile",
  "tokio",
  "tokio-util",
+ "tracing",
+ "tracing-appender",
+ "tracing-subscriber",
  "unrar",
  "zip",
 ]
@@ -1514,6 +1535,15 @@ dependencies = [
  "regex-syntax",
 ]
 
+[[package]]
+name = "regex-automata"
+version = "0.1.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132"
+dependencies = [
+ "regex-syntax",
+]
+
 [[package]]
 name = "regex-syntax"
 version = "0.6.25"
@@ -1736,6 +1766,15 @@ dependencies = [
  "opaque-debug",
 ]
 
+[[package]]
+name = "sharded-slab"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "79c719719ee05df97490f80a45acfc99e5a30ce98a1e4fb67aee422745ae14e3"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "signal-hook-registry"
 version = "1.3.0"
@@ -2010,6 +2049,15 @@ dependencies = [
  "syn",
 ]
 
+[[package]]
+name = "thread_local"
+version = "1.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8018d24e04c95ac8790716a5987d0fec4f8b27249ffa0f7d33f1369bdfb88cbd"
+dependencies = [
+ "once_cell",
+]
+
 [[package]]
 name = "time"
 version = "0.1.43"
@@ -2116,9 +2164,32 @@ checksum = "09adeb8c97449311ccd28a427f96fb563e7fd31aabf994189879d9da2394b89d"
 dependencies = [
  "cfg-if",
  "pin-project-lite",
+ "tracing-attributes",
  "tracing-core",
 ]
 
+[[package]]
+name = "tracing-appender"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9965507e507f12c8901432a33e31131222abac31edd90cabbcf85cf544b7127a"
+dependencies = [
+ "chrono",
+ "crossbeam-channel",
+ "tracing-subscriber",
+]
+
+[[package]]
+name = "tracing-attributes"
+version = "0.1.15"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c42e6fa53307c8a17e4ccd4dc81cf5ec38db9209f59b222210375b54ee40d1e2"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.18"
@@ -2128,6 +2199,49 @@ dependencies = [
  "lazy_static",
 ]
 
+[[package]]
+name = "tracing-log"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3"
+dependencies = [
+ "lazy_static",
+ "log",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-serde"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b"
+dependencies = [
+ "serde",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.2.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ab69019741fca4d98be3c62d2b75254528b5432233fd8a4d2739fec20278de48"
+dependencies = [
+ "ansi_term",
+ "chrono",
+ "lazy_static",
+ "matchers",
+ "regex",
+ "serde",
+ "serde_json",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing",
+ "tracing-core",
+ "tracing-log",
+ "tracing-serde",
+]
+
 [[package]]
 name = "try-lock"
 version = "0.2.3"

Cargo.toml

@@ -26,6 +26,9 @@ skyrim-cell-dump = "0.1.3"
 tempfile = "3.2"
 tokio = { version = "1.5.0", features = ["full"] }
 tokio-util = { version = "0.6", features = ["compat"] }
+tracing = "0.1"
+tracing-appender = "0.1"
+tracing-subscriber = "0.2"
 unrar = "0.4"
 # Need `ZipWriter::append_new` from https://github.com/zip-rs/zip/commit/ce272616ac69b798bb7b0925147a8a710dc2bb65
 zip = { git = "https://github.com/zip-rs/zip.git" }

src/main.rs

@@ -12,6 +12,7 @@ use std::time::Duration;
 use tempfile::tempdir;
 use tokio::io::{AsyncReadExt, AsyncSeekExt};
 use tokio::time::sleep;
+use tracing::{debug, error, info, instrument, warn};
 use unrar::Archive;
 use zip::write::{FileOptions, ZipWriter};
 
@@ -27,6 +28,7 @@ use models::plugin::insert_plugin;
 use models::plugin_cell::insert_plugin_cell;
 use nexus_api::{GAME_ID, GAME_NAME};
 
+#[instrument(level = "debug", skip(plugin_buf, pool, plugin_archive, db_file, mod_obj), fields(name = ?mod_obj.name, id = mod_obj.nexus_mod_id))]
 async fn process_plugin<W>(
     plugin_buf: &mut [u8],
     pool: &sqlx::Pool<sqlx::Postgres>,
@@ -39,6 +41,7 @@ where
     W: std::io::Write + std::io::Seek,
 {
     let plugin = parse_plugin(&plugin_buf)?;
+    info!(file_name, num_cells = plugin.cells.len(), "parsed plugin");
     let hash = seahash::hash(&plugin_buf);
     let plugin_row = insert_plugin(
         &pool,
@@ -100,6 +103,9 @@ fn initialize_plugins_archive(mod_id: i32, file_id: i32) -> Result<()> {
 #[tokio::main]
 pub async fn main() -> Result<()> {
     dotenv().ok();
+
+    tracing_subscriber::fmt::init();
+
     let pool = PgPoolOptions::new()
         .max_connections(5)
         .connect(&env::var("DATABASE_URL")?)
@@ -132,10 +138,13 @@ pub async fn main() -> Result<()> {
                 );
             }
         }
-        dbg!(mods.len());
 
         for db_mod in mods {
-            dbg!(&db_mod.name);
+            info!(
+                mod_name = ?&db_mod.name,
+                mod_id = ?&db_mod.nexus_mod_id,
+                "fetching files for mod"
+            );
             let files_resp = nexus_api::files::get(&client, db_mod.nexus_mod_id).await?;
             // TODO: download other files than just MAIN files
             // let files = files.into_iter().filter(|file| {
@@ -146,6 +155,7 @@ pub async fn main() -> Result<()> {
             //     }
             // });
             if let Some(duration) = files_resp.wait {
+                debug!(?duration, "sleeping");
                 sleep(duration).await;
             }
 
@@ -163,6 +173,8 @@ pub async fn main() -> Result<()> {
                 )
                 .await?;
 
+                // TODO: check the file metadata to see if there are any plugin files in the archive before bothering to download the file (checking metadata does not count against rate-limit)
+
                 let download_link_resp =
                     nexus_api::download_link::get(&client, db_mod.nexus_mod_id, api_file.file_id)
                         .await?;
@@ -180,7 +192,10 @@ pub async fn main() -> Result<()> {
                 tokio_file.seek(SeekFrom::Start(0)).await?;
                 tokio_file.read_exact(&mut initial_bytes).await?;
                 let kind = infer::get(&initial_bytes).expect("unknown file type of file download");
-                dbg!(kind.mime_type());
+                info!(
+                    mime_type = kind.mime_type(),
+                    "inferred mime_type of downloaded archive"
+                );
 
                 tokio_file.seek(SeekFrom::Start(0)).await?;
                 let mut file = tokio_file.try_clone().await?.into_std().await;
@@ -194,10 +209,17 @@ pub async fn main() -> Result<()> {
                         plugin_file_paths.push(file_name);
                     }
                 }
+                info!(
+                    num_plugin_files = plugin_file_paths.len(),
+                    "listed plugins in downloaded archive"
+                );
 
                 for file_name in plugin_file_paths.iter() {
                     file.seek(SeekFrom::Start(0))?;
-                    dbg!(file_name);
+                    info!(
+                        ?file_name,
+                        "attempting to uncompress file from downloaded archive"
+                    );
                     let mut buf = Vec::default();
                     match uncompress_archive_file(&mut file, &mut buf, file_name) {
                         Ok(_) => {
@@ -212,10 +234,14 @@ pub async fn main() -> Result<()> {
                             .await?;
                         }
                         Err(error) => {
-                            dbg!(error);
+                            warn!(
+                                ?error,
+                                "error occurred while attempting to uncompress archive file"
+                            );
                             if kind.mime_type() == "application/x-rar-compressed"
                                 || kind.mime_type() == "application/vnd.rar"
                             {
+                                info!("downloaded archive is RAR archive, attempt to uncompress entire archive instead");
                                 // Use unrar to uncompress the entire .rar file to avoid a bug with compress_tools panicking when uncompressing
                                 // certain .rar files: https://github.com/libarchive/libarchive/issues/373
                                 tokio_file.seek(SeekFrom::Start(0)).await?;
@@ -253,7 +279,10 @@ pub async fn main() -> Result<()> {
                                         .process()
                                         .expect("failed to extract");
                                     for file_name in plugin_file_paths.iter() {
-                                        dbg!(file_name);
+                                        info!(
+                                            ?file_name,
+                                            "processing uncompressed file from downloaded archive"
+                                        );
                                         let mut plugin_buf =
                                             std::fs::read(temp_dir.path().join(file_name))?;
                                         process_plugin(
@@ -269,20 +298,21 @@ pub async fn main() -> Result<()> {
                                 }
                                 temp_dir.close()?;
                             }
+                            error!(mime_type = ?kind.mime_type(), "downloaded archive is not RAR archive, skipping processing of this file");
                         }
                     }
                 }
 
                 plugins_archive.finish()?;
                 if let Some(duration) = download_link_resp.wait {
+                    debug!(?duration, "sleeping");
                     sleep(duration).await;
                 }
             }
         }
 
         page += 1;
-        dbg!(page);
+        debug!(?page, ?has_next_page, "sleeping 1 second");
-        dbg!(has_next_page);
         sleep(Duration::new(1, 0)).await;
     }
 

src/models/cell.rs

@@ -1,6 +1,7 @@
 use anyhow::{Context, Result};
 use chrono::NaiveDateTime;
 use serde::{Deserialize, Serialize};
+use tracing::instrument;
 
 #[derive(Debug, Serialize, Deserialize)]
 pub struct Cell {
@@ -13,6 +14,7 @@ pub struct Cell {
     pub created_at: NaiveDateTime,
 }
 
+#[instrument(level = "debug", skip(pool))]
 pub async fn insert_cell(
     pool: &sqlx::Pool<sqlx::Postgres>,
     form_id: i32,

src/models/file.rs

@@ -1,6 +1,7 @@
 use anyhow::{Context, Result};
 use chrono::NaiveDateTime;
 use serde::{Deserialize, Serialize};
+use tracing::instrument;
 
 #[derive(Debug, Serialize, Deserialize)]
 pub struct File {
@@ -17,6 +18,7 @@ pub struct File {
     pub created_at: NaiveDateTime,
 }
 
+#[instrument(level = "debug", skip(pool))]
 pub async fn insert_file(
     pool: &sqlx::Pool<sqlx::Postgres>,
     name: &str,

src/models/game.rs

@@ -1,6 +1,7 @@
 use anyhow::{Context, Result};
 use chrono::NaiveDateTime;
 use serde::{Deserialize, Serialize};
+use tracing::instrument;
 
 #[derive(Debug, Serialize, Deserialize)]
 pub struct Game {
@@ -11,6 +12,7 @@ pub struct Game {
     pub created_at: NaiveDateTime,
 }
 
+#[instrument(level = "debug", skip(pool))]
 pub async fn insert_game(
     pool: &sqlx::Pool<sqlx::Postgres>,
     name: &str,

src/models/game_mod.rs

@@ -1,6 +1,7 @@
 use anyhow::{Context, Result};
 use chrono::NaiveDateTime;
 use serde::{Deserialize, Serialize};
+use tracing::instrument;
 
 #[derive(Debug, Serialize, Deserialize)]
 pub struct Mod {
@@ -15,6 +16,7 @@ pub struct Mod {
     pub created_at: NaiveDateTime,
 }
 
+#[instrument(level = "debug", skip(pool))]
 pub async fn get_mod_by_nexus_mod_id(
     pool: &sqlx::Pool<sqlx::Postgres>,
     nexus_mod_id: i32,
@@ -29,6 +31,7 @@ pub async fn get_mod_by_nexus_mod_id(
     .context("Failed to get mod")
 }
 
+#[instrument(level = "debug", skip(pool))]
 pub async fn insert_mod(
     pool: &sqlx::Pool<sqlx::Postgres>,
     name: &str,

src/models/plugin.rs

@@ -1,6 +1,7 @@
 use anyhow::{Context, Result};
 use chrono::NaiveDateTime;
 use serde::{Deserialize, Serialize};
+use tracing::instrument;
 
 #[derive(Debug, Serialize, Deserialize)]
 pub struct Plugin {
@@ -16,6 +17,7 @@ pub struct Plugin {
     pub created_at: NaiveDateTime,
 }
 
+#[instrument(level = "debug", skip(pool))]
 pub async fn insert_plugin(
     pool: &sqlx::Pool<sqlx::Postgres>,
     name: &str,

src/models/plugin_cell.rs

@@ -1,7 +1,7 @@
 use anyhow::{Context, Result};
 use chrono::NaiveDateTime;
 use serde::{Deserialize, Serialize};
-
+use tracing::instrument;
 #[derive(Debug, Serialize, Deserialize)]
 pub struct PluginCell {
     pub id: i32,
@@ -12,6 +12,7 @@ pub struct PluginCell {
     pub created_at: NaiveDateTime,
 }
 
+#[instrument(level = "debug", skip(pool))]
 pub async fn insert_plugin_cell(
     pool: &sqlx::Pool<sqlx::Postgres>,
     plugin_id: i32,

src/nexus_api/download_link.rs

@@ -6,6 +6,7 @@ use std::{env, time::Duration};
 use tempfile::tempfile;
 use tokio::fs::File;
 use tokio_util::compat::FuturesAsyncReadCompatExt;
+use tracing::{info, instrument};
 
 use super::{rate_limit_wait_duration, GAME_NAME, USER_AGENT};
 
@@ -14,6 +15,7 @@ pub struct DownloadLinkResponse {
     json: Value,
 }
 
+#[instrument(skip(client))]
 pub async fn get(client: &Client, mod_id: i32, file_id: i64) -> Result<DownloadLinkResponse> {
     let res = client
         .get(format!(
@@ -27,6 +29,7 @@ pub async fn get(client: &Client, mod_id: i32, file_id: i64) -> Result<DownloadL
         .await?
         .error_for_status()?;
 
+    info!(status = %res.status(), "fetched file download link from API");
     let wait = rate_limit_wait_duration(&res)?;
     let json = res.json::<Value>().await?;
 
@@ -34,6 +37,7 @@ pub async fn get(client: &Client, mod_id: i32, file_id: i64) -> Result<DownloadL
 }
 
 impl DownloadLinkResponse {
+    #[instrument(skip(self))]
     pub fn link<'a>(&'a self) -> Result<&'a str> {
         let link = self
             .json
@@ -43,9 +47,11 @@ impl DownloadLinkResponse {
             .ok_or_else(|| anyhow!("Missing URI key in link in API response"))?
             .as_str()
             .ok_or_else(|| anyhow!("URI value in API response link is not a string"))?;
+        info!(link = %link, "parsed download link from API response");
         Ok(link)
     }
 
+    #[instrument(skip(self, client))]
     pub async fn download_file(&self, client: &Client) -> Result<File> {
         let mut tokio_file = File::from_std(tempfile()?);
         let res = client
@@ -55,6 +61,7 @@ impl DownloadLinkResponse {
             .send()
             .await?
             .error_for_status()?;
+        info!(status = %res.status(), "downloaded file from nexus");
 
         // See: https://github.com/benkay86/async-applied/blob/master/reqwest-tokio-compat/src/main.rs
         let mut byte_stream = res

src/nexus_api/files.rs

@@ -3,6 +3,7 @@ use chrono::NaiveDateTime;
 use reqwest::Client;
 use serde_json::Value;
 use std::{env, time::Duration};
+use tracing::{info, instrument};
 
 use super::{rate_limit_wait_duration, GAME_NAME, USER_AGENT};
 
@@ -21,6 +22,7 @@ pub struct ApiFile<'a> {
     pub uploaded_at: NaiveDateTime,
 }
 
+#[instrument(skip(client))]
 pub async fn get(client: &Client, nexus_mod_id: i32) -> Result<FilesResponse> {
     let res = client
         .get(format!(
@@ -34,6 +36,7 @@ pub async fn get(client: &Client, nexus_mod_id: i32) -> Result<FilesResponse> {
         .await?
         .error_for_status()?;
 
+    info!(status = %res.status(), "fetched files for mod from API");
     let wait = rate_limit_wait_duration(&res)?;
     let json = res.json::<Value>().await?;
 
@@ -41,6 +44,7 @@ pub async fn get(client: &Client, nexus_mod_id: i32) -> Result<FilesResponse> {
 }
 
 impl FilesResponse {
+    #[instrument(skip(self))]
     pub fn files<'a>(&'a self) -> Result<Vec<ApiFile<'a>>> {
         let files = self
             .json
@@ -48,7 +52,7 @@ impl FilesResponse {
             .ok_or_else(|| anyhow!("Missing files key in API response"))?
             .as_array()
             .ok_or_else(|| anyhow!("files value in API response is not an array"))?;
-        files
+        let files: Vec<ApiFile> = files
             .into_iter()
             .map(|file| {
                 let file_id = file
@@ -56,7 +60,6 @@ impl FilesResponse {
                     .ok_or_else(|| anyhow!("Missing file_id key in file in API response"))?
                     .as_i64()
                     .ok_or_else(|| anyhow!("file_id value in API response file is not a number"))?;
-                dbg!(file_id);
                 let name = file
                     .get("name")
                     .ok_or_else(|| anyhow!("Missing name key in file in API response"))?
@@ -102,6 +105,8 @@ impl FilesResponse {
                     uploaded_at,
                 })
             })
-            .collect()
+            .collect::<Result<Vec<ApiFile>>>()?;
+        info!(num_files = files.len(), "parsed files out of API response");
+        Ok(files)
     }
 }

src/nexus_api/mod.rs

@@ -3,6 +3,7 @@ use chrono::DateTime;
 use chrono::Duration;
 use chrono::Utc;
 use reqwest::Response;
+use tracing::info;
 
 pub mod download_link;
 pub mod files;
@@ -24,8 +25,7 @@ pub fn rate_limit_wait_duration(res: &Response) -> Result<Option<std::time::Dura
         .headers()
         .get("x-rl-hourly-reset")
         .expect("No hourly reset in response headers");
-    dbg!(daily_remaining);
+    info!(daily_remaining = ?daily_remaining, hourly_remaining = ?hourly_remaining, "rate limit check");
-    dbg!(hourly_remaining);
 
     if hourly_remaining == "0" {
         let hourly_reset = hourly_reset.to_str()?.trim();
@@ -33,9 +33,11 @@ pub fn rate_limit_wait_duration(res: &Response) -> Result<Option<std::time::Dura
             (DateTime::parse_from_str(hourly_reset, "%Y-%m-%d %H:%M:%S %z")?
                 + Duration::seconds(5))
             .into();
-        dbg!(hourly_reset);
         let duration = (hourly_reset - Utc::now()).to_std()?;
-        dbg!(duration);
+        info!(
+            hourly_reset = ?hourly_reset,
+            duration = ?duration, "need to wait until rate-limit hourly reset"
+        );
 
         return Ok(Some(duration));
     }

src/nexus_scraper.rs

@@ -1,6 +1,7 @@
 use anyhow::Result;
 use reqwest::Client;
 use scraper::{Html, Selector};
+use tracing::{info, instrument};
 
 use crate::nexus_api::GAME_ID;
 
@@ -20,6 +21,7 @@ pub struct ModListScrape<'a> {
     pub has_next_page: bool,
 }
 
+#[instrument(skip(client))]
 pub async fn get_mod_list_page(client: &Client, page: i32) -> Result<ModListResponse> {
     let res = client
         .get(format!(
@@ -30,6 +32,7 @@ pub async fn get_mod_list_page(client: &Client, page: i32) -> Result<ModListResp
         .send()
         .await?
         .error_for_status()?;
+    info!(status = %res.status(), "fetched mod list page");
     let text = res.text().await?;
     let html = Html::parse_document(&text);
 
@@ -37,6 +40,7 @@ pub async fn get_mod_list_page(client: &Client, page: i32) -> Result<ModListResp
 }
 
 impl ModListResponse {
+    #[instrument(skip(self))]
     pub fn scrape_mods<'a>(&'a self) -> Result<ModListScrape> {
         let mod_select = Selector::parse("li.mod-tile").expect("failed to parse CSS selector");
         let left_select =
@@ -110,7 +114,10 @@ impl ModListResponse {
                 }
             })
             .collect();
-        dbg!(mods.len());
+        info!(
+            len = mods.len(),
+            has_next_page, "scraped mods from mod list page"
+        );
         Ok(ModListScrape {
             mods,
             has_next_page,