feat: improve logging, solve lints, improve implementations, remove unused code, standardize things

This commit is contained in:
2025-08-27 12:13:09 -05:00
parent 9972357cf6
commit ac70306c04
10 changed files with 168 additions and 121 deletions

View File

@@ -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.

View File

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

View File

@@ -35,10 +35,17 @@ impl SessionManager {
/// Ensures a valid session is available, creating one if necessary
pub fn ensure_session(&self) -> Result<String> {
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(())
}

View File

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

View File

@@ -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<String>| {
strings
.iter()
.map(|s| format!("\"{}\"", s))
.collect::<Vec<_>>()
.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);
}

View File

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

View File

@@ -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<String>) with names of services that timed out
pub async fn shutdown(mut self, timeout: Duration) -> Result<(), Vec<String>> {
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<Duration, Vec<String>> {
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<String> = 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)
}
}
}

View File

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

View File

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

View File

@@ -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<Value> {
debug!("root endpoint accessed");
Json(json!({
"message": "Banner Discord Bot API",
"version": "0.1.0",
@@ -33,6 +36,15 @@ async fn root() -> Json<Value> {
}))
}
/// Health check endpoint
async fn health() -> Json<Value> {
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<BannerState>) -> Json<Value> {
// For now, return basic status without accessing private fields