feat: much better JSON logging, project-wide logging improvements, better use of debug/trace levels, field attributes

src/banner/api.rs

@@ -175,10 +175,9 @@ impl BannerApi {
 
         debug!(
             term = term,
-            query = ?query,
+            subject = query.get_subject().map(|s| s.as_str()).unwrap_or("all"),
-            sort = sort,
+            max_results = query.get_max_results(),
-            sort_descending = sort_descending,
+            "Searching for courses"
-            "Searching for courses with params: {:?}", params
         );
 
         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<SearchResult, BannerApiError> {
+        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<Option<Course>, BannerApiError> {
+        debug!(term = term, crn = crn, "Looking up course by CRN");
+
         let query = SearchQuery::new()
             .course_reference_number(crn)
             .max_results(1);

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)
             }
         }

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<String, String> {
         let mut params = HashMap::new();

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<Response, reqwest_middleware::Error> {
         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"

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

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!(
+        trace!(id = id, queue_size, "Session returned to pool");
-            id = id,
-            "Session returned to pool. Queue size is now {queue_size}."
-        );
         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<BannerSession> {
-        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(())
     }
 }

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 {

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(())
 }
 

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(())
 }

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(())
 }

src/bot/utils.rs

@@ -18,7 +18,7 @@ pub async fn get_course_by_crn(ctx: &Context<'_>, crn: i32) -> Result<Course> {
         .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
         })
 }

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<S, N> FormatEvent<S, N> 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::<FormattedFields<N>>() {
+                    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<S, N> FormatEvent<S, N> 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<String, Value>,
+        }
+
+        let (message, fields) = {
+            let mut message: Option<String> = None;
+            let mut fields: Map<String, Value> = Map::new();
+
+            struct FieldVisitor<'a> {
+                message: &'a mut Option<String>,
+                fields: &'a mut Map<String, Value>,
+            }
+
+            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)
+    }
+}

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
+    // Load configuration first to get log level
-    let filter =
+    let config: Config = Figment::new()
-        EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("warn,banner=debug"));
+        .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");
                 })

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");
     }
 }
 

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!(
+        debug!(term = term, "Enqueuing subject jobs");
-            term = term,
-            "[Scheduler] Enqueuing baseline subject scrape 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(())
     }
 }

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(())
     }
 }

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) => {

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");

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 {}",
+            address = %addr,
-            format!("http://{}", 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"
                 );