From 792e78391c37f196d4fb4f931f09c3ffc6ee9928 Mon Sep 17 00:00:00 2001 From: Tyler Hallada Date: Sun, 11 Jul 2021 19:45:26 -0400 Subject: [PATCH] Replace dbg macros with tracing events --- Cargo.lock | 114 +++++++++++++++++++++++++++++++++ Cargo.toml | 3 + src/main.rs | 46 ++++++++++--- src/models/cell.rs | 2 + src/models/file.rs | 2 + src/models/game.rs | 2 + src/models/game_mod.rs | 3 + src/models/plugin.rs | 4 +- src/models/plugin_cell.rs | 5 +- src/nexus_api/download_link.rs | 7 ++ src/nexus_api/files.rs | 11 +++- src/nexus_api/mod.rs | 10 +-- src/nexus_scraper.rs | 9 ++- 13 files changed, 199 insertions(+), 19 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 54fe15f..8f3fa28 100644 --- a/Cargo.lock +++ b/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" diff --git a/Cargo.toml b/Cargo.toml index c164d8d..9aa371f 100644 --- a/Cargo.toml +++ b/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" } \ No newline at end of file diff --git a/src/main.rs b/src/main.rs index b60ef09..dfe6987 100644 --- a/src/main.rs +++ b/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( plugin_buf: &mut [u8], pool: &sqlx::Pool, @@ -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); - dbg!(has_next_page); + debug!(?page, ?has_next_page, "sleeping 1 second"); sleep(Duration::new(1, 0)).await; } diff --git a/src/models/cell.rs b/src/models/cell.rs index f5d526e..69c2f67 100644 --- a/src/models/cell.rs +++ b/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, form_id: i32, diff --git a/src/models/file.rs b/src/models/file.rs index 863a46a..cb85199 100644 --- a/src/models/file.rs +++ b/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, name: &str, diff --git a/src/models/game.rs b/src/models/game.rs index b882ce9..b1dddc2 100644 --- a/src/models/game.rs +++ b/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, name: &str, diff --git a/src/models/game_mod.rs b/src/models/game_mod.rs index 18334ed..7779df1 100644 --- a/src/models/game_mod.rs +++ b/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, 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, name: &str, diff --git a/src/models/plugin.rs b/src/models/plugin.rs index aaf3740..e5997bd 100644 --- a/src/models/plugin.rs +++ b/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, name: &str, @@ -46,4 +48,4 @@ pub async fn insert_plugin( .fetch_one(pool) .await .context("Failed to insert plugin") -} \ No newline at end of file +} diff --git a/src/models/plugin_cell.rs b/src/models/plugin_cell.rs index 46726bc..03af569 100644 --- a/src/models/plugin_cell.rs +++ b/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, plugin_id: i32, @@ -33,4 +34,4 @@ pub async fn insert_plugin_cell( .fetch_one(pool) .await .context("Failed to insert cell") -} \ No newline at end of file +} diff --git a/src/nexus_api/download_link.rs b/src/nexus_api/download_link.rs index 65c5547..84d90df 100644 --- a/src/nexus_api/download_link.rs +++ b/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 { let res = client .get(format!( @@ -27,6 +29,7 @@ pub async fn get(client: &Client, mod_id: i32, file_id: i64) -> Result().await?; @@ -34,6 +37,7 @@ pub async fn get(client: &Client, mod_id: i32, file_id: i64) -> Result(&'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 { 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 diff --git a/src/nexus_api/files.rs b/src/nexus_api/files.rs index 3e4d734..979362f 100644 --- a/src/nexus_api/files.rs +++ b/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 { let res = client .get(format!( @@ -34,6 +36,7 @@ pub async fn get(client: &Client, nexus_mod_id: i32) -> Result { .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::().await?; @@ -41,6 +44,7 @@ pub async fn get(client: &Client, nexus_mod_id: i32) -> Result { } impl FilesResponse { + #[instrument(skip(self))] pub fn files<'a>(&'a self) -> Result>> { 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 = 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::>>()?; + info!(num_files = files.len(), "parsed files out of API response"); + Ok(files) } } diff --git a/src/nexus_api/mod.rs b/src/nexus_api/mod.rs index fc21dca..aa21fab 100644 --- a/src/nexus_api/mod.rs +++ b/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 Result { pub has_next_page: bool, } +#[instrument(skip(client))] pub async fn get_mod_list_page(client: &Client, page: i32) -> Result { let res = client .get(format!( @@ -30,6 +32,7 @@ pub async fn get_mod_list_page(client: &Client, page: i32) -> Result Result(&'a self) -> Result { 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,