From 14b02df8f40c3220278acd403f2a6426a20a66c8 Mon Sep 17 00:00:00 2001 From: Xevion Date: Fri, 12 Sep 2025 22:01:14 -0500 Subject: [PATCH] feat: much better JSON logging, project-wide logging improvements, better use of debug/trace levels, field attributes --- src/banner/api.rs | 17 +- src/banner/middleware.rs | 2 +- src/banner/query.rs | 10 ++ src/banner/rate_limit_middleware.rs | 8 +- src/banner/rate_limiter.rs | 6 +- src/banner/session.rs | 29 ++-- src/bin/search.rs | 4 +- src/bot/commands/gcal.rs | 2 +- src/bot/commands/ics.rs | 2 +- src/bot/commands/time.rs | 2 +- src/bot/utils.rs | 2 +- src/formatter.rs | 243 ++++++++++++++++++++++++++++ src/main.rs | 37 +++-- src/scraper/mod.rs | 13 +- src/scraper/scheduler.rs | 17 +- src/scraper/worker.rs | 14 +- src/services/bot.rs | 4 +- src/services/manager.rs | 4 +- src/services/web.rs | 10 +- 19 files changed, 348 insertions(+), 78 deletions(-) create mode 100644 src/formatter.rs diff --git a/src/banner/api.rs b/src/banner/api.rs index 5642611..dba9221 100644 --- a/src/banner/api.rs +++ b/src/banner/api.rs @@ -175,10 +175,9 @@ impl BannerApi { debug!( term = term, - query = ?query, - sort = sort, - sort_descending = sort_descending, - "Searching for courses with params: {:?}", params + subject = query.get_subject().map(|s| s.as_str()).unwrap_or("all"), + max_results = query.get_max_results(), + "Searching for courses" ); let response = self @@ -199,7 +198,7 @@ impl BannerApi { let search_result: SearchResult = parse_json_with_context(&body).map_err(|e| { BannerApiError::RequestFailed(anyhow!( - "Failed to parse search response (status={status}, url={url}): {e}\nBody: {body}" + "Failed to parse search response (status={status}, url={url}): {e}" )) })?; @@ -318,6 +317,12 @@ impl BannerApi { sort: &str, sort_descending: bool, ) -> Result { + debug!( + term = term, + subject = query.get_subject().map(|s| s.as_str()).unwrap_or("all"), + max_results = query.get_max_results(), + "Starting course search" + ); self.perform_search(term, query, sort, sort_descending) .await } @@ -328,6 +333,8 @@ impl BannerApi { term: &str, crn: &str, ) -> Result, BannerApiError> { + debug!(term = term, crn = crn, "Looking up course by CRN"); + let query = SearchQuery::new() .course_reference_number(crn) .max_results(1); diff --git a/src/banner/middleware.rs b/src/banner/middleware.rs index 8560e65..7ce4f8a 100644 --- a/src/banner/middleware.rs +++ b/src/banner/middleware.rs @@ -41,7 +41,7 @@ impl Middleware for TransparentMiddleware { } } Err(error) => { - warn!(?error, "Request failed (middleware)"); + warn!(error = ?error, "Request failed (middleware)"); Err(error) } } diff --git a/src/banner/query.rs b/src/banner/query.rs index 0def026..7fe0231 100644 --- a/src/banner/query.rs +++ b/src/banner/query.rs @@ -160,6 +160,16 @@ impl SearchQuery { self } + /// Gets the subject field + pub fn get_subject(&self) -> Option<&String> { + self.subject.as_ref() + } + + /// Gets the max_results field + pub fn get_max_results(&self) -> i32 { + self.max_results + } + /// Converts the query into URL parameters for the Banner API pub fn to_params(&self) -> HashMap { let mut params = HashMap::new(); diff --git a/src/banner/rate_limit_middleware.rs b/src/banner/rate_limit_middleware.rs index e114564..8c08cac 100644 --- a/src/banner/rate_limit_middleware.rs +++ b/src/banner/rate_limit_middleware.rs @@ -4,7 +4,7 @@ use crate::banner::rate_limiter::{RequestType, SharedRateLimiter}; use http::Extensions; use reqwest::{Request, Response}; use reqwest_middleware::{Middleware, Next}; -use tracing::{debug, warn}; +use tracing::{debug, warn, trace}; use url::Url; /// Middleware that enforces rate limiting based on request URL patterns @@ -53,7 +53,7 @@ impl Middleware for RateLimitMiddleware { ) -> std::result::Result { let request_type = Self::get_request_type(req.url()); - debug!( + trace!( url = %req.url(), request_type = ?request_type, "Rate limiting request" @@ -62,7 +62,7 @@ impl Middleware for RateLimitMiddleware { // Wait for permission to make the request self.rate_limiter.wait_for_permission(request_type).await; - debug!( + trace!( url = %req.url(), request_type = ?request_type, "Rate limit permission granted, making request" @@ -74,7 +74,7 @@ impl Middleware for RateLimitMiddleware { match response_result { Ok(response) => { if response.status().is_success() { - debug!( + trace!( url = %response.url(), status = response.status().as_u16(), "Request completed successfully" diff --git a/src/banner/rate_limiter.rs b/src/banner/rate_limiter.rs index d35af18..0cac69a 100644 --- a/src/banner/rate_limiter.rs +++ b/src/banner/rate_limiter.rs @@ -8,7 +8,7 @@ use governor::{ use std::num::NonZeroU32; use std::sync::Arc; use std::time::Duration; -use tracing::{debug, warn}; +use tracing::{debug, trace, warn}; /// Different types of Banner API requests with different rate limits #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -101,12 +101,12 @@ impl BannerRateLimiter { RequestType::Reset => &self.reset_limiter, }; - debug!(request_type = ?request_type, "Waiting for rate limit permission"); + trace!(request_type = ?request_type, "Waiting for rate limit permission"); // Wait until we can make the request limiter.until_ready().await; - debug!(request_type = ?request_type, "Rate limit permission granted"); + trace!(request_type = ?request_type, "Rate limit permission granted"); } /// Checks if a request of the given type would be allowed immediately diff --git a/src/banner/session.rs b/src/banner/session.rs index d408cce..79ca9b2 100644 --- a/src/banner/session.rs +++ b/src/banner/session.rs @@ -16,7 +16,7 @@ use std::ops::{Deref, DerefMut}; use std::sync::Arc; use std::time::{Duration, Instant}; use tokio::sync::{Mutex, Notify}; -use tracing::{debug, info}; +use tracing::{debug, info, trace}; use url::Url; const SESSION_EXPIRY: Duration = Duration::from_secs(25 * 60); // 25 minutes @@ -82,7 +82,7 @@ impl BannerSession { /// Updates the last activity timestamp pub fn touch(&mut self) { - debug!(id = self.unique_session_id, "Session was used"); + trace!(id = self.unique_session_id, "Session was used"); self.last_activity = Some(Instant::now()); } @@ -162,7 +162,7 @@ impl TermPool { async fn release(&self, session: BannerSession) { let id = session.unique_session_id.clone(); if session.is_expired() { - debug!(id = id, "Session is now expired, dropping."); + trace!(id = id, "Session is now expired, dropping."); // Wake up a waiter, as it might need to create a new session // if this was the last one. self.notifier.notify_one(); @@ -174,10 +174,7 @@ impl TermPool { let queue_size = queue.len(); drop(queue); // Release lock before notifying - debug!( - id = id, - "Session returned to pool. Queue size is now {queue_size}." - ); + trace!(id = id, queue_size, "Session returned to pool"); self.notifier.notify_one(); } } @@ -213,13 +210,13 @@ impl SessionPool { let mut queue = term_pool.sessions.lock().await; if let Some(session) = queue.pop_front() { if !session.is_expired() { - debug!(id = session.unique_session_id, "Reusing session from pool"); + trace!(id = session.unique_session_id, "Reusing session from pool"); return Ok(PooledSession { session: Some(session), pool: Arc::clone(&term_pool), }); } else { - debug!( + trace!( id = session.unique_session_id, "Popped an expired session, discarding." ); @@ -232,7 +229,7 @@ impl SessionPool { if *is_creating_guard { // Another task is already creating a session. Release the lock and wait. drop(is_creating_guard); - debug!("Another task is creating a session, waiting for notification..."); + trace!("Another task is creating a session, waiting for notification..."); term_pool.notifier.notified().await; // Loop back to the top to try the fast path again. continue; @@ -243,12 +240,12 @@ impl SessionPool { drop(is_creating_guard); // Race: wait for a session to be returned OR for the rate limiter to allow a new one. - debug!("Pool empty, racing notifier vs rate limiter..."); + trace!("Pool empty, racing notifier vs rate limiter..."); tokio::select! { _ = term_pool.notifier.notified() => { // A session was returned while we were waiting! // We are no longer the creator. Reset the flag and loop to race for the new session. - debug!("Notified that a session was returned. Looping to retry."); + trace!("Notified that a session was returned. Looping to retry."); let mut guard = term_pool.is_creating.lock().await; *guard = false; drop(guard); @@ -256,7 +253,7 @@ impl SessionPool { } _ = SESSION_CREATION_RATE_LIMITER.until_ready() => { // The rate limit has elapsed. It's our job to create the session. - debug!("Rate limiter ready. Proceeding to create a new session."); + trace!("Rate limiter ready. Proceeding to create a new session."); let new_session_result = self.create_session(&term).await; // After creation, we are no longer the creator. Reset the flag @@ -286,7 +283,7 @@ impl SessionPool { /// Sets up initial session cookies by making required Banner API requests pub async fn create_session(&self, term: &Term) -> Result { - info!("setting up banner session for term {term}"); + info!(term = %term, "setting up banner session"); // The 'register' or 'search' registration page let initial_registration = self @@ -317,7 +314,7 @@ impl SessionPool { let ssb_cookie = cookies.get("SSB_COOKIE").unwrap(); let cookie_header = format!("JSESSIONID={}; SSB_COOKIE={}", jsessionid, ssb_cookie); - debug!( + trace!( jsessionid = jsessionid, ssb_cookie = ssb_cookie, "New session cookies acquired" @@ -457,7 +454,7 @@ impl SessionPool { )); } - debug!(term = term, "successfully selected term"); + trace!(term = term, "successfully selected term"); Ok(()) } } diff --git a/src/bin/search.rs b/src/bin/search.rs index e60cfd5..b842162 100644 --- a/src/bin/search.rs +++ b/src/bin/search.rs @@ -69,11 +69,11 @@ async fn main() -> Result<()> { ), ]; - info!("Executing {} concurrent searches", queries.len()); + info!(query_count = queries.len(), "Executing concurrent searches"); // Execute all searches concurrently let search_futures = queries.into_iter().map(|(label, query)| { - info!("Starting search: {}", label); + info!(label = %label, "Starting search"); let banner_api = &banner_api; let term = &term; async move { diff --git a/src/bot/commands/gcal.rs b/src/bot/commands/gcal.rs index 613d38b..2a3dceb 100644 --- a/src/bot/commands/gcal.rs +++ b/src/bot/commands/gcal.rs @@ -77,7 +77,7 @@ pub async fn gcal( ) .await?; - info!("gcal command completed for CRN: {}", crn); + info!(crn = %crn, "gcal command completed"); Ok(()) } diff --git a/src/bot/commands/ics.rs b/src/bot/commands/ics.rs index 3ecfe9a..b1b165d 100644 --- a/src/bot/commands/ics.rs +++ b/src/bot/commands/ics.rs @@ -20,6 +20,6 @@ pub async fn ics( )) .await?; - info!("ics command completed for CRN: {}", crn); + info!(crn = %crn, "ics command completed"); Ok(()) } diff --git a/src/bot/commands/time.rs b/src/bot/commands/time.rs index 0002bba..3309d3f 100644 --- a/src/bot/commands/time.rs +++ b/src/bot/commands/time.rs @@ -20,6 +20,6 @@ pub async fn time( )) .await?; - info!("time command completed for CRN: {}", crn); + info!(crn = %crn, "time command completed"); Ok(()) } diff --git a/src/bot/utils.rs b/src/bot/utils.rs index 3e9934b..35a9a35 100644 --- a/src/bot/utils.rs +++ b/src/bot/utils.rs @@ -18,7 +18,7 @@ pub async fn get_course_by_crn(ctx: &Context<'_>, crn: i32) -> Result { .get_course_or_fetch(&term.to_string(), &crn.to_string()) .await .map_err(|e| { - error!(%e, crn, "failed to fetch course data"); + error!(error = %e, crn = %crn, "failed to fetch course data"); e }) } diff --git a/src/formatter.rs b/src/formatter.rs new file mode 100644 index 0000000..b37e6b9 --- /dev/null +++ b/src/formatter.rs @@ -0,0 +1,243 @@ +//! Custom tracing formatter + +use serde::Serialize; +use serde_json::{Map, Value}; +use std::fmt; +use time::macros::format_description; +use time::{OffsetDateTime, format_description::FormatItem}; +use tracing::field::{Field, Visit}; +use tracing::{Event, Level, Subscriber}; +use tracing_subscriber::fmt::format::Writer; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields, FormattedFields}; +use tracing_subscriber::registry::LookupSpan; + +/// Cached format description for timestamps +/// Uses 3 subsecond digits on Emscripten, 5 otherwise for better performance +#[cfg(target_os = "emscripten")] +const TIMESTAMP_FORMAT: &[FormatItem<'static>] = + format_description!("[hour]:[minute]:[second].[subsecond digits:3]"); + +#[cfg(not(target_os = "emscripten"))] +const TIMESTAMP_FORMAT: &[FormatItem<'static>] = + format_description!("[hour]:[minute]:[second].[subsecond digits:5]"); + +/// A custom formatter with enhanced timestamp formatting +/// +/// Re-implementation of the Full formatter with improved timestamp display. +pub struct CustomFormatter; + +/// A custom JSON formatter that flattens fields to root level +/// +/// Outputs logs in the format: { "message": "...", "level": "...", "customAttribute": "..." } +pub struct CustomJsonFormatter; + +impl FormatEvent for CustomFormatter +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + let meta = event.metadata(); + + // 1) Timestamp (dimmed when ANSI) + let now = OffsetDateTime::now_utc(); + let formatted_time = now.format(&TIMESTAMP_FORMAT).map_err(|e| { + eprintln!("Failed to format timestamp: {}", e); + fmt::Error + })?; + write_dimmed(&mut writer, formatted_time)?; + writer.write_char(' ')?; + + // 2) Colored 5-char level like Full + write_colored_level(&mut writer, meta.level())?; + writer.write_char(' ')?; + + // 3) Span scope chain (bold names, fields in braces, dimmed ':') + if let Some(scope) = ctx.event_scope() { + let mut saw_any = false; + for span in scope.from_root() { + write_bold(&mut writer, span.metadata().name())?; + saw_any = true; + let ext = span.extensions(); + if let Some(fields) = &ext.get::>() { + if !fields.is_empty() { + write_bold(&mut writer, "{")?; + write!(writer, "{}", fields)?; + write_bold(&mut writer, "}")?; + } + } + if writer.has_ansi_escapes() { + write!(writer, "\x1b[2m:\x1b[0m")?; + } else { + writer.write_char(':')?; + } + } + if saw_any { + writer.write_char(' ')?; + } + } + + // 4) Target (dimmed), then a space + if writer.has_ansi_escapes() { + write!(writer, "\x1b[2m{}\x1b[0m\x1b[2m:\x1b[0m ", meta.target())?; + } else { + write!(writer, "{}: ", meta.target())?; + } + + // 5) Event fields + ctx.format_fields(writer.by_ref(), event)?; + + // 6) Newline + writeln!(writer) + } +} + +impl FormatEvent for CustomJsonFormatter +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + _ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + let meta = event.metadata(); + + #[derive(Serialize)] + struct EventFields { + message: String, + level: String, + target: String, + #[serde(flatten)] + fields: Map, + } + + let (message, fields) = { + let mut message: Option = None; + let mut fields: Map = Map::new(); + + struct FieldVisitor<'a> { + message: &'a mut Option, + fields: &'a mut Map, + } + + impl<'a> Visit for FieldVisitor<'a> { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + let key = field.name(); + if key == "message" { + *self.message = Some(format!("{:?}", value)); + } else { + // Use typed methods for better performance + self.fields + .insert(key.to_string(), Value::String(format!("{:?}", value))); + } + } + + fn record_str(&mut self, field: &Field, value: &str) { + let key = field.name(); + if key == "message" { + *self.message = Some(value.to_string()); + } else { + self.fields + .insert(key.to_string(), Value::String(value.to_string())); + } + } + + fn record_i64(&mut self, field: &Field, value: i64) { + let key = field.name(); + if key != "message" { + self.fields.insert( + key.to_string(), + Value::Number(serde_json::Number::from(value)), + ); + } + } + + fn record_u64(&mut self, field: &Field, value: u64) { + let key = field.name(); + if key != "message" { + self.fields.insert( + key.to_string(), + Value::Number(serde_json::Number::from(value)), + ); + } + } + + fn record_bool(&mut self, field: &Field, value: bool) { + let key = field.name(); + if key != "message" { + self.fields.insert(key.to_string(), Value::Bool(value)); + } + } + } + + let mut visitor = FieldVisitor { + message: &mut message, + fields: &mut fields, + }; + event.record(&mut visitor); + + (message, fields) + }; + + let json = EventFields { + message: message.unwrap_or_default(), + level: meta.level().to_string(), + target: meta.target().to_string(), + fields, + }; + + writeln!( + writer, + "{}", + serde_json::to_string(&json).unwrap_or_else(|_| "{}".to_string()) + ) + } +} + +/// Write the verbosity level with the same coloring/alignment as the Full formatter. +fn write_colored_level(writer: &mut Writer<'_>, level: &Level) -> fmt::Result { + if writer.has_ansi_escapes() { + // Basic ANSI color sequences; reset with \x1b[0m + let (color, text) = match *level { + Level::TRACE => ("\x1b[35m", "TRACE"), // purple + Level::DEBUG => ("\x1b[34m", "DEBUG"), // blue + Level::INFO => ("\x1b[32m", " INFO"), // green, note leading space + Level::WARN => ("\x1b[33m", " WARN"), // yellow, note leading space + Level::ERROR => ("\x1b[31m", "ERROR"), // red + }; + write!(writer, "{}{}\x1b[0m", color, text) + } else { + // Right-pad to width 5 like Full's non-ANSI mode + match *level { + Level::TRACE => write!(writer, "{:>5}", "TRACE"), + Level::DEBUG => write!(writer, "{:>5}", "DEBUG"), + Level::INFO => write!(writer, "{:>5}", " INFO"), + Level::WARN => write!(writer, "{:>5}", " WARN"), + Level::ERROR => write!(writer, "{:>5}", "ERROR"), + } + } +} + +fn write_dimmed(writer: &mut Writer<'_>, s: impl fmt::Display) -> fmt::Result { + if writer.has_ansi_escapes() { + write!(writer, "\x1b[2m{}\x1b[0m", s) + } else { + write!(writer, "{}", s) + } +} + +fn write_bold(writer: &mut Writer<'_>, s: impl fmt::Display) -> fmt::Result { + if writer.has_ansi_escapes() { + write!(writer, "\x1b[1m{}\x1b[0m", s) + } else { + write!(writer, "{}", s) + } +} diff --git a/src/main.rs b/src/main.rs index 201c23e..cd837f4 100644 --- a/src/main.rs +++ b/src/main.rs @@ -20,6 +20,7 @@ mod bot; mod config; mod data; mod error; +mod formatter; mod scraper; mod services; mod state; @@ -29,21 +30,36 @@ mod web; async fn main() { dotenvy::dotenv().ok(); - // Configure logging - let filter = - EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("warn,banner=debug")); + // Load configuration first to get log level + let config: Config = Figment::new() + .merge(Env::raw().only(&["DATABASE_URL"])) + .merge(Env::prefixed("APP_")) + .extract() + .expect("Failed to load config"); + + // Configure logging based on config + let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| { + let base_level = &config.log_level; + EnvFilter::new(&format!( + "warn,banner={},banner::rate_limiter=warn,banner::session=warn,banner::rate_limit_middleware=warn", + base_level + )) + }); let subscriber = { #[cfg(debug_assertions)] { FmtSubscriber::builder() + .with_target(true) + .event_format(formatter::CustomFormatter) } #[cfg(not(debug_assertions))] { - FmtSubscriber::builder().json() + FmtSubscriber::builder() + .with_target(true) + .event_format(formatter::CustomJsonFormatter) } } .with_env_filter(filter) - .with_target(true) .finish(); tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); @@ -58,12 +74,6 @@ async fn main() { "starting banner" ); - let config: Config = Figment::new() - .merge(Env::raw().only(&["DATABASE_URL"])) - .merge(Env::prefixed("APP_")) - .extract() - .expect("Failed to load config"); - // Create database connection pool let db_pool = PgPoolOptions::new() .max_connections(10) @@ -82,7 +92,8 @@ async fn main() { let banner_api = BannerApi::new_with_config( config.banner_base_url.clone(), config.rate_limiting.clone().into(), - ).expect("Failed to create BannerApi"); + ) + .expect("Failed to create BannerApi"); let banner_api_arc = Arc::new(banner_api); let app_state = AppState::new(banner_api_arc.clone(), &config.redis_url) @@ -140,7 +151,7 @@ async fn main() { on_error: |error| { Box::pin(async move { if let Err(e) = poise::builtins::on_error(error).await { - tracing::error!("Fatal error while sending error message: {}", e); + tracing::error!(error = %e, "Fatal error while sending error message"); } // error!(error = ?error, "command error"); }) diff --git a/src/scraper/mod.rs b/src/scraper/mod.rs index 16c3281..1daa864 100644 --- a/src/scraper/mod.rs +++ b/src/scraper/mod.rs @@ -35,14 +35,14 @@ impl ScraperService { /// Starts the scheduler and a pool of workers. pub fn start(&mut self) { - info!("ScraperService starting..."); + info!("ScraperService starting"); let scheduler = Scheduler::new(self.db_pool.clone(), self.banner_api.clone()); let scheduler_handle = tokio::spawn(async move { scheduler.run().await; }); self.scheduler_handle = Some(scheduler_handle); - info!("Scheduler task spawned."); + info!("Scheduler task spawned"); let worker_count = 4; // This could be configurable for i in 0..worker_count { @@ -52,19 +52,22 @@ impl ScraperService { }); self.worker_handles.push(worker_handle); } - info!("Spawned {} worker tasks.", self.worker_handles.len()); + info!( + worker_count = self.worker_handles.len(), + "Spawned worker tasks" + ); } /// Signals all child tasks to gracefully shut down. pub async fn shutdown(&mut self) { - info!("Shutting down scraper service..."); + info!("Shutting down scraper service"); if let Some(handle) = self.scheduler_handle.take() { handle.abort(); } for handle in self.worker_handles.drain(..) { handle.abort(); } - info!("Scraper service shutdown."); + info!("Scraper service shutdown"); } } diff --git a/src/scraper/scheduler.rs b/src/scraper/scheduler.rs index 58c272e..dba70d2 100644 --- a/src/scraper/scheduler.rs +++ b/src/scraper/scheduler.rs @@ -6,7 +6,7 @@ use sqlx::PgPool; use std::sync::Arc; use std::time::Duration; use tokio::time; -use tracing::{error, info}; +use tracing::{error, info, debug, trace}; /// Periodically analyzes data and enqueues prioritized scrape jobs. pub struct Scheduler { @@ -24,12 +24,12 @@ impl Scheduler { /// Runs the scheduler's main loop. pub async fn run(&self) { - info!("Scheduler service started."); + info!("Scheduler service started"); let mut interval = time::interval(Duration::from_secs(60)); // Runs every minute loop { interval.tick().await; - info!("Scheduler waking up to analyze and schedule jobs..."); + // Scheduler analyzing data... if let Err(e) = self.schedule_jobs().await { error!(error = ?e, "Failed to schedule jobs"); } @@ -44,12 +44,10 @@ impl Scheduler { // 3. If no job exists, create a new, low-priority job to be executed in the near future. let term = Term::get_current().inner().to_string(); - info!( - term = term, - "[Scheduler] Enqueuing baseline subject scrape jobs..." - ); + debug!(term = term, "Enqueuing subject jobs"); let subjects = self.banner_api.get_subjects("", &term, 1, 500).await?; + debug!(subject_count = subjects.len(), "Retrieved subjects from API"); for subject in subjects { let payload = json!({ "subject": subject.code }); @@ -63,6 +61,7 @@ impl Scheduler { .await?; if existing_job.is_some() { + trace!(subject = subject.code, "Job already exists, skipping"); continue; } @@ -76,10 +75,10 @@ impl Scheduler { .execute(&self.db_pool) .await?; - info!(subject = subject.code, "[Scheduler] Enqueued new job"); + debug!(subject = subject.code, "New job enqueued for subject"); } - info!("[Scheduler] Job scheduling complete."); + debug!("Job scheduling complete"); Ok(()) } } diff --git a/src/scraper/worker.rs b/src/scraper/worker.rs index e76390c..43420f2 100644 --- a/src/scraper/worker.rs +++ b/src/scraper/worker.rs @@ -6,7 +6,7 @@ use sqlx::PgPool; use std::sync::Arc; use std::time::Duration; use tokio::time; -use tracing::{error, info, warn}; +use tracing::{debug, error, info, trace, warn}; /// A single worker instance. /// @@ -34,7 +34,7 @@ impl Worker { match self.fetch_and_lock_job().await { Ok(Some(job)) => { let job_id = job.id; - info!(worker_id = self.id, job_id = job.id, "Processing job"); + debug!(worker_id = self.id, job_id = job.id, "Processing job"); if let Err(e) = self.process_job(job).await { // Check if the error is due to an invalid session if let Some(BannerApiError::InvalidSession(_)) = @@ -58,7 +58,7 @@ impl Worker { ); } } else { - info!(worker_id = self.id, job_id, "Job processed successfully"); + debug!(worker_id = self.id, job_id, "Job completed"); // If successful, delete the job. if let Err(delete_err) = self.delete_job(job_id).await { error!( @@ -72,6 +72,7 @@ impl Worker { } Ok(None) => { // No job found, wait for a bit before polling again. + trace!(worker_id = self.id, "No jobs available, waiting"); time::sleep(Duration::from_secs(5)).await; } Err(e) => { @@ -127,7 +128,7 @@ impl Worker { info!( worker_id = self.id, subject = subject_code, - "Processing subject job" + "Scraping subject" ); let term = Term::get_current().inner().to_string(); @@ -143,7 +144,7 @@ impl Worker { worker_id = self.id, subject = subject_code, count = courses_from_api.len(), - "Found courses to upsert" + "Found courses" ); for course in courses_from_api { self.upsert_course(&course).await?; @@ -190,7 +191,6 @@ impl Worker { .bind(job_id) .execute(&self.db_pool) .await?; - info!(worker_id = self.id, job_id, "Job deleted"); Ok(()) } @@ -199,7 +199,7 @@ impl Worker { .bind(job_id) .execute(&self.db_pool) .await?; - info!(worker_id = self.id, job_id, "Job unlocked after failure"); + info!(worker_id = self.id, job_id, "Job unlocked for retry"); Ok(()) } } diff --git a/src/services/bot.rs b/src/services/bot.rs index 72db051..cb16524 100644 --- a/src/services/bot.rs +++ b/src/services/bot.rs @@ -1,7 +1,7 @@ use super::Service; use serenity::Client; use std::sync::Arc; -use tracing::{debug, error}; +use tracing::{error, warn}; /// Discord bot service implementation pub struct BotService { @@ -28,7 +28,7 @@ impl Service for BotService { async fn run(&mut self) -> Result<(), anyhow::Error> { match self.client.start().await { Ok(()) => { - debug!(service = "bot", "stopped early."); + warn!(service = "bot", "stopped early"); Err(anyhow::anyhow!("bot stopped early")) } Err(e) => { diff --git a/src/services/manager.rs b/src/services/manager.rs index 68e50f0..5e47a8e 100644 --- a/src/services/manager.rs +++ b/src/services/manager.rs @@ -42,7 +42,7 @@ impl ServiceManager { for (name, service) in self.registered_services.drain() { let shutdown_rx = self.shutdown_tx.subscribe(); let handle = tokio::spawn(run_service(service, shutdown_rx)); - trace!(service = name, id = ?handle.id(), "service spawned",); + debug!(service = name, id = ?handle.id(), "service spawned"); self.running_services.insert(name, handle); } @@ -127,7 +127,7 @@ impl ServiceManager { for (name, handle) in self.running_services.drain() { match tokio::time::timeout(timeout, handle).await { Ok(Ok(_)) => { - debug!(service = name, "service shutdown completed"); + trace!(service = name, "service shutdown completed"); } Ok(Err(e)) => { warn!(service = name, error = ?e, "service shutdown failed"); diff --git a/src/services/web.rs b/src/services/web.rs index e36c853..f23cde6 100644 --- a/src/services/web.rs +++ b/src/services/web.rs @@ -3,7 +3,7 @@ use crate::web::{BannerState, create_router}; use std::net::SocketAddr; use tokio::net::TcpListener; use tokio::sync::broadcast; -use tracing::{debug, info, warn}; +use tracing::{info, warn, trace}; /// Web server service implementation pub struct WebService { @@ -40,10 +40,10 @@ impl Service for WebService { ); let listener = TcpListener::bind(addr).await?; - debug!( + info!( service = "web", - "web server listening on {}", - format!("http://{}", addr) + address = %addr, + "web server listening" ); // Create internal shutdown channel for axum graceful shutdown @@ -54,7 +54,7 @@ impl Service for WebService { axum::serve(listener, app) .with_graceful_shutdown(async move { let _ = shutdown_rx.recv().await; - debug!( + trace!( service = "web", "received shutdown signal, starting graceful shutdown" );