feat: logging

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"] }

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,16 +162,17 @@ 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(),
                         })
                         .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;
                 }

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,19 +79,19 @@ 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;
         }
     };
 
     let (user_id, verified) = match row {
         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()

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

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

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;

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");
+            }
+        },
+    }
+}