feat: setup tracing calls throughout project

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<String, String>) -> Result<AuthUser, ErrorResponse> {
         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(),

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

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<String>,
 ) -> 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<AppState>, 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<AppState>, cookie: CookieMan
         app_state.sessions.remove(&token_str);
     }
     session::clear_session_cookie(&cookie);
+    info!("Signed out successfully");
     (StatusCode::FOUND, Redirect::to("/")).into_response()
 }

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::<Claims>(token, decoding_key, &validation) {
         Ok(_) => true,
         Err(e) => {
-            println!("JWT verification failed: {:?}", e);
+            warn!(error = %e, "Session JWT verification failed");
             false
         }
     }