diff --git a/src/banner/api.rs b/src/banner/api.rs index b625fa9..ecf8930 100644 --- a/src/banner/api.rs +++ b/src/banner/api.rs @@ -6,7 +6,7 @@ use axum::http::HeaderValue; use reqwest::Client; use serde_json; -// use tracing::debug; +use tracing::{error, info}; /// Main Banner API client. #[derive(Debug)] @@ -40,7 +40,13 @@ impl BannerApi { /// Sets up the API client by initializing session cookies. pub async fn setup(&self) -> Result<()> { - self.session_manager.setup().await + info!(base_url = self.base_url, "setting up banner api client"); + let result = self.session_manager.setup().await; + match &result { + Ok(()) => info!("banner api client setup completed successfully"), + Err(e) => error!(error = ?e, "banner api client setup failed"), + } + result } /// Retrieves a list of terms from the Banner API. diff --git a/src/banner/scraper.rs b/src/banner/scraper.rs index 23214a8..06e30b8 100644 --- a/src/banner/scraper.rs +++ b/src/banner/scraper.rs @@ -53,12 +53,12 @@ impl CourseScraper { expired_subjects.extend(self.get_expired_subjects(&other_subjects, term).await?); if expired_subjects.is_empty() { - info!("No expired subjects found, skipping scrape"); + info!("no expired subjects found, skipping scrape"); return Ok(()); } info!( - "Scraping {} subjects for term {}", + "scraping {} subjects for term {}", expired_subjects.len(), term ); @@ -66,7 +66,7 @@ impl CourseScraper { // Scrape each expired subject for subject in expired_subjects { if let Err(e) = self.scrape_subject(&subject.code, term).await { - error!("Failed to scrape subject {}: {}", subject.code, e); + error!("failed to scrape subject {}: {}", subject.code, e); } // Rate limiting between subjects @@ -138,7 +138,7 @@ impl CourseScraper { total_courses += course_count; debug!( - "Retrieved {} courses for subject {} at offset {}", + "retrieved {} courses for subject {} at offset {}", course_count, subject, offset ); @@ -146,7 +146,7 @@ impl CourseScraper { for course in result.data.unwrap_or_default() { if let Err(e) = self.store_course(&course).await { error!( - "Failed to store course {}: {}", + "failed to store course {}: {}", course.course_reference_number, e ); } @@ -156,14 +156,14 @@ impl CourseScraper { if course_count >= MAX_PAGE_SIZE { if course_count > MAX_PAGE_SIZE { warn!( - "Course count {} exceeds max page size {}", + "course count {} exceeds max page size {}", course_count, MAX_PAGE_SIZE ); } offset += MAX_PAGE_SIZE; debug!( - "Continuing to next page for subject {} at offset {}", + "continuing to next page for subject {} at offset {}", subject, offset ); @@ -176,7 +176,7 @@ impl CourseScraper { } info!( - "Scraped {} total courses for subject {}", + "scraped {} total courses for subject {}", total_courses, subject ); @@ -230,7 +230,7 @@ impl CourseScraper { .context("Failed to mark subject as scraped")?; debug!( - "Marked subject {} as scraped with {} courses, expiry: {:?}", + "marked subject {} as scraped with {} courses, expiry: {:?}", subject, course_count, expiry ); diff --git a/src/banner/session.rs b/src/banner/session.rs index 999f901..1a5e7e4 100644 --- a/src/banner/session.rs +++ b/src/banner/session.rs @@ -35,10 +35,17 @@ impl SessionManager { /// Ensures a valid session is available, creating one if necessary pub fn ensure_session(&self) -> Result { + let start_time = std::time::Instant::now(); let mut session_guard = self.current_session.lock().unwrap(); if let Some(ref session) = *session_guard { if session.created_at.elapsed() < Self::SESSION_EXPIRY { + let elapsed = start_time.elapsed(); + debug!( + session_id = session.session_id, + elapsed = format!("{:.2?}", elapsed), + "reusing existing banner session" + ); return Ok(session.session_id.clone()); } } @@ -50,7 +57,12 @@ impl SessionManager { created_at: Instant::now(), }); - debug!("Generated new Banner session: {}", session_id); + let elapsed = start_time.elapsed(); + info!( + session_id = session_id, + elapsed = format!("{:.2?}", elapsed), + "generated new banner session" + ); Ok(session_id) } @@ -66,7 +78,7 @@ impl SessionManager { /// Sets up initial session cookies by making required Banner API requests pub async fn setup(&self) -> Result<()> { - info!("Setting up Banner session..."); + info!("setting up banner session..."); let request_paths = ["/registration/registration", "/selfServiceMenu/data"]; @@ -90,7 +102,7 @@ impl SessionManager { } // Note: Cookie validation would require additional setup in a real implementation - debug!("Session setup complete"); + debug!("session setup complete"); Ok(()) } @@ -150,7 +162,7 @@ impl SessionManager { )); } - debug!("Successfully selected term: {}", term); + debug!("successfully selected term: {}", term); Ok(()) } diff --git a/src/bot/commands/gcal.rs b/src/bot/commands/gcal.rs index 841adf8..ae80d6e 100644 --- a/src/bot/commands/gcal.rs +++ b/src/bot/commands/gcal.rs @@ -32,7 +32,7 @@ pub async fn gcal( { Ok(course) => course, Err(e) => { - error!(%e, crn, "Failed to fetch course data"); + error!(%e, crn, "failed to fetch course data"); return Err(Error::from(e)); } }; @@ -44,7 +44,7 @@ pub async fn gcal( { Ok(meeting_time) => meeting_time, Err(e) => { - error!("Failed to get meeting times: {}", e); + error!("failed to get meeting times: {}", e); return Err(Error::from(e)); } }; diff --git a/src/main.rs b/src/main.rs index 6c8d418..59973ed 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,6 +1,6 @@ use serenity::all::{ClientBuilder, GatewayIntents}; use tokio::signal; -use tracing::{debug, error, info, warn}; +use tracing::{error, info, warn}; use tracing_subscriber::{EnvFilter, FmtSubscriber}; use crate::app_state::AppState; @@ -39,14 +39,33 @@ async fn main() { } } .with_env_filter(filter) + .with_target(true) .finish(); tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); + // Log application startup context + info!( + version = env!("CARGO_PKG_VERSION"), + environment = if cfg!(debug_assertions) { + "development" + } else { + "production" + }, + "starting banner system" + ); + let config: Config = Figment::new() .merge(Env::prefixed("APP_")) .extract() .expect("Failed to load config"); + info!( + port = config.port, + shutdown_timeout = format!("{:.2?}", config.shutdown_timeout), + banner_base_url = config.banner_base_url, + "configuration loaded" + ); + // Create BannerApi and AppState let banner_api = BannerApi::new(config.banner_base_url.clone()).expect("Failed to create BannerApi"); @@ -121,61 +140,67 @@ async fn main() { signal::ctrl_c() .await .expect("Failed to install CTRL+C signal handler"); - info!("Received CTRL+C, gracefully shutting down..."); + info!("received ctrl+c, gracefully shutting down..."); }; // Main application loop - wait for services or CTRL+C let mut exit_code = 0; - let join = |strings: Vec| { - strings - .iter() - .map(|s| format!("\"{}\"", s)) - .collect::>() - .join(", ") - }; - tokio::select! { (service_name, result) = service_manager.run() => { // A service completed unexpectedly match result { ServiceResult::GracefulShutdown => { - info!(service = service_name, "Service completed gracefully"); + info!(service = service_name, "service completed gracefully"); } ServiceResult::NormalCompletion => { - warn!(service = service_name, "Service completed unexpectedly"); + warn!(service = service_name, "service completed unexpectedly"); exit_code = 1; } ServiceResult::Error(e) => { - error!(service = service_name, "Service failed: {e}"); + error!(service = service_name, error = ?e, "service failed"); exit_code = 1; } } // Shutdown remaining services match service_manager.shutdown(shutdown_timeout).await { - Ok(()) => { - debug!("Graceful shutdown complete"); + Ok(elapsed) => { + info!( + remaining = format!("{:.2?}", shutdown_timeout - elapsed), + "graceful shutdown complete" + ); } Err(pending_services) => { warn!( - "Graceful shutdown elapsed - the following service(s) did not complete: {}", - join(pending_services) + pending_count = pending_services.len(), + pending_services = ?pending_services, + "graceful shutdown elapsed - {} service(s) did not complete", + pending_services.len() ); + + // Non-zero exit code, default to 2 if not set exit_code = if exit_code == 0 { 2 } else { exit_code }; } } } _ = ctrl_c => { // User requested shutdown + info!("user requested shutdown via ctrl+c"); match service_manager.shutdown(shutdown_timeout).await { - Ok(()) => { - debug!("Graceful shutdown complete"); + Ok(elapsed) => { + info!( + remaining = format!("{:.2?}", shutdown_timeout - elapsed), + "graceful shutdown complete" + ); + info!("graceful shutdown complete"); } Err(pending_services) => { warn!( - "Graceful shutdown elapsed - the following service(s) did not complete: {}", - join(pending_services) + pending_count = pending_services.len(), + pending_services = ?pending_services, + "graceful shutdown elapsed - {} service(s) did not complete", + pending_services.len() ); exit_code = 2; } @@ -183,6 +208,6 @@ async fn main() { } } - info!(exit_code = exit_code, "Shutdown complete"); + info!(exit_code, "application shutdown complete"); std::process::exit(exit_code); } diff --git a/src/services/bot.rs b/src/services/bot.rs index 38aa84c..72db051 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::{error, warn}; +use tracing::{debug, error}; /// Discord bot service implementation pub struct BotService { @@ -28,11 +28,11 @@ impl Service for BotService { async fn run(&mut self) -> Result<(), anyhow::Error> { match self.client.start().await { Ok(()) => { - warn!(service = "bot", "Stopped early."); + debug!(service = "bot", "stopped early."); Err(anyhow::anyhow!("bot stopped early")) } Err(e) => { - error!(service = "bot", "Error: {e:?}"); + error!(service = "bot", "error: {e:?}"); Err(e.into()) } } diff --git a/src/services/manager.rs b/src/services/manager.rs index 4113347..0dc85a5 100644 --- a/src/services/manager.rs +++ b/src/services/manager.rs @@ -2,7 +2,7 @@ use std::collections::HashMap; use std::time::Duration; use tokio::sync::broadcast; use tokio::task::JoinHandle; -use tracing::{error, info, warn}; +use tracing::{debug, error, info, warn}; use crate::services::{Service, ServiceResult, run_service}; @@ -30,12 +30,21 @@ impl ServiceManager { /// Spawn all registered services pub fn spawn_all(&mut self) { + let service_count = self.registered_services.len(); + let service_names: Vec<_> = self.registered_services.keys().cloned().collect(); + for (name, service) in self.registered_services.drain() { let shutdown_rx = self.shutdown_tx.subscribe(); let handle = tokio::spawn(run_service(service, shutdown_rx)); self.running_services.insert(name, handle); } - info!("Spawned {} services", self.running_services.len()); + + info!( + service_count, + services = ?service_names, + "spawned {} services", + service_count + ); } /// Run all services until one completes or fails @@ -49,7 +58,7 @@ impl ServiceManager { } info!( - "ServiceManager running {} services", + "servicemanager running {} services", self.running_services.len() ); @@ -70,7 +79,7 @@ impl ServiceManager { return (completed_name.clone(), result); } Err(e) => { - error!(service = completed_name, "Service task panicked: {e}"); + error!(service = completed_name, "service task panicked: {e}"); return ( completed_name.clone(), ServiceResult::Error(anyhow::anyhow!("Task panic: {e}")), @@ -84,82 +93,65 @@ impl ServiceManager { } } - /// Shutdown all services gracefully with a timeout - /// Returns Ok(()) if all services shut down, or Err(Vec) with names of services that timed out - pub async fn shutdown(mut self, timeout: Duration) -> Result<(), Vec> { - if self.running_services.is_empty() { - info!("No services to shutdown"); - return Ok(()); - } + /// Shutdown all services gracefully with a timeout. + /// + /// If any service fails to shutdown, it will return an error containing the names of the services that failed to shutdown. + /// If all services shutdown successfully, the function will return the duration elapsed. + pub async fn shutdown(&mut self, timeout: Duration) -> Result> { + let service_count = self.running_services.len(); + let service_names: Vec<_> = self.running_services.keys().cloned().collect(); info!( - "Shutting down {} services with {}s timeout", - self.running_services.len(), - timeout.as_secs() + service_count, + services = ?service_names, + timeout = format!("{:.2?}", timeout), + "shutting down {} services with {:?} timeout", + service_count, + timeout ); - // Signal all services to shutdown + // Send shutdown signal to all services let _ = self.shutdown_tx.send(()); - // Wait for all services to complete with timeout - let shutdown_result = tokio::time::timeout(timeout, async { - let mut completed = Vec::new(); - let mut failed = Vec::new(); + // Wait for all services to complete + let start_time = std::time::Instant::now(); + let mut pending_services = Vec::new(); - while !self.running_services.is_empty() { - let mut to_remove = Vec::new(); - - for (name, handle) in &mut self.running_services { - if handle.is_finished() { - to_remove.push(name.clone()); - } + for (name, handle) in self.running_services.drain() { + match tokio::time::timeout(timeout, handle).await { + Ok(Ok(_)) => { + debug!(service = name, "service shutdown completed"); } - - for name in to_remove { - let handle = self.running_services.remove(&name).unwrap(); - match handle.await { - Ok(ServiceResult::GracefulShutdown) => { - completed.push(name); - } - Ok(ServiceResult::NormalCompletion) => { - warn!(service = name, "Service completed normally during shutdown"); - completed.push(name); - } - Ok(ServiceResult::Error(e)) => { - error!(service = name, "Service error during shutdown: {e}"); - failed.push(name); - } - Err(e) => { - error!(service = name, "Service panic during shutdown: {e}"); - failed.push(name); - } - } + Ok(Err(e)) => { + warn!(service = name, error = ?e, "service shutdown failed"); + pending_services.push(name); } - - if !self.running_services.is_empty() { - tokio::time::sleep(Duration::from_millis(10)).await; + Err(_) => { + warn!(service = name, "service shutdown timed out"); + pending_services.push(name); } } + } - (completed, failed) - }) - .await; - - match shutdown_result { - Ok((completed, failed)) => { - if !completed.is_empty() { - info!("Services shutdown completed: {}", completed.join(", ")); - } - if !failed.is_empty() { - warn!("Services had errors during shutdown: {}", failed.join(", ")); - } - Ok(()) - } - Err(_) => { - // Timeout occurred - return names of services that didn't complete - let pending_services: Vec = self.running_services.keys().cloned().collect(); - Err(pending_services) - } + let elapsed = start_time.elapsed(); + if pending_services.is_empty() { + info!( + service_count, + elapsed = format!("{:.2?}", elapsed), + "services shutdown completed: {}", + service_names.join(", ") + ); + Ok(elapsed) + } else { + warn!( + pending_count = pending_services.len(), + pending_services = ?pending_services, + elapsed = format!("{:.2?}", elapsed), + "services shutdown completed with {} pending: {}", + pending_services.len(), + pending_services.join(", ") + ); + Err(pending_services) } } } diff --git a/src/services/mod.rs b/src/services/mod.rs index b236d36..1c5f84a 100644 --- a/src/services/mod.rs +++ b/src/services/mod.rs @@ -33,16 +33,16 @@ pub async fn run_service( mut shutdown_rx: broadcast::Receiver<()>, ) -> ServiceResult { let name = service.name(); - info!(service = name, "Service started"); + info!(service = name, "service started"); let work = async { match service.run().await { Ok(()) => { - warn!(service = name, "Service completed unexpectedly"); + warn!(service = name, "service completed unexpectedly"); ServiceResult::NormalCompletion } Err(e) => { - error!(service = name, "Service failed: {e}"); + error!(service = name, "service failed: {e}"); ServiceResult::Error(e) } } @@ -51,18 +51,18 @@ pub async fn run_service( tokio::select! { result = work => result, _ = shutdown_rx.recv() => { - info!(service = name, "Shutting down..."); + info!(service = name, "shutting down..."); let start_time = std::time::Instant::now(); match service.shutdown().await { Ok(()) => { let elapsed = start_time.elapsed(); - info!(service = name, "Shutdown completed in {elapsed:.2?}"); + info!(service = name, "shutdown completed in {elapsed:.2?}"); ServiceResult::GracefulShutdown } Err(e) => { let elapsed = start_time.elapsed(); - error!(service = name, "Shutdown failed after {elapsed:.2?}: {e}"); + error!(service = name, "shutdown failed after {elapsed:.2?}: {e}"); ServiceResult::Error(e) } } diff --git a/src/services/web.rs b/src/services/web.rs index 339e9d3..b176298 100644 --- a/src/services/web.rs +++ b/src/services/web.rs @@ -36,13 +36,13 @@ impl Service for WebService { info!( service = "web", link = format!("http://localhost:{}", addr.port()), - "Starting web server", + "starting web server", ); let listener = TcpListener::bind(addr).await?; debug!( service = "web", - "Web server listening on {}", + "web server listening on {}", format!("http://{}", addr) ); @@ -56,12 +56,12 @@ impl Service for WebService { let _ = shutdown_rx.recv().await; debug!( service = "web", - "Received shutdown signal, starting graceful shutdown" + "received shutdown signal, starting graceful shutdown" ); }) .await?; - info!(service = "web", "Web server stopped"); + info!(service = "web", "web server stopped"); Ok(()) } @@ -71,7 +71,7 @@ impl Service for WebService { } else { warn!( service = "web", - "No shutdown channel found, cannot trigger graceful shutdown" + "no shutdown channel found, cannot trigger graceful shutdown" ); } Ok(()) diff --git a/src/web/routes.rs b/src/web/routes.rs index e8804d6..4a10703 100644 --- a/src/web/routes.rs +++ b/src/web/routes.rs @@ -3,6 +3,7 @@ use axum::{Router, extract::State, response::Json, routing::get}; use serde_json::{Value, json}; use std::sync::Arc; +use tracing::{debug, info}; /// Shared application state for web server #[derive(Clone)] @@ -15,6 +16,7 @@ pub struct BannerState { pub fn create_banner_router(state: BannerState) -> Router { Router::new() .route("/", get(root)) + .route("/health", get(health)) .route("/status", get(status)) .route("/metrics", get(metrics)) .with_state(state) @@ -22,6 +24,7 @@ pub fn create_banner_router(state: BannerState) -> Router { /// Root endpoint - shows API info async fn root() -> Json { + debug!("root endpoint accessed"); Json(json!({ "message": "Banner Discord Bot API", "version": "0.1.0", @@ -33,6 +36,15 @@ async fn root() -> Json { })) } +/// Health check endpoint +async fn health() -> Json { + info!("health check requested"); + Json(json!({ + "status": "healthy", + "timestamp": chrono::Utc::now().to_rfc3339() + })) +} + /// Status endpoint showing bot and system status async fn status(State(_state): State) -> Json { // For now, return basic status without accessing private fields