diff --git a/Cargo.lock b/Cargo.lock index 17efcbd..9cc8e05 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1887,6 +1887,7 @@ dependencies = [ "tower-http", "tower_governor", "tracing", + "tracing-journald", "tracing-subscriber", "tungstenite", "uuid", @@ -2871,6 +2872,17 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-journald" +version = "0.3.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2d3a81ed245bfb62592b1e2bc153e77656d94ee6a0497683a65a12ccaf2438d0" +dependencies = [ + "libc", + "tracing-core", + "tracing-subscriber", +] + [[package]] name = "tracing-log" version = "0.2.0" @@ -2882,6 +2894,16 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.23" @@ -2892,12 +2914,15 @@ dependencies = [ "nu-ansi-term", "once_cell", "regex-automata", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 9ba0530..7647d60 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -26,6 +26,7 @@ tokio-util = "0.7.18" tower-http = { version = "0.6.8", features = ["fs", "trace"] } tower_governor = "0.8.0" tracing = "0.1.44" -tracing-subscriber = { version = "0.3.23", features = ["env-filter"] } +tracing-subscriber = { version = "0.3.23", features = ["env-filter", "json"] } +tracing-journald = "0.3" tungstenite = "0.29.0" uuid = { version = "1.23.1", features = ["serde", "v7"] } diff --git a/src/attachment.rs b/src/attachment.rs index f9b0f2a..5819240 100644 --- a/src/attachment.rs +++ b/src/attachment.rs @@ -103,8 +103,10 @@ pub fn spawn( let inserted = match inserted { Ok(result) => result, - Err(_) => { - // TODO - Logging. FK gone (attachment reaped) or DB error. + Err(e) => { + // Often a benign FK-gone (the attachment was reaped mid-upload); + // could also be a real DB error. Either way, abandon this upload. + tracing::warn!(error = %e, %attachment_id, "upload: chunk insert failed (attachment reaped or DB error)"); break; } }; @@ -123,8 +125,8 @@ pub fn spawn( .await { Ok(count) => count, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %attachment_id, "upload: chunk count query failed"); break; } }; @@ -160,7 +162,8 @@ pub fn spawn( // All chunks present but content doesn't match the declared // hash/size. Keep-first means re-sending can't fix it; leave the // row incomplete for the reaper and report a generic failure. - // TODO - Logging (details server-side only) + // Details stay server-side; the client only sees a generic error. + tracing::warn!(%attachment_id, "upload: content does not match declared hash/size"); let _ = user_tx .send(ServerEvent::Error { error: "attachment upload failed".to_owned(), @@ -168,8 +171,8 @@ pub fn spawn( .await; break; } - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %attachment_id, "upload: verification query failed"); break; } } @@ -223,8 +226,8 @@ pub fn download( .await; return; } - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %attachment_id, "download: lookup query failed"); let _ = user_tx.send(ServerEvent::Failed).await; return; } @@ -254,8 +257,13 @@ pub fn download( Ok(Some(data)) => data, // A gap in a "complete" attachment shouldn't be possible; stop and // report a generic failure rather than send a truncated stream. - Ok(None) | Err(_) => { - // TODO - Logging + Ok(None) => { + tracing::error!(%attachment_id, seq, "download: missing chunk in a complete attachment"); + let _ = user_tx.send(ServerEvent::Failed).await; + return; + } + Err(e) => { + tracing::error!(error = %e, %attachment_id, seq, "download: chunk fetch failed"); let _ = user_tx.send(ServerEvent::Failed).await; return; } diff --git a/src/auth.rs b/src/auth.rs index e118286..fab273a 100644 --- a/src/auth.rs +++ b/src/auth.rs @@ -22,8 +22,17 @@ struct AuthRequest { #[derive(Debug)] pub enum AuthResult { - Ok { user_id: Uuid }, + Ok { + user_id: Uuid, + }, + /// Credentials were rejected: unknown user or wrong password. A genuine + /// authentication failure, audited as such by the caller. Failed, + /// The attempt could not be completed due to a server-side fault (DB error, + /// corrupt stored hash, auth actor gone). Already logged at `error!` where it + /// occurs; the caller treats it as no-auth but does NOT audit it as a failed + /// login, since the credentials were never actually judged. + Error, } #[derive(Clone)] @@ -47,9 +56,9 @@ impl AuthHandle { .await .is_err() { - return AuthResult::Failed; + return AuthResult::Error; } - rx.await.unwrap_or(AuthResult::Failed) + rx.await.unwrap_or(AuthResult::Error) } } @@ -70,9 +79,9 @@ async fn authenticate( .await { Ok(maybe_data) => maybe_data, - Err(_e) => { - // TODO - Logging - return AuthResult::Failed; + Err(e) => { + tracing::error!(error = %e, "auth: credential lookup query failed"); + return AuthResult::Error; } }; @@ -80,9 +89,9 @@ async fn authenticate( Some((user_id, hash)) => { let parsed = match PasswordHash::new(&hash) { Ok(parsed) => parsed, - Err(_e) => { - // TODO - Logging - return AuthResult::Failed; + Err(e) => { + tracing::error!(error = %e, %user_id, "auth: stored password hash is unparseable"); + return AuthResult::Error; } }; let verified = Argon2::default() @@ -95,9 +104,11 @@ async fn authenticate( // Perform a dummy check to take the same amount of time as if the user exists let parsed = match PasswordHash::new(&dummy_hash) { Ok(parsed) => parsed, - Err(_e) => { - // TODO - Logging - return AuthResult::Failed; + Err(e) => { + // The dummy hash is generated once at startup, so this should be + // unreachable -- log loudly if it ever isn't. + tracing::error!(error = %e, "auth: dummy password hash is unparseable"); + return AuthResult::Error; } }; let _ = Argon2::default() diff --git a/src/config.rs b/src/config.rs index 293fc2c..662ac80 100644 --- a/src/config.rs +++ b/src/config.rs @@ -1,5 +1,7 @@ use serde::Deserialize; +use crate::logging::LogFormat; + #[derive(Debug, Deserialize, Clone)] pub struct Config { pub database_url: String, @@ -30,6 +32,14 @@ pub struct Config { pub max_chunk_bytes: usize, pub admin_username: String, pub admin_credential: String, + // Filter directive used when RUST_LOG is unset (e.g. "info", "relay=debug"). + // RUST_LOG, when present, always takes precedence. + #[serde(default = "default_log_level")] + pub log_level: String, + // Log output format: "pretty" (stdout, default), "json" (stdout, for log + // shippers), or "journald" (native systemd journal). See logging::LogFormat. + #[serde(default)] + pub log_format: LogFormat, } fn default_bind() -> String { @@ -47,6 +57,9 @@ fn default_retention_days() -> i32 { fn default_reap_interval_secs() -> u64 { 3600 } +fn default_log_level() -> String { + "info".into() +} fn default_max_chunk_bytes() -> usize { // Mirror the framework's own default message size so an unconfigured server // matches axum/tungstenite exactly, minus the frame header since the advertised diff --git a/src/handler.rs b/src/handler.rs index de0b099..6a405e6 100644 --- a/src/handler.rs +++ b/src/handler.rs @@ -22,8 +22,7 @@ pub(crate) async fn ws_handler( } else { String::from("Unknown browser") }; - // TODO tracing - println!("{user_agent} at {addr} connected."); + tracing::debug!(who = %addr, %user_agent, "connection accepted"); // Pin both the message and frame size caps to the configured max chunk payload // (plus the frame header) so the limit a client learns from GetMaxChunkSize is diff --git a/src/lib.rs b/src/lib.rs index 7cba586..2aab447 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -5,6 +5,7 @@ pub mod config; pub mod control; pub mod handler; pub mod hub; +pub mod logging; pub mod message; pub mod model; pub mod reaper; diff --git a/src/logging.rs b/src/logging.rs new file mode 100644 index 0000000..7fad9d4 --- /dev/null +++ b/src/logging.rs @@ -0,0 +1,122 @@ +//! Logging policy and subscriber setup. +//! +//! This module is the single source of truth for *how* the server logs. The +//! conventions below are deliberately mechanical so that the ~150 call sites +//! across the actors stay consistent. +//! +//! ## Levels +//! +//! - `error!` — server-side faults an operator must fix: DB `begin`/`acquire`/ +//! `commit`/query failures, corrupt stored password hash, hash generation +//! failure, actor-channel send failures, reaper failures. +//! - `warn!` — security-relevant denials and anomalies: authorization denials +//! (JIT re-check fails), failed logins, signup rejected when `open_signups` +//! is off. +//! - `info!` — lifecycle and operator-visible state: bind/start, restart/ +//! shutdown requested, connection authenticated, reaper run summaries, and +//! successful admin actions (promote/demote/delete-user/reset-password). +//! - `debug!` — client-caused noise and fine lifecycle: malformed JSON, unknown +//! commands, connection accept/close. +//! - `trace!` — reserved (e.g. per-chunk upload detail) if ever needed. +//! +//! The mapping is mechanical: today's `Err(_e) => { return Failed }` arms become +//! `Err(e) => { error!(error = %e, ...); return Failed }`. The error that was +//! being discarded *is* the log payload — the client still sees only a generic +//! `ServerEvent`, the detail goes to the server log. +//! +//! ## Targets +//! +//! Most events use the default crate target (operational logs). Security- +//! relevant events are emitted under the dedicated [`AUDIT`] target so operators +//! can route or retain them separately, e.g. `RUST_LOG=relay::audit=info`. Use +//! it for authentication outcomes, authorization denials, signup gating, admin +//! actions, and server control (restart/shutdown): +//! +//! ```ignore +//! tracing::warn!(target: logging::AUDIT, actor = %caller, target = %username, "promote denied"); +//! ``` +//! +//! ## Spans +//! +//! Each connection is wrapped in a per-connection span carrying `who` (peer +//! addr) and, once authenticated, `user_id`. Dispatch-side events inherit it. +//! The actors (`auth`/`user`/`room`/`message`) run as *separate tasks*, so their +//! events do not inherit the connection span — they must carry the relevant IDs +//! (`user_id`, `actor`, `target`, `room`) explicitly from the request. +//! +//! ## Field naming +//! +//! Keep keys consistent across call sites: `error = %e`, `who = %addr`, +//! `user_id`, `actor` (the caller), `target` (the object: username/room), +//! `action` (only when the message string isn't enough). +//! +//! ## Never log +//! +//! Passwords, password hashes, attachment bytes, and message body text never go +//! to the log. The [`crate::model::Password`] and [`crate::model::PasswordHash`] +//! newtypes already have redacting `Debug` impls, so they cannot leak through a +//! structured field — keep it that way. +//! +//! ## Retention +//! +//! Logs are written to stdout/stderr as a stream; they are **not** stored in the +//! database and are therefore **not** subject to the [`crate::reaper`], which +//! only ages out DB rows. Retention belongs to the platform layer (journald, +//! Docker/k8s logging drivers, or a log shipper). Audit logs typically warrant a +//! separate, longer-retained sink. If SQL-queryable audit history is ever +//! required, that would be a dedicated `audit_log` table with its own retention +//! policy — deliberately *not* something the message reaper deletes, since an +//! app that erases its own audit trail defeats the purpose of having one. + +use serde::Deserialize; +use tracing_subscriber::{EnvFilter, fmt, prelude::*}; + +/// Tracing target for security-relevant audit events. Route separately via +/// `RUST_LOG=relay::audit=info`. +pub const AUDIT: &str = "relay::audit"; + +/// Output format for the subscriber. +/// +/// - `Pretty` — human-readable formatter to stdout. The default; best for local +/// dev and tests. +/// - `Json` — one JSON object per event to stdout, for log collectors (Loki, +/// CloudWatch, …) that parse fields back out. +/// - `Journald` — write natively to the systemd journal: tracing levels map to +/// journal `PRIORITY` (so `journalctl -p err` works) and each field becomes a +/// real journal field (so `journalctl RELAY_USER_ID=…` works). The intended +/// production format; set `LOG_FORMAT=journald` in the service unit. If the +/// journal socket is unavailable (e.g. running outside systemd), it falls back +/// to the `Pretty` stdout formatter. +#[derive(Debug, Clone, Copy, Default, PartialEq, Deserialize)] +#[serde(rename_all = "lowercase")] +pub enum LogFormat { + #[default] + Pretty, + Json, + Journald, +} + +/// Initialize the global tracing subscriber. Process-once: must be called +/// exactly once, before any logging, and never across a hot restart (a second +/// init would panic). +/// +/// `RUST_LOG`, when set, takes precedence over `level`; otherwise `level` (from +/// config) is used as the filter directive. +pub fn init(level: &str, format: LogFormat) { + let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(level)); + let registry = tracing_subscriber::registry().with(filter); + match format { + LogFormat::Pretty => registry.with(fmt::layer()).init(), + LogFormat::Json => registry.with(fmt::layer().json()).init(), + LogFormat::Journald => match tracing_journald::layer() { + Ok(journald) => registry.with(journald).init(), + // No journal socket (not under systemd, or it's unavailable). Fall + // back to stdout so we still get logs, then report why once the + // subscriber is live. + Err(e) => { + registry.with(fmt::layer()).init(); + tracing::warn!(error = %e, "journald unavailable; falling back to stdout"); + } + }, + } +} diff --git a/src/main.rs b/src/main.rs index 772eb02..f982665 100644 --- a/src/main.rs +++ b/src/main.rs @@ -17,8 +17,12 @@ async fn main() { dotenvy::dotenv().ok(); // Process-once setup. Tracing MUST be initialized exactly once -- it lives - // across restarts, and a second init would panic. - tracing_subscriber::fmt::init(); + // across restarts, and a second init would panic. Log settings and the bind + // address are process-lifetime (a hot restart never re-reads them), so they + // come from this one config read; serve_once re-reads config for everything + // that can change across a restart. + let startup_config = Config::from_env().expect("invalid config"); + relay::logging::init(&startup_config.log_level, startup_config.log_format); // Control plane. Anything inside the app (via `ServerControl` in `AppState`) or // the OS-signal task below sends a `ControlSignal` here to drive the process @@ -38,7 +42,7 @@ async fn main() { // A restart never drops the port: in-flight connections queue in the backlog // instead of being refused, and there's no rebind race. (Changing the bind // address therefore requires a full process restart, not a hot restart.) - let bind = Config::from_env().expect("invalid config").bind; + let bind = startup_config.bind; let listener = std::net::TcpListener::bind(&bind).expect("failed to bind listener"); listener .set_nonblocking(true) @@ -182,7 +186,7 @@ async fn shutdown_signal() { let terminate = std::future::pending::<()>(); tokio::select! { - _ = ctrl_c => { println!("\nSHUTDOWN REQUESTED!") }, - _ = terminate => { println!("\nSHUTDOWN REQUESTED!") }, + _ = ctrl_c => { tracing::info!("received SIGINT (Ctrl-C); shutting down") }, + _ = terminate => { tracing::info!("received SIGTERM; shutting down") }, } } diff --git a/src/message.rs b/src/message.rs index 2ec244c..374881d 100644 --- a/src/message.rs +++ b/src/message.rs @@ -284,8 +284,8 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "send_message: begin transaction failed"); return (MessageResponse::Failed, tx); } }; @@ -307,8 +307,8 @@ async fn handle_request( { Ok(Some(name)) => name, Ok(None) => return (MessageResponse::Failed, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "send_message: room membership lookup failed"); return (MessageResponse::Failed, tx); } }; @@ -319,25 +319,29 @@ async fn handle_request( // server-assigned timestamp, the (round-tripped) content, and the // sender's current display name so the same canonical item can go in the // ack and the live broadcast. - let (message_id, timestamp, content, sender_username) = - match sqlx::query_as::<_, (Uuid, chrono::DateTime, String, String)>( - "INSERT INTO messages (room_id, sender_id, content) + let (message_id, timestamp, content, sender_username) = match sqlx::query_as::< + _, + (Uuid, chrono::DateTime, String, String), + >( + "INSERT INTO messages (room_id, sender_id, content) VALUES ($1, $2, $3) RETURNING message_id, timestamp, content, (SELECT username FROM users WHERE user_id = $2)", - ) - .bind(room_id) - .bind(sender_id) - .bind(content) - .fetch_one(&mut *db) - .await - { - Ok(row) => row, - Err(_e) => { - // TODO - Logging - return (MessageResponse::Failed, tx); - } - }; + ) + .bind(room_id) + .bind(sender_id) + .bind(content) + .fetch_one(&mut *db) + .await + { + Ok(row) => row, + Err(e) => { + // Empty content trips the table CHECK -- a client error rather + // than a server fault, so warn rather than error. + tracing::warn!(error = %e, %room_id, "send_message: message insert failed (e.g. empty content)"); + return (MessageResponse::Failed, tx); + } + }; // Create one incomplete attachment row per declaration, in order, so // the returned ids line up with the client's `attachments`. The bytes @@ -372,8 +376,9 @@ async fn handle_request( .await { Ok(id) => id, - Err(_e) => { - // TODO - Logging + Err(e) => { + // A malformed declaration trips a table CHECK -- client error. + tracing::warn!(error = %e, %message_id, "send_message: attachment insert failed (e.g. malformed declaration)"); return (MessageResponse::Failed, tx); } }; @@ -393,7 +398,7 @@ async fn handle_request( // watermark to this message so their own posts never show as unread to // them. Forward-only guard, though the just-inserted id is always the // newest. Part of the same transaction as the insert. - if let Err(_e) = sqlx::query( + if let Err(e) = sqlx::query( "UPDATE memberships SET last_read_message_id = $3 WHERE room_id = $1 AND user_id = $2 @@ -405,7 +410,7 @@ async fn handle_request( .execute(&mut *db) .await { - // TODO - Logging + tracing::error!(error = %e, %room_id, %message_id, "send_message: sender watermark update failed"); return (MessageResponse::Failed, tx); } @@ -443,8 +448,8 @@ async fn handle_request( tx, ) } - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, %message_id, "send_message: commit failed"); (MessageResponse::Failed, tx) } } @@ -480,8 +485,9 @@ async fn handle_request( match result { Ok(_) => (MessageResponse::Success, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + // An empty emoji trips the table CHECK -- client error. + tracing::warn!(error = %e, %message_id, "add_reaction: insert failed (e.g. empty emoji)"); (MessageResponse::Failed, tx) } } @@ -514,8 +520,8 @@ async fn handle_request( match result { Ok(_) => (MessageResponse::Success, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %message_id, "remove_reaction: delete failed"); (MessageResponse::Failed, tx) } } @@ -538,8 +544,8 @@ async fn handle_request( let room_id = match resolve_member_room(&pool, &room_name, user_id).await { Ok(Some(id)) => id, Ok(None) => return (MessageResponse::Failed, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_messages: room resolution failed"); return (MessageResponse::Failed, tx); } }; @@ -552,8 +558,8 @@ async fn handle_request( }, tx, ), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "get_messages: history query failed"); (MessageResponse::Failed, tx) } } @@ -570,8 +576,8 @@ async fn handle_request( let room_id = match resolve_member_room(&pool, &room_name, user_id).await { Ok(Some(id)) => id, Ok(None) => return (MessageResponse::Failed, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "mark_read: room resolution failed"); return (MessageResponse::Failed, tx); } }; @@ -596,8 +602,8 @@ async fn handle_request( match result { Ok(_) => (MessageResponse::Success, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "mark_read: watermark update failed"); (MessageResponse::Failed, tx) } } @@ -630,8 +636,8 @@ async fn handle_request( .collect(); (MessageResponse::UnreadSummary { rooms }, tx) } - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %user_id, "get_unread_summary: query failed"); (MessageResponse::Failed, tx) } } diff --git a/src/reaper.rs b/src/reaper.rs index 4bcc96c..221b8e2 100644 --- a/src/reaper.rs +++ b/src/reaper.rs @@ -17,8 +17,8 @@ pub fn spawn(shutdown: CancellationToken, pool: PgPool, retention_days: i32, int loop { select! { _ = tick.tick() => { - if let Err(_e) = reap(&pool, retention_days).await { - // TODO - Logging + if let Err(e) = reap(&pool, retention_days).await { + tracing::error!(error = %e, "reaper: run failed"); } } _ = shutdown.cancelled() => break, @@ -32,49 +32,68 @@ pub fn spawn(shutdown: CancellationToken, pool: PgPool, retention_days: i32, int // e.g. from tests. pub async fn reap(pool: &PgPool, retention_days: i32) -> Result<(), sqlx::Error> { let mut tx = pool.begin().await?; - sqlx::query("DELETE FROM messages WHERE timestamp < now() - make_interval(days => $1)") - .bind(retention_days) - .execute(&mut *tx) - .await?; + let messages = + sqlx::query("DELETE FROM messages WHERE timestamp < now() - make_interval(days => $1)") + .bind(retention_days) + .execute(&mut *tx) + .await? + .rows_affected(); - sqlx::query( + let rooms = sqlx::query( "DELETE FROM rooms r WHERE NOT EXISTS (SELECT 1 FROM messages m WHERE m.room_id = r.room_id) AND uuid_extract_timestamp(r.room_id) < now() - make_interval(days => $1)", ) .bind(retention_days) .execute(&mut *tx) - .await?; + .await? + .rows_affected(); // Pending invites and join requests age out by their own creation time, so // ones that are never acted on (accepted/declined, approved/rejected) can't // accumulate unbounded. (Those for a reaped room are already gone via the // ON DELETE CASCADE above; this handles stale rows in rooms that survive.) - sqlx::query("DELETE FROM room_invites WHERE created_at < now() - make_interval(days => $1)") - .bind(retention_days) - .execute(&mut *tx) - .await?; + let invites = sqlx::query( + "DELETE FROM room_invites WHERE created_at < now() - make_interval(days => $1)", + ) + .bind(retention_days) + .execute(&mut *tx) + .await? + .rows_affected(); - sqlx::query( + let join_requests = sqlx::query( "DELETE FROM room_join_requests WHERE created_at < now() - make_interval(days => $1)", ) .bind(retention_days) .execute(&mut *tx) - .await?; + .await? + .rows_affected(); // Uploads abandoned mid-stream: the attachment row and any partial chunks were // committed alongside a still-young message, so neither the message rule above // nor the parent's ON DELETE CASCADE will reclaim them. Sweep incomplete rows // past the grace period; their chunks cascade. Completed attachments are left // to age out with their message. Uses the message_attachments_incomplete index. - sqlx::query( + let incomplete_attachments = sqlx::query( "DELETE FROM message_attachments WHERE NOT is_complete AND created_at < now() - make_interval(hours => $1)", ) .bind(INCOMPLETE_UPLOAD_GRACE_HOURS) .execute(&mut *tx) - .await?; + .await? + .rows_affected(); + + tx.commit().await?; + + tracing::info!( + messages, + rooms, + invites, + join_requests, + incomplete_attachments, + "reaper run complete" + ); - tx.commit().await + Ok(()) } diff --git a/src/room.rs b/src/room.rs index 6c05339..4c748dc 100644 --- a/src/room.rs +++ b/src/room.rs @@ -472,12 +472,15 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "new_room: begin transaction failed"); return (RoomResponse::Failed, tx); } }; + // Captured for the audit log below; room_name is consumed by the insert. + let room_name_for_log = room_name.clone(); + // Create the room with the requested visibility let room_id: Uuid = match sqlx::query( "INSERT INTO rooms (room_name, is_public, is_discoverable) @@ -492,23 +495,25 @@ async fn handle_request( { Ok(Some(row)) => match row.try_get("room_id") { Ok(room_id) => room_id, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "new_room: room_id column read failed"); return (RoomResponse::Failed, tx); } }, Ok(None) => { - // TODO - Logging + tracing::error!("new_room: insert returned no row"); return (RoomResponse::Failed, tx); } - Err(_e) => { - // TODO - Logging + Err(e) => { + // Commonly a unique-violation (room name already taken), a client + // error rather than a server fault -- warn rather than error. + tracing::warn!(error = %e, "new_room: room insert failed (e.g. duplicate name)"); return (RoomResponse::Failed, tx); } }; // Seed the creator as the room's first member and owner - if let Err(_e) = sqlx::query( + if let Err(e) = sqlx::query( "INSERT INTO memberships (room_id, user_id, is_owner) VALUES ($1, $2, true)", ) .bind(room_id) @@ -516,14 +521,17 @@ async fn handle_request( .execute(&mut *db) .await { - // TODO - Logging + tracing::error!(error = %e, %room_id, "new_room: owner membership insert failed"); return (RoomResponse::Failed, tx); } match db.commit().await { - Ok(_) => (RoomResponse::RoomCreated { room_id }, tx), - Err(_e) => { - // TODO - Logging + Ok(_) => { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_name_for_log, %room_id, "room created"); + (RoomResponse::RoomCreated { room_id }, tx) + } + Err(e) => { + tracing::error!(error = %e, %room_id, "new_room: commit failed"); (RoomResponse::Failed, tx) } } @@ -537,24 +545,33 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "add_room_owner: begin transaction failed"); return (RoomResponse::Failed, tx); } }; + // Captured for audit/denial logs; new_owner_username is consumed below. + let new_owner_for_log = new_owner_username.clone(); + // Authorize: caller must own the room (or be an admin). "No such // room" and "not authorized" both return Failed so existence isn't // leaked. let (room_id, authorized) = match gate_room(&mut db, source_user_id, &room_name).await { Ok(Some(gate)) => gate, - Ok(None) | Err(_) => { - // TODO - Logging + // No such room: existence-hidden, not a fault. + Ok(None) => { + tracing::debug!(room = %room_name, "add_room_owner: no such room"); + return (RoomResponse::Failed, tx); + } + Err(e) => { + tracing::error!(error = %e, "add_room_owner: room authorization lookup failed"); return (RoomResponse::Failed, tx); } }; if !authorized { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_name, "add_room_owner denied: caller is not an owner or admin"); return (RoomResponse::Failed, tx); } @@ -569,12 +586,12 @@ async fn handle_request( Ok(maybe_user_id) => match maybe_user_id { Some(row) => row, None => { - // TODO - Logging + tracing::debug!(target = %new_owner_for_log, "add_room_owner: target user not found"); return (RoomResponse::Failed, tx); } }, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "add_room_owner: target user lookup failed"); return (RoomResponse::Failed, tx); } }; @@ -583,8 +600,8 @@ async fn handle_request( let user_id = match maybe_user_id { Ok(user_id) => user_id, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "add_room_owner: user_id column read failed"); return (RoomResponse::Failed, tx); } }; @@ -605,8 +622,8 @@ async fn handle_request( .await { Ok(maybe) => maybe, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "add_room_owner: ownership lookup failed"); return (RoomResponse::Failed, tx); } }; @@ -614,7 +631,7 @@ async fn handle_request( match already_owner { None => { // Targeted user is not a member of the room - // TODO - Logging + tracing::debug!(%room_id, target = %new_owner_for_log, "add_room_owner: target is not a member"); (RoomResponse::Failed, tx) } Some(true) => { @@ -623,7 +640,7 @@ async fn handle_request( } Some(false) => { // Member but not yet an owner - if let Err(_e) = sqlx::query( + if let Err(e) = sqlx::query( "UPDATE memberships SET is_owner = true WHERE room_id = $1 AND user_id = $2", ) @@ -632,14 +649,17 @@ async fn handle_request( .execute(&mut *db) .await { - // TODO - Logging + tracing::error!(error = %e, %room_id, "add_room_owner: ownership grant failed"); return (RoomResponse::Failed, tx); } match db.commit().await { - Ok(_) => (RoomResponse::Success, tx), - Err(_e) => { - // TODO - Logging + Ok(_) => { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_name, target = %new_owner_for_log, %room_id, "room owner added"); + (RoomResponse::Success, tx) + } + Err(e) => { + tracing::error!(error = %e, %room_id, "add_room_owner: commit failed"); (RoomResponse::Failed, tx) } } @@ -655,48 +675,63 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "set_room_name: begin transaction failed"); return (RoomResponse::Failed, tx); } }; + // Captured for the audit log; new_name is consumed by the update. + let new_name_for_log = new_name.clone(); + // Authorize: caller must own the room (or be an admin). "No such // room" and "not authorized" both return Failed so existence isn't // leaked. - let (room_id, authorized) = - match gate_room(&mut db, source_user_id, ¤t_name).await { - Ok(Some(gate)) => gate, - Ok(None) | Err(_) => { - // TODO - Logging - return (RoomResponse::Failed, tx); - } - }; + let (room_id, authorized) = match gate_room(&mut db, source_user_id, ¤t_name) + .await + { + Ok(Some(gate)) => gate, + // No such room: existence-hidden, not a fault. + Ok(None) => { + tracing::debug!(room = %current_name, "set_room_name: no such room"); + return (RoomResponse::Failed, tx); + } + Err(e) => { + tracing::error!(error = %e, "set_room_name: room authorization lookup failed"); + return (RoomResponse::Failed, tx); + } + }; if !authorized { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, room = %current_name, "set_room_name denied: caller is not an owner or admin"); return (RoomResponse::Failed, tx); } // Update the room's name to the new name - let result = - match sqlx::query("UPDATE rooms SET room_name = trim_ws($1) WHERE room_id = $2") - .bind(new_name) - .bind(room_id) - .execute(&mut *db) - .await - { - Ok(res) => res, - Err(_e) => { - // TODO - Logging - return (RoomResponse::Failed, tx); - } - }; + let result = match sqlx::query( + "UPDATE rooms SET room_name = trim_ws($1) WHERE room_id = $2", + ) + .bind(new_name) + .bind(room_id) + .execute(&mut *db) + .await + { + Ok(res) => res, + Err(e) => { + // Commonly a unique-violation (new name already taken). + tracing::warn!(error = %e, %room_id, "set_room_name: rename failed (e.g. duplicate name)"); + return (RoomResponse::Failed, tx); + } + }; match result.rows_affected() { 1 => match db.commit().await { - Ok(_) => (RoomResponse::Success, tx), - Err(_e) => { - // TODO - Logging + Ok(_) => { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, room = %current_name, new_name = %new_name_for_log, %room_id, "room renamed"); + (RoomResponse::Success, tx) + } + Err(e) => { + tracing::error!(error = %e, %room_id, "set_room_name: commit failed"); (RoomResponse::Failed, tx) } }, @@ -712,8 +747,8 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_room: acquire connection failed"); return (RoomResponse::Failed, tx); } }; @@ -727,8 +762,8 @@ async fn handle_request( .await { Ok(maybe_room) => maybe_room, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_room: room lookup failed"); return (RoomResponse::Failed, tx); } }; @@ -752,8 +787,8 @@ async fn handle_request( .await { Ok(visible) => visible, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, room_id = %room.room_id, "get_room: visibility check failed"); return (RoomResponse::Failed, tx); } }; @@ -780,8 +815,8 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_room_membership: acquire connection failed"); return (RoomResponse::Failed, tx); } }; @@ -797,8 +832,8 @@ async fn handle_request( .await { Ok(maybe_room) => maybe_room, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_room_membership: room lookup failed"); return (RoomResponse::Failed, tx); } }; @@ -822,8 +857,8 @@ async fn handle_request( .await { Ok(visible) => visible, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, room_id = %room.room_id, "get_room_membership: visibility check failed"); return (RoomResponse::Failed, tx); } }; @@ -845,8 +880,8 @@ async fn handle_request( .await { Ok(users) => users, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, room_id = %room.room_id, "get_room_membership: member list query failed"); return (RoomResponse::Failed, tx); } }; @@ -861,8 +896,8 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "join_room: acquire connection failed"); return (RoomResponse::Failed, tx); } }; @@ -877,8 +912,8 @@ async fn handle_request( .await { Ok(maybe_room) => maybe_room, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "join_room: room lookup failed"); return (RoomResponse::Failed, tx); } }; @@ -905,8 +940,8 @@ async fn handle_request( .await { Ok(res) => res, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, room_id = %room.room_id, "join_room: membership insert failed"); return (RoomResponse::Failed, tx); } }; @@ -935,8 +970,8 @@ async fn handle_request( .await { Ok(res) => res, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, room_id = %room.room_id, "join_room: join request insert failed"); return (RoomResponse::Failed, tx); } }; @@ -960,8 +995,8 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "leave_room: acquire connection failed"); return (RoomResponse::Failed, tx); } }; @@ -981,8 +1016,8 @@ async fn handle_request( .await { Ok(res) => res, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "leave_room: membership delete failed"); return (RoomResponse::Failed, tx); } }; @@ -997,8 +1032,8 @@ async fn handle_request( RoomRequest::GetMyJoinRequests { source_user_id, tx } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_my_join_requests: acquire connection failed"); return (RoomResponse::Failed, tx); } }; @@ -1016,8 +1051,8 @@ async fn handle_request( .await { Ok(rooms) => rooms, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_my_join_requests: query failed"); return (RoomResponse::Failed, tx); } }; @@ -1028,8 +1063,8 @@ async fn handle_request( RoomRequest::GetIncomingJoinRequests { source_user_id, tx } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_incoming_join_requests: acquire connection failed"); return (RoomResponse::Failed, tx); } }; @@ -1051,8 +1086,8 @@ async fn handle_request( .await { Ok(requests) => requests, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_incoming_join_requests: query failed"); return (RoomResponse::Failed, tx); } }; @@ -1068,24 +1103,33 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "approve_join_request: begin transaction failed"); return (RoomResponse::Failed, tx); } }; + // Captured for audit/denial logs; requester_username is consumed below. + let requester_for_log = requester_username.clone(); + // Authorize: caller must own the room (or be an admin). "No such // room" and "not authorized" both return Failed so existence isn't // leaked. let (room_id, authorized) = match gate_room(&mut db, source_user_id, &room_name).await { Ok(Some(gate)) => gate, - Ok(None) | Err(_) => { - // TODO - Logging + // No such room: existence-hidden, not a fault. + Ok(None) => { + tracing::debug!(room = %room_name, "approve_join_request: no such room"); + return (RoomResponse::Failed, tx); + } + Err(e) => { + tracing::error!(error = %e, "approve_join_request: room authorization lookup failed"); return (RoomResponse::Failed, tx); } }; if !authorized { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_name, "approve_join_request denied: caller is not an owner or admin"); return (RoomResponse::Failed, tx); } @@ -1104,8 +1148,8 @@ async fn handle_request( .await { Ok(maybe_id) => maybe_id, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "approve_join_request: request delete failed"); return (RoomResponse::Failed, tx); } }; @@ -1117,7 +1161,7 @@ async fn handle_request( // Admit the requester. ON CONFLICT DO NOTHING in case they became a // member by some other path in the meantime. // Start caught up: watermark = newest message at admission time. - if let Err(_e) = sqlx::query( + if let Err(e) = sqlx::query( "INSERT INTO memberships (room_id, user_id, last_read_message_id) VALUES ($1, $2, (SELECT message_id FROM messages @@ -1129,7 +1173,7 @@ async fn handle_request( .execute(&mut *db) .await { - // TODO - Logging + tracing::error!(error = %e, %room_id, %approved_user_id, "approve_join_request: membership insert failed"); return (RoomResponse::Failed, tx); } @@ -1142,14 +1186,15 @@ async fn handle_request( .await { Ok(name) => name, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "approve_join_request: canonical name lookup failed"); return (RoomResponse::Failed, tx); } }; match db.commit().await { Ok(_) => { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_name, target = %requester_for_log, %approved_user_id, %room_id, "join request approved"); // Cross-session: the admitted user isn't the caller. If any of // their sessions are online, subscribe those sessions to the // room's live stream now, so they get messages without @@ -1157,8 +1202,8 @@ async fn handle_request( hub.subscribe_user_to_room(approved_user_id, room_id, room_name); (RoomResponse::Success, tx) } - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "approve_join_request: commit failed"); (RoomResponse::Failed, tx) } } @@ -1172,12 +1217,16 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "reject_join_request: begin transaction failed"); return (RoomResponse::Failed, tx); } }; + // Captured for audit/denial logs; both are consumed by the queries below. + let room_for_log = room_name.clone(); + let requester_for_log = requester_username.clone(); + // Authorize: caller must own the room (or be an admin). let gate = match sqlx::query_as::<_, (Uuid, bool)>( "SELECT @@ -1195,8 +1244,8 @@ async fn handle_request( .await { Ok(gate) => gate, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "reject_join_request: room authorization lookup failed"); return (RoomResponse::Failed, tx); } }; @@ -1204,9 +1253,11 @@ async fn handle_request( // Treat "no such room" and "not authorized" identically, so a // non-owner can't probe a private room's existence here. let Some((room_id, authorized)) = gate else { + tracing::debug!(room = %room_for_log, "reject_join_request: no such room"); return (RoomResponse::Failed, tx); }; if !authorized { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_for_log, "reject_join_request denied: caller is not an owner or admin"); return (RoomResponse::Failed, tx); } @@ -1223,8 +1274,8 @@ async fn handle_request( .await { Ok(res) => res, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "reject_join_request: request delete failed"); return (RoomResponse::Failed, tx); } }; @@ -1232,9 +1283,12 @@ async fn handle_request( match result.rows_affected() { 0 => (RoomResponse::NoChange, tx), _ => match db.commit().await { - Ok(_) => (RoomResponse::Success, tx), - Err(_e) => { - // TODO - Logging + Ok(_) => { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_for_log, target = %requester_for_log, %room_id, "join request rejected"); + (RoomResponse::Success, tx) + } + Err(e) => { + tracing::error!(error = %e, %room_id, "reject_join_request: commit failed"); (RoomResponse::Failed, tx) } }, @@ -1249,23 +1303,32 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "invite_to_room: begin transaction failed"); return (RoomResponse::Failed, tx); } }; + // Captured for audit/denial logs; invitee_username is consumed below. + let invitee_for_log = invitee_username.clone(); + // Authorize: only an owner (or admin) may invite. Missing room and // not-authorized both return Failed so existence isn't leaked. let (room_id, authorized) = match gate_room(&mut db, source_user_id, &room_name).await { Ok(Some(gate)) => gate, - Ok(None) | Err(_) => { - // TODO - Logging + // No such room: existence-hidden, not a fault. + Ok(None) => { + tracing::debug!(room = %room_name, "invite_to_room: no such room"); + return (RoomResponse::Failed, tx); + } + Err(e) => { + tracing::error!(error = %e, "invite_to_room: room authorization lookup failed"); return (RoomResponse::Failed, tx); } }; if !authorized { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_name, "invite_to_room denied: caller is not an owner or admin"); return (RoomResponse::Failed, tx); } @@ -1278,13 +1341,14 @@ async fn handle_request( .await { Ok(maybe_id) => maybe_id, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "invite_to_room: invitee lookup failed"); return (RoomResponse::Failed, tx); } }; let Some(invitee_id) = invitee_id else { + tracing::debug!(target = %invitee_for_log, "invite_to_room: invitee not found"); return (RoomResponse::Failed, tx); }; @@ -1306,17 +1370,20 @@ async fn handle_request( .await { Ok(res) => res, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, %invitee_id, "invite_to_room: invite insert failed"); return (RoomResponse::Failed, tx); } }; match result.rows_affected() { 1 => match db.commit().await { - Ok(_) => (RoomResponse::Success, tx), - Err(_e) => { - // TODO - Logging + Ok(_) => { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, room = %room_name, target = %invitee_for_log, %invitee_id, %room_id, "user invited to room"); + (RoomResponse::Success, tx) + } + Err(e) => { + tracing::error!(error = %e, %room_id, "invite_to_room: commit failed"); (RoomResponse::Failed, tx) } }, @@ -1328,8 +1395,8 @@ async fn handle_request( RoomRequest::GetMyInvites { source_user_id, tx } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_my_invites: acquire connection failed"); return (RoomResponse::Failed, tx); } }; @@ -1347,8 +1414,8 @@ async fn handle_request( .await { Ok(rooms) => rooms, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_my_invites: query failed"); return (RoomResponse::Failed, tx); } }; @@ -1363,8 +1430,8 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "accept_invite: begin transaction failed"); return (RoomResponse::Failed, tx); } }; @@ -1384,8 +1451,8 @@ async fn handle_request( .await { Ok(maybe_id) => maybe_id, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "accept_invite: invite consume failed"); return (RoomResponse::Failed, tx); } }; @@ -1397,7 +1464,7 @@ async fn handle_request( // Join the room. ON CONFLICT DO NOTHING in case membership already // exists by some other path. // Start caught up: watermark = newest message at accept time. - if let Err(_e) = sqlx::query( + if let Err(e) = sqlx::query( "INSERT INTO memberships (room_id, user_id, last_read_message_id) VALUES ($1, $2, (SELECT message_id FROM messages @@ -1409,14 +1476,14 @@ async fn handle_request( .execute(&mut *db) .await { - // TODO - Logging + tracing::error!(error = %e, %room_id, "accept_invite: membership insert failed"); return (RoomResponse::Failed, tx); } match db.commit().await { Ok(_) => (RoomResponse::Success, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %room_id, "accept_invite: commit failed"); (RoomResponse::Failed, tx) } } @@ -1429,8 +1496,8 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "decline_invite: acquire connection failed"); return (RoomResponse::Failed, tx); } }; @@ -1448,8 +1515,8 @@ async fn handle_request( .await { Ok(res) => res, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "decline_invite: invite delete failed"); return (RoomResponse::Failed, tx); } }; diff --git a/src/server.rs b/src/server.rs index 32e20d7..b6c7cfe 100644 --- a/src/server.rs +++ b/src/server.rs @@ -14,6 +14,7 @@ use tokio_stream::StreamMap; use tokio_stream::wrappers::BroadcastStream; use tokio_stream::wrappers::errors::BroadcastStreamRecvError; use tokio_util::sync::CancellationToken; +use tracing::Instrument; use uuid::Uuid; use crate::attachment::{self, AttachmentHandle, Chunk}; @@ -43,8 +44,7 @@ struct Handles { } async fn send_close(sender: &mut SplitSink, who: SocketAddr) { - // TODO tracing - println!("Sending close to {who}"); + tracing::debug!(who = %who, "sending close frame"); if let Err(e) = sender .send(Message::Close(Some(CloseFrame { code: axum::extract::ws::close_code::NORMAL, @@ -52,7 +52,8 @@ async fn send_close(sender: &mut SplitSink, who: SocketAddr) }))) .await { - println!("Could not send Close due to {e}, probably it is ok?"); + // The peer is often already gone by the time we try to close; not an error. + tracing::debug!(who = %who, error = %e, "could not send close frame (peer likely gone)"); } } @@ -192,8 +193,14 @@ async fn spawn_receiver_task( download_semaphore: Arc, hub: Hub, sub_tx: mpsc::Sender, + who: SocketAddr, ) -> tokio::task::JoinHandle<()> { - tokio::spawn(async move { + // One span per connection. `user_id` starts empty and is recorded once the + // prelude authenticates, so every event this task emits (here and down through + // process_message) is attributable to the connection and, post-auth, the user. + let span = tracing::info_span!("conn", %who, user_id = tracing::field::Empty); + tokio::spawn( + async move { // PRELUDE - PREAUTH'd let (user_id, server_event) = prelude( &mut receiver, @@ -205,6 +212,8 @@ async fn spawn_receiver_task( match server_event { ServerEvent::AuthOk => { + tracing::Span::current().record("user_id", tracing::field::display(user_id)); + tracing::debug!("session authenticated"); let _ = user_tx.send(ServerEvent::AuthOk).await; } // Anything but AuthOk results in shutdown @@ -355,7 +364,11 @@ async fn spawn_receiver_task( } } } - }) + + tracing::debug!("session closed"); + } + .instrument(span), + ) } pub(crate) async fn handle_socket(socket: WebSocket, state: AppState, who: SocketAddr) { @@ -397,6 +410,7 @@ pub(crate) async fn handle_socket(socket: WebSocket, state: AppState, who: Socke download_semaphore, hub, sub_tx, + who, ) .await; @@ -507,20 +521,22 @@ async fn process_message( // the socket closes shortly after. ClientCommand::RestartServer => { if handles.user_handle.is_admin(user_id).await { + tracing::info!(target: crate::logging::AUDIT, actor = %user_id, "server restart requested"); let _ = user_tx.send(ServerEvent::Success).await; handles.control.restart().await; } else { - // TODO - Logging + tracing::warn!(target: crate::logging::AUDIT, actor = %user_id, "server restart denied: caller is not an admin"); let _ = user_tx.send(ServerEvent::Failed).await; } } ClientCommand::ShutdownServer => { if handles.user_handle.is_admin(user_id).await { + tracing::info!(target: crate::logging::AUDIT, actor = %user_id, "server shutdown requested"); let _ = user_tx.send(ServerEvent::Success).await; handles.control.shutdown().await; } else { - // TODO - Logging + tracing::warn!(target: crate::logging::AUDIT, actor = %user_id, "server shutdown denied: caller is not an admin"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -560,9 +576,10 @@ async fn process_message( .await; } // Failed (or the reaction-only Success, which SendMessage never - // returns) collapses to a generic failure for the client. + // returns) collapses to a generic failure for the client. The + // detailed cause is already logged in the message actor. _ => { - // TODO - Logging + tracing::debug!("send_message: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -605,7 +622,7 @@ async fn process_message( let _ = user_tx.send(ServerEvent::Success).await; } _ => { - // TODO - Logging + tracing::debug!("add_reaction: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -621,7 +638,7 @@ async fn process_message( let _ = user_tx.send(ServerEvent::Success).await; } _ => { - // TODO - Logging + tracing::debug!("remove_reaction: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -651,7 +668,7 @@ async fn process_message( .await; } _ => { - // TODO - Logging + tracing::debug!("get_messages: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -670,7 +687,7 @@ async fn process_message( let _ = user_tx.send(ServerEvent::Success).await; } _ => { - // TODO - Logging + tracing::debug!("mark_read: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -682,7 +699,7 @@ async fn process_message( let _ = user_tx.send(ServerEvent::UnreadSummary { rooms }).await; } _ => { - // TODO - Logging + tracing::debug!("get_unread_summary: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -704,7 +721,7 @@ async fn process_message( // rather than trusting a value cached at connect time. let allowed = open_signups || handles.user_handle.is_admin(user_id).await; if !allowed { - // TODO - Logging + tracing::warn!(target: crate::logging::AUDIT, actor = %user_id, "user creation denied: signups closed and caller is not an admin"); let _ = user_tx.send(ServerEvent::Failed).await; } else { match new_user( @@ -721,7 +738,7 @@ async fn process_message( let _ = user_tx.send(ServerEvent::UserCreated).await; } _ => { - // TODO - Logging + tracing::debug!("new_user: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -775,7 +792,7 @@ async fn process_message( let _ = user_tx.send(ServerEvent::NoUserExists).await; } _ => { - // TODO - Logging + tracing::debug!("get_user_by_username: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -800,7 +817,7 @@ async fn process_message( } } _ => { - // TODO - Logging + tracing::debug!("delete_user: request failed"); let _ = user_tx.send(ServerEvent::Failed).await; } } @@ -1158,7 +1175,9 @@ async fn process_message( } }, Err(e) => { - println!("ERR: {:?}", e); + // Client-caused: malformed/oversized/incomplete input. Not a server + // fault, so debug, not warn. The client still gets a generic reason. + tracing::debug!(error = %e, "rejected undecodable client command"); if e.is_data() { let _ = user_tx .send(ServerEvent::Error { @@ -1183,7 +1202,6 @@ async fn process_message( error: "unknown error".to_owned(), }) .await; - println!("unknown error: {}", e); }; } } @@ -1209,7 +1227,8 @@ async fn process_binary( // Need a full header (20-Bytes) plus at least one payload byte. // Generic error; specifics stay server-side. if data.len() <= HEADER_LEN { - // TODO - Logging + // Client-caused: a frame too short to hold the header plus a payload byte. + tracing::debug!(len = data.len(), "process_binary: undersized chunk frame"); let _ = user_tx .send(ServerEvent::Error { error: "invalid chunk".to_owned(), @@ -1283,8 +1302,8 @@ async fn process_binary( .await; return; } - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %attachment_id, "process_binary: attachment metadata lookup failed"); let _ = user_tx.send(ServerEvent::Failed).await; return; } @@ -1355,15 +1374,26 @@ async fn prelude( Some(Ok(Message::Text(t))) => { match serde_json::from_str::(&t) { Ok(ClientCommand::Auth{username, password}) => { - match auth_handle.authenticate(username, password).await { - AuthResult::Ok { user_id } => (user_id, ServerEvent::AuthOk), - _ => (Uuid::nil(), ServerEvent::NoAuth), + // Clone the username for audit logging; authenticate consumes it. + match auth_handle.authenticate(username.clone(), password).await { + AuthResult::Ok { user_id } => { + tracing::info!(target: crate::logging::AUDIT, %user_id, username = %username, "login succeeded"); + (user_id, ServerEvent::AuthOk) + } + AuthResult::Failed => { + tracing::warn!(target: crate::logging::AUDIT, username = %username, "login failed"); + (Uuid::nil(), ServerEvent::NoAuth) + } + // Server-side fault, not a credential rejection: already + // logged at error! in the auth actor, so don't audit it + // as a failed login. + AuthResult::Error => (Uuid::nil(), ServerEvent::NoAuth), } }, // Unauthenticated user creation is only allowed when open // signups are enabled in the config; otherwise reject it. - Ok(ClientCommand::NewUser { .. }) if !open_signups => { - // TODO - Logging + Ok(ClientCommand::NewUser { username, .. }) if !open_signups => { + tracing::warn!(target: crate::logging::AUDIT, username = %username, "signup rejected: open signups disabled"); (Uuid::nil(), ServerEvent::NoAuth) } Ok(ClientCommand::NewUser { @@ -1373,27 +1403,31 @@ async fn prelude( last_name, alias }) => { - match new_user(user_handle, username, password, first_name, last_name, alias).await { - UserResponse::UserCreated { user_id } => { (user_id, ServerEvent::UserCreated ) } + // Clone the username for audit logging; new_user consumes it. + match new_user(user_handle, username.clone(), password, first_name, last_name, alias).await { + // Account-creation audit happens in the user actor (the + // single point both signup and authenticated paths hit). + UserResponse::UserCreated { user_id } => (user_id, ServerEvent::UserCreated), UserResponse::Failed => { - // TODO - Logging + // Detailed cause is logged in the user actor; this is just the prelude outcome. + tracing::debug!(username = %username, "open-signup user creation failed"); (Uuid::nil(), ServerEvent::Failed) } _ => { - // TODO - Logging + tracing::debug!(username = %username, "open-signup user creation returned unexpected response"); (Uuid::nil(), ServerEvent::Failed) } } }, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::debug!(error = %e, "undecodable command during prelude"); (Uuid::nil(), ServerEvent::NoAuth) } _ => (Uuid::nil(), ServerEvent::NoAuth) } } - Some(Err(_e)) => { - // TODO - Logging + Some(Err(e)) => { + tracing::debug!(error = %e, "websocket error during prelude"); (Uuid::nil(), ServerEvent::NoAuth) } _ => (Uuid::nil(), ServerEvent::NoAuth) diff --git a/src/user.rs b/src/user.rs index c2608ee..3760fd8 100644 --- a/src/user.rs +++ b/src/user.rs @@ -186,7 +186,7 @@ impl UserHandle { .await .is_err() { - // TODO - Logging + tracing::error!("user actor unavailable: get_user_by_username request dropped"); return UserResponse::Failed; } @@ -322,32 +322,41 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "new_user: begin transaction failed"); return (UserResponse::Failed, tx); } }; let hash = match generate_hash(credential) { Ok(hash) => hash, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "new_user: password hashing failed"); return (UserResponse::Failed, tx); } }; + // Captured for the audit log below; create_user consumes `user`. + let username = user.username.clone(); let user_id = match create_user(&mut db, user, &hash).await { Ok(user_id) => user_id, - Err(_e) => { - // TODO - Logging + Err(e) => { + // Commonly a unique-violation (username already taken), which is + // a client error, not a server fault -- warn rather than error. + tracing::warn!(error = %e, "new_user: user insert failed (e.g. duplicate username)"); return (UserResponse::Failed, tx); } }; match db.commit().await { - Ok(_) => (UserResponse::UserCreated { user_id }, tx), - Err(_e) => { - // TODO - Logging + Ok(_) => { + // Single audit point for account creation -- covers both the open + // signup and authenticated-creation paths that reach this actor. + tracing::info!(target: crate::logging::AUDIT, %user_id, username = %username, "account created"); + (UserResponse::UserCreated { user_id }, tx) + } + Err(e) => { + tracing::error!(error = %e, %user_id, "new_user: commit failed"); (UserResponse::Failed, tx) } } @@ -363,8 +372,8 @@ async fn handle_request( Some(user) => user, None => return (UserResponse::NoUserExists, tx), }, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %user_id, "get_user_info: query failed"); return (UserResponse::Failed, tx); } }; @@ -374,16 +383,16 @@ async fn handle_request( UserRequest::IsAdminRequest { user_id, tx } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "is_admin: acquire connection failed"); return (UserResponse::Failed, tx); } }; match is_admin(&mut db, user_id).await { Ok(value) => (UserResponse::IsAdmin { is_admin: value }, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %user_id, "is_admin: query failed"); (UserResponse::Failed, tx) } } @@ -400,8 +409,8 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "edit_user: acquire connection failed"); return (UserResponse::Failed, tx); } }; @@ -420,8 +429,8 @@ async fn handle_request( .await { Ok(res) => (res, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, actor = %source_user_id, target = %target_username, "edit_user: query failed"); (UserResponse::Failed, tx) } } @@ -430,16 +439,16 @@ async fn handle_request( UserRequest::GetUserByUsername { username, tx } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_user_by_username: acquire connection failed"); return (UserResponse::Failed, tx); } }; match get_user_by_username(&mut db, &username).await { Ok(res) => (res, tx), - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "get_user_by_username: query failed"); (UserResponse::Failed, tx) } } @@ -452,8 +461,8 @@ async fn handle_request( } => { let mut db: sqlx::Transaction<'_, sqlx::Postgres> = match pool.begin().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "delete_user: begin transaction failed"); return (UserResponse::Failed, tx); } }; @@ -471,23 +480,23 @@ async fn handle_request( // Check if source user is admin let is_admin: bool = match is_admin(&mut db, source_user_id).await { Ok(maybe_admin) => maybe_admin, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "delete_user: admin check query failed"); return (UserResponse::Failed, tx); } }; // If the user source is not an admin or targeting itself, fail if !is_admin && target_user_id != source_user_id { - // TODO - Logging + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "delete denied: caller is not an admin and not deleting self"); return (UserResponse::Failed, tx); } // Check if the target user is Default Admin let maybe_admin: Option = match get_admin(&mut db, target_user_id).await { Ok(maybe_admin) => maybe_admin, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "delete_user: target admin lookup failed"); return (UserResponse::Failed, tx); } }; @@ -497,20 +506,22 @@ async fn handle_request( }; if is_default { - return (UserResponse::Failed, tx); // Don't allow default admin to be deleted, even by admin or itself + // Don't allow the default admin to be deleted, even by an admin or itself. + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "delete denied: target is the default admin"); + return (UserResponse::Failed, tx); } // Put a DB lock on the target user's ID - if let Err(_e) = sqlx::query("SELECT user_id FROM users WHERE user_id = $1 FOR UPDATE") + if let Err(e) = sqlx::query("SELECT user_id FROM users WHERE user_id = $1 FOR UPDATE") .bind(target_user_id) .execute(&mut *db) .await { - // TODO - Logging + tracing::error!(error = %e, %target_user_id, "delete_user: row lock failed"); return (UserResponse::Failed, tx); } - if let Err(_e) = sqlx::query( + if let Err(e) = sqlx::query( "UPDATE messages set sender_username_snapshot = u.username FROM users u WHERE messages.sender_id = $1 AND u.user_id = $1", @@ -519,7 +530,7 @@ async fn handle_request( .execute(&mut *db) .await { - // TODO - Logging + tracing::error!(error = %e, %target_user_id, "delete_user: username snapshot update failed"); return (UserResponse::Failed, tx); }; @@ -536,8 +547,8 @@ async fn handle_request( .await { Ok(res) => res.rows_affected() == 1, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %target_user_id, "delete_user: delete failed"); false } }; @@ -545,12 +556,13 @@ async fn handle_request( if !success { return (UserResponse::Failed, tx); } - if let Err(_e) = db.commit().await { - // TODO - Logging + if let Err(e) = db.commit().await { + tracing::error!(error = %e, %target_user_id, "delete_user: commit failed"); return (UserResponse::Failed, tx); } let is_self = source_user_id == target_user_id; + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, %target_user_id, is_self, "user deleted"); (UserResponse::UserDeleted { is_self }, tx) } @@ -562,8 +574,8 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "update_password: acquire connection failed"); return (UserResponse::Failed, tx); } }; @@ -574,13 +586,13 @@ async fn handle_request( let source_is_default = match get_admin(&mut db, source_user_id).await { Ok(Some(admin)) => admin.is_default, Ok(None) => false, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "update_password: admin lookup failed"); return (UserResponse::Failed, tx); } }; if source_is_default { - // TODO - Logging + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, "update_password denied: default admin credentials are config-managed"); return (UserResponse::Failed, tx); } @@ -591,8 +603,8 @@ async fn handle_request( password: new_password, }) { Ok(hash) => hash, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "update_password: password hashing failed"); return (UserResponse::Failed, tx); } }; @@ -609,21 +621,23 @@ async fn handle_request( .await { Ok(res) => res, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %source_user_id, "update_password: credential update failed"); return (UserResponse::Failed, tx); } } .rows_affected(); if row == 1 { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, "password changed"); (UserResponse::Success, tx) } else { - // TODO - Logging + // No credential row matched -- shouldn't happen for a verified user. + tracing::warn!(%source_user_id, "update_password: no credential row updated"); (UserResponse::Failed, tx) } } else { - // TODO - Logging + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, "update_password denied: current password incorrect"); (UserResponse::Failed, tx) } } @@ -636,8 +650,8 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "reset_password: acquire connection failed"); return (UserResponse::Failed, tx); } }; @@ -648,14 +662,15 @@ async fn handle_request( Some(admin) => (true, admin.is_default), None => (false, false), }, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "reset_password: caller admin lookup failed"); return (UserResponse::Failed, tx); } }; // Non-admins cannot use ResetPassword if !source_is_admin { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "reset_password denied: caller is not an admin"); return (UserResponse::Failed, tx); } @@ -671,6 +686,7 @@ async fn handle_request( // Admins can change other user passwords, but not their own if target_user_id == source_user_id { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, "reset_password denied: admin cannot reset own password"); return (UserResponse::Failed, tx); } @@ -680,14 +696,15 @@ async fn handle_request( Some(admin) => (true, admin.is_default), None => (false, false), }, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "reset_password: target admin lookup failed"); return (UserResponse::Failed, tx); } }; // Only the Default Admin can reset the password of admins if target_is_admin && !source_is_default || target_is_default { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "reset_password denied: only the default admin may reset an admin's password"); return (UserResponse::Failed, tx); } @@ -695,8 +712,8 @@ async fn handle_request( password: new_password, }) { Ok(hash) => hash, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "reset_password: password hashing failed"); return (UserResponse::Failed, tx); } }; @@ -713,17 +730,18 @@ async fn handle_request( .await { Ok(res) => res, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %target_user_id, "reset_password: credential update failed"); return (UserResponse::Failed, tx); } } .rows_affected(); if row == 1 { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, %target_user_id, "password reset"); (UserResponse::Success, tx) } else { - // TODO - Logging + tracing::warn!(%target_user_id, "reset_password: no credential row updated"); (UserResponse::Failed, tx) } } @@ -735,21 +753,22 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "promote: acquire connection failed"); return (UserResponse::Failed, tx); } }; let source_is_admin = match is_admin(&mut db, source_user_id).await { Ok(is_admin) => is_admin, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "promote: caller admin check failed"); return (UserResponse::Failed, tx); } }; if !source_is_admin { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "promote denied: caller is not an admin"); return (UserResponse::Failed, tx); } @@ -774,14 +793,17 @@ async fn handle_request( .await { Ok(res) => res, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %target_user_id, "promote: admin insert failed"); return (UserResponse::Failed, tx); } }; match result.rows_affected() { - 1 => (UserResponse::Success, tx), + 1 => { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, %target_user_id, "user promoted to admin"); + (UserResponse::Success, tx) + } 0 => (UserResponse::NoChange, tx), _ => unreachable!(), } @@ -794,21 +816,22 @@ async fn handle_request( } => { let mut db = match pool.acquire().await { Ok(db) => db, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "demote: acquire connection failed"); return (UserResponse::Failed, tx); } }; let source_is_admin = match is_admin(&mut db, source_user_id).await { Ok(is_admin) => is_admin, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "demote: caller admin check failed"); return (UserResponse::Failed, tx); } }; if !source_is_admin { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "demote denied: caller is not an admin"); return (UserResponse::Failed, tx); } @@ -828,8 +851,8 @@ async fn handle_request( Some(admin) => (true, admin.is_default), None => (false, false), }, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "demote: target admin lookup failed"); return (UserResponse::Failed, tx); } }; @@ -840,6 +863,7 @@ async fn handle_request( } // Reject attempts to demote the default admin if target_is_default { + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "demote denied: target is the default admin"); return (UserResponse::Failed, tx); } @@ -849,13 +873,14 @@ async fn handle_request( .await { Ok(res) => res.rows_affected() == 1, - Err(_e) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, %target_user_id, "demote: admin delete failed"); false } }; if success { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, %target_user_id, "user demoted from admin"); (UserResponse::Success, tx) } else { (UserResponse::Failed, tx) @@ -907,21 +932,21 @@ async fn edit_user( // If the target user does not exist, fail let Some(target_user_id) = target_user_id else { - // TODO - Logging + tracing::debug!(target = %target_username, "edit_user: target user not found"); return Ok(UserResponse::Failed); }; // If the user is not modifying itself or the user is not an admin, fail if target_user_id != source_user_id && !is_source_admin { - // TODO - Logging + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "edit denied: caller is not an admin and not editing self"); return Ok(UserResponse::Failed); } // Check if the target user is Default Admin let maybe_admin: Option = match get_admin(db, target_user_id).await { Ok(maybe_admin) => maybe_admin, - Err(_) => { - // TODO - Logging + Err(e) => { + tracing::error!(error = %e, "edit_user: target admin lookup failed"); return Ok(UserResponse::Failed); } }; @@ -931,7 +956,9 @@ async fn edit_user( }; if is_default { - return Ok(UserResponse::Failed); // Don't allow edits to the default admin + // Don't allow edits to the default admin. + tracing::warn!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, "edit denied: target is the default admin"); + return Ok(UserResponse::Failed); } let result = sqlx::query( @@ -952,10 +979,11 @@ async fn edit_user( .rows_affected(); if result == 1 { + tracing::info!(target: crate::logging::AUDIT, actor = %source_user_id, target = %target_username, %target_user_id, "user profile edited"); Ok(UserResponse::Success) } else { - // Zero rows were changed - // TODO - Logging + // Zero rows changed -- target vanished between the lookup and the update. + tracing::debug!(%target_user_id, "edit_user: no rows updated"); Ok(UserResponse::Failed) } } @@ -1027,7 +1055,7 @@ async fn translate_username_to_id( match user_response { UserResponse::UserInfo { user_info } => Ok(Some(user_info.user_id)), _ => { - // TODO - Logging + tracing::debug!(username = %username, "translate_username_to_id: no user for username"); Ok(None) } }