From 92acb07b04c08b02ccc4420da0c331fcba9696c1 Mon Sep 17 00:00:00 2001 From: Ryan Walters Date: Wed, 17 Sep 2025 04:05:59 -0500 Subject: [PATCH] feat: setup tracing calls throughout project --- pacman-server/src/auth/github.rs | 21 ++++++++++++++++++--- pacman-server/src/main.rs | 12 ++++++++---- pacman-server/src/routes.rs | 20 ++++++++++++++++++-- pacman-server/src/session.rs | 7 +++++-- 4 files changed, 49 insertions(+), 11 deletions(-) diff --git a/pacman-server/src/auth/github.rs b/pacman-server/src/auth/github.rs index a49ec51..f677431 100644 --- a/pacman-server/src/auth/github.rs +++ b/pacman-server/src/auth/github.rs @@ -5,6 +5,7 @@ use serde::{Deserialize, Serialize}; use std::sync::Arc; use std::time::{Duration, Instant}; +use tracing::{trace, warn}; use crate::{ auth::provider::{AuthUser, OAuthProvider}, @@ -43,6 +44,7 @@ pub async fn fetch_github_user( .await?; if !response.status().is_success() { + warn!(status = %response.status(), endpoint = "/user", "GitHub API returned an error"); return Err(format!("GitHub API error: {}", response.status()).into()); } @@ -110,11 +112,13 @@ impl OAuthProvider for GitHubProvider { self.pkce.remove(entry.key()); } } + trace!(state = %csrf_state.secret(), "Generated OAuth authorization URL"); Redirect::to(authorize_url.as_str()).into_response() } async fn handle_callback(&self, query: &std::collections::HashMap) -> Result { if let Some(err) = query.get("error") { + warn!(error = %err, desc = query.get("error_description").map(|s| s.as_str()), "OAuth callback contained an error"); return Err(ErrorResponse::bad_request( err.clone(), query.get("error_description").cloned(), @@ -129,6 +133,7 @@ impl OAuthProvider for GitHubProvider { .cloned() .ok_or_else(|| ErrorResponse::bad_request("invalid_request", Some("missing state".into())))?; let Some((verifier, created_at)) = self.pkce.remove(&state).map(|e| e.1) else { + warn!("Missing PKCE verifier for state parameter"); return Err(ErrorResponse::bad_request( "invalid_request", Some("missing pkce verifier for state".into()), @@ -136,6 +141,7 @@ impl OAuthProvider for GitHubProvider { }; // Verify PKCE TTL if Instant::now().duration_since(created_at) > Duration::from_secs(5 * 60) { + warn!("PKCE verifier expired for state parameter"); return Err(ErrorResponse::bad_request( "invalid_request", Some("expired pkce verifier for state".into()), @@ -148,14 +154,23 @@ impl OAuthProvider for GitHubProvider { .set_pkce_verifier(PkceCodeVerifier::new(verifier)) .request_async(&self.http) .await - .map_err(|e| ErrorResponse::bad_gateway("token_exchange_failed", Some(e.to_string())))?; + .map_err(|e| { + warn!(error = %e, "Token exchange with GitHub failed"); + ErrorResponse::bad_gateway("token_exchange_failed", Some(e.to_string())) + })?; let user = fetch_github_user(&self.http, token.access_token().secret()) .await - .map_err(|e| ErrorResponse::bad_gateway("github_api_error", Some(format!("failed to fetch user: {}", e))))?; + .map_err(|e| { + warn!(error = %e, "Failed to fetch GitHub user profile"); + ErrorResponse::bad_gateway("github_api_error", Some(format!("failed to fetch user: {}", e))) + })?; let _emails = fetch_github_emails(&self.http, token.access_token().secret()) .await - .map_err(|e| ErrorResponse::bad_gateway("github_api_error", Some(format!("failed to fetch emails: {}", e))))?; + .map_err(|e| { + warn!(error = %e, "Failed to fetch GitHub user emails"); + ErrorResponse::bad_gateway("github_api_error", Some(format!("failed to fetch emails: {}", e))) + })?; Ok(AuthUser { id: user.id.to_string(), diff --git a/pacman-server/src/main.rs b/pacman-server/src/main.rs index 3efc1f6..83c36df 100644 --- a/pacman-server/src/main.rs +++ b/pacman-server/src/main.rs @@ -16,6 +16,7 @@ use std::time::Instant; #[cfg(unix)] use tokio::signal::unix::{signal, SignalKind}; use tokio::sync::{watch, Notify}; +use tracing::{info, trace, warn}; #[tokio::main] async fn main() { @@ -30,6 +31,7 @@ async fn main() { // Initialize tracing subscriber logging::setup_logging(&config); + trace!(host = %config.host, port = config.port, shutdown_timeout_seconds = config.shutdown_timeout_seconds, "Loaded server configuration"); let addr = std::net::SocketAddr::new(config.host, config.port); let shutdown_timeout = std::time::Duration::from_secs(config.shutdown_timeout_seconds as u64); @@ -44,7 +46,9 @@ async fn main() { .with_state(AppState::new(config, auth)) .layer(CookieLayer::default()); + info!(%addr, "Starting HTTP server bind"); let listener = tokio::net::TcpListener::bind(addr).await.unwrap(); + info!(%addr, "HTTP server listening"); // coordinated graceful shutdown with timeout let notify = Arc::new(Notify::new()); @@ -69,7 +73,7 @@ async fn main() { } } tokio::time::sleep(shutdown_timeout).await; - eprintln!("shutdown timeout elapsed (>{:.2?}) - forcing exit", shutdown_timeout); + warn!(timeout = ?shutdown_timeout, "Shutdown timeout elapsed; forcing exit"); std::process::exit(1); }; @@ -86,7 +90,7 @@ async fn main() { let elapsed = now.duration_since(signaled_at); if elapsed < shutdown_timeout { let remaining = shutdown_timeout - elapsed; - eprintln!("graceful shutdown complete, remaining time: {:.2?}", remaining); + info!(remaining = ?remaining, "Graceful shutdown complete"); } } res.unwrap(); @@ -98,14 +102,14 @@ async fn main() { async fn shutdown_signal() -> Instant { let ctrl_c = async { tokio::signal::ctrl_c().await.expect("failed to install Ctrl+C handler"); - eprintln!("received Ctrl+C, shutting down"); + warn!(signal = "ctrl_c", "Received Ctrl+C; shutting down"); }; #[cfg(unix)] let sigterm = async { let mut term_stream = signal(SignalKind::terminate()).expect("failed to install SIGTERM handler"); term_stream.recv().await; - eprintln!("received SIGTERM, shutting down"); + warn!(signal = "sigterm", "Received SIGTERM; shutting down"); }; #[cfg(not(unix))] diff --git a/pacman-server/src/routes.rs b/pacman-server/src/routes.rs index 8e9fed9..f360a04 100644 --- a/pacman-server/src/routes.rs +++ b/pacman-server/src/routes.rs @@ -4,6 +4,7 @@ use axum::{ response::{IntoResponse, Redirect}, }; use axum_cookie::CookieManager; +use tracing::{debug, info, trace, warn}; use crate::{app::AppState, errors::ErrorResponse, session}; @@ -20,9 +21,13 @@ pub async fn oauth_authorize_handler( Path(provider): Path, ) -> axum::response::Response { let Some(prov) = app_state.auth.get(&provider) else { + warn!(%provider, "Unknown OAuth provider"); return ErrorResponse::bad_request("invalid_provider", Some(provider)).into_response(); }; - prov.authorize().await + trace!(provider = %provider, "Starting OAuth authorization"); + let resp = prov.authorize().await; + trace!(provider = %provider, "Redirecting to provider authorization page"); + resp } pub async fn oauth_callback_handler( @@ -32,9 +37,11 @@ pub async fn oauth_callback_handler( cookie: CookieManager, ) -> axum::response::Response { let Some(prov) = app_state.auth.get(&provider) else { + warn!(%provider, "Unknown OAuth provider"); return ErrorResponse::bad_request("invalid_provider", Some(provider)).into_response(); }; if let Some(error) = params.error { + warn!(%provider, error = %error, desc = ?params.error_description, "OAuth callback returned an error"); return ErrorResponse::bad_request(error, params.error_description).into_response(); } let mut q = std::collections::HashMap::new(); @@ -46,24 +53,32 @@ pub async fn oauth_callback_handler( } let user = match prov.handle_callback(&q).await { Ok(u) => u, - Err(e) => return e.into_response(), + Err(e) => { + warn!(%provider, "OAuth callback handling failed"); + return e.into_response(); + } }; let session_token = session::create_jwt_for_user(&user, &app_state.jwt_encoding_key); app_state.sessions.insert(session_token.clone(), user); session::set_session_cookie(&cookie, &session_token); + info!(%provider, "Signed in successfully"); (StatusCode::FOUND, Redirect::to("/profile")).into_response() } pub async fn profile_handler(State(app_state): State, cookie: CookieManager) -> axum::response::Response { let Some(token_str) = session::get_session_token(&cookie) else { + debug!("Missing session cookie"); return ErrorResponse::unauthorized("missing session cookie").into_response(); }; if !session::verify_jwt(&token_str, &app_state.jwt_decoding_key) { + debug!("Invalid session token"); return ErrorResponse::unauthorized("invalid session token").into_response(); } if let Some(user) = app_state.sessions.get(&token_str) { + trace!("Fetched user profile"); return axum::Json(&*user).into_response(); } + debug!("Session not found"); ErrorResponse::unauthorized("session not found").into_response() } @@ -73,5 +88,6 @@ pub async fn logout_handler(State(app_state): State, cookie: CookieMan app_state.sessions.remove(&token_str); } session::clear_session_cookie(&cookie); + info!("Signed out successfully"); (StatusCode::FOUND, Redirect::to("/")).into_response() } diff --git a/pacman-server/src/session.rs b/pacman-server/src/session.rs index 4bdd121..4ab7061 100644 --- a/pacman-server/src/session.rs +++ b/pacman-server/src/session.rs @@ -4,6 +4,7 @@ use axum_cookie::{cookie::Cookie, prelude::SameSite, CookieManager}; use jsonwebtoken::{decode, encode, Algorithm, DecodingKey, EncodingKey, Header, Validation}; use crate::auth::provider::AuthUser; +use tracing::{trace, warn}; pub const SESSION_COOKIE_NAME: &str = "session"; pub const JWT_TTL_SECS: u64 = 60 * 60; // 1 hour @@ -27,7 +28,9 @@ pub fn create_jwt_for_user(user: &AuthUser, encoding_key: &EncodingKey) -> Strin iat: now, exp: now + JWT_TTL_SECS as usize, }; - encode(&Header::new(Algorithm::HS256), &claims, encoding_key).expect("jwt sign") + let token = encode(&Header::new(Algorithm::HS256), &claims, encoding_key).expect("jwt sign"); + trace!(sub = %claims.sub, exp = claims.exp, "Created session JWT"); + token } pub fn verify_jwt(token: &str, decoding_key: &DecodingKey) -> bool { @@ -36,7 +39,7 @@ pub fn verify_jwt(token: &str, decoding_key: &DecodingKey) -> bool { match decode::(token, decoding_key, &validation) { Ok(_) => true, Err(e) => { - println!("JWT verification failed: {:?}", e); + warn!(error = %e, "Session JWT verification failed"); false } }