diff --git a/Client/tauri-client/src-tauri/Cargo.lock b/Client/tauri-client/src-tauri/Cargo.lock index f30bd028..c6882c97 100644 --- a/Client/tauri-client/src-tauri/Cargo.lock +++ b/Client/tauri-client/src-tauri/Cargo.lock @@ -32,6 +32,23 @@ dependencies = [ "alloc-no-stdlib", ] +[[package]] +name = "android_log-sys" +version = "0.3.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "84521a3cf562bc62942e294181d9eef17eb38ceb8c68677bc49f144e4c3d4f8d" + +[[package]] +name = "android_logger" +version = "0.15.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "dbb4e440d04be07da1f1bf44fb4495ebd58669372fe0cffa6e48595ac5bd88a3" +dependencies = [ + "android_log-sys", + "env_filter", + "log", +] + [[package]] name = "android_system_properties" version = "0.1.5" @@ -1256,27 +1273,14 @@ dependencies = [ [[package]] name = "env_filter" -version = "2.0.0" +version = "0.1.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "900d271a03799a1ee8d1ca9b19893b48ca674a9284fefcfb85f05e74ed314217" +checksum = "1bf3c259d255ca70051b30e2e95b5446cdb8949ac4cd22c0d7fd634d89f568e2" dependencies = [ "log", "regex", ] -[[package]] -name = "env_logger" -version = "0.11.11" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "de671bd27a75a797dc9ae289ba1e77276e75e2026408aab65185384e2d5cd3f6" -dependencies = [ - "anstream", - "anstyle", - "env_filter", - "jiff", - "log", -] - [[package]] name = "equivalent" version = "1.0.2" @@ -1340,6 +1344,15 @@ dependencies = [ "simd-adler32", ] +[[package]] +name = "fern" +version = "0.7.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4316185f709b23713e41e3195f90edef7fb00c3ed4adc79769cf09cc762a3b29" +dependencies = [ + "log", +] + [[package]] name = "field-offset" version = "0.3.6" @@ -2350,30 +2363,6 @@ dependencies = [ "system-deps", ] -[[package]] -name = "jiff" -version = "0.2.23" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1a3546dc96b6d42c5f24902af9e2538e82e39ad350b0c766eb3fbf2d8f3d8359" -dependencies = [ - "jiff-static", - "log", - "portable-atomic", - "portable-atomic-util", - "serde_core", -] - -[[package]] -name = "jiff-static" -version = "0.2.23" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2a8c8b344124222efd714b73bb41f8b5120b27a7cc1c75593a6ff768d9d05aa4" -dependencies = [ - "proc-macro2", - "quote", - "syn 2.0.117", -] - [[package]] name = "jni" version = "0.21.1" @@ -2802,6 +2791,15 @@ dependencies = [ "syn 2.0.117", ] +[[package]] +name = "num_threads" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5c7398b9c8b70908f6371f47ed36737907c87c52af34c268fed0bf0ceb92ead9" +dependencies = [ + "libc", +] + [[package]] name = "objc2" version = "0.6.4" @@ -3013,7 +3011,6 @@ name = "owncord-client" version = "1.1.0-alpha.2" dependencies = [ "device_query", - "env_logger", "futures-util", "keyring", "log", @@ -3029,6 +3026,7 @@ dependencies = [ "tauri-plugin-dialog", "tauri-plugin-fs", "tauri-plugin-http", + "tauri-plugin-log", "tauri-plugin-notification", "tauri-plugin-opener", "tauri-plugin-process", @@ -3431,15 +3429,6 @@ version = "1.13.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c33a9471896f1c69cecef8d20cbe2f7accd12527ce60845ff44c153bb2a21b49" -[[package]] -name = "portable-atomic-util" -version = "0.2.6" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "091397be61a01d4be58e7841595bd4bfedb15f1cd54977d79b8271e94ed799a3" -dependencies = [ - "portable-atomic", -] - [[package]] name = "potential_utf" version = "0.1.4" @@ -5073,6 +5062,27 @@ dependencies = [ "urlpattern", ] +[[package]] +name = "tauri-plugin-log" +version = "2.9.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6792296e6f389268016c77db21ebae1fc0568f2fccf88b1ec7e2ea71330afb4c" +dependencies = [ + "android_logger", + "fern", + "log", + "objc2", + "objc2-foundation", + "serde", + "serde_json", + "serde_repr", + "swift-rs", + "tauri", + "tauri-plugin", + "thiserror 2.0.18", + "time", +] + [[package]] name = "tauri-plugin-notification" version = "2.3.3" @@ -5442,7 +5452,9 @@ checksum = "743bd48c283afc0388f9b8827b976905fb217ad9e647fae3a379a9283c4def2c" dependencies = [ "deranged", "itoa", + "libc", "num-conv", + "num_threads", "powerfmt", "serde_core", "time-core", diff --git a/Client/tauri-client/src-tauri/Cargo.toml b/Client/tauri-client/src-tauri/Cargo.toml index 7aae1b0a..7a2640d7 100644 --- a/Client/tauri-client/src-tauri/Cargo.toml +++ b/Client/tauri-client/src-tauri/Cargo.toml @@ -48,7 +48,10 @@ rustls = { version = "0.23", default-features = false, features = ["ring", "std" webpki-roots = "1" ring = "0.17" log = "0.4" -env_logger = "0.11" +# Writes Rust logs to a rotating file under the OS app-log dir (alongside the +# TS client-logs) so a shipped user can retrieve them — a release build detaches +# the console, so stdout/stderr logging is otherwise unreachable. +tauri-plugin-log = "2" keyring = "3" rfd = { version = "0.16", default-features = false } diff --git a/Client/tauri-client/src-tauri/src/commands.rs b/Client/tauri-client/src-tauri/src/commands.rs index e734a34b..0c876d92 100644 --- a/Client/tauri-client/src-tauri/src/commands.rs +++ b/Client/tauri-client/src-tauri/src/commands.rs @@ -47,6 +47,13 @@ pub fn get_settings(app: tauri::AppHandle) -> Result { Ok(Value::Object(map)) } +/// Log a command failure Rust-side — so it lands in the retrievable log file — +/// and return the same message unchanged to the JS caller. +fn log_cmd_err(cmd: &str, msg: String) -> String { + log::warn!("{cmd}: {msg}"); + msg +} + #[tauri::command] pub fn save_settings(app: tauri::AppHandle, key: String, value: Value) -> Result<(), String> { if !is_settings_key_allowed(&key) { @@ -55,12 +62,12 @@ pub fn save_settings(app: tauri::AppHandle, key: String, value: Value) -> Result let store = app .store(SETTINGS_STORE) - .map_err(|e| format!("failed to open settings store: {e}"))?; + .map_err(|e| log_cmd_err("save_settings", format!("failed to open settings store: {e}")))?; store.set(&key, value); store .save() - .map_err(|e| format!("failed to persist settings: {e}"))?; + .map_err(|e| log_cmd_err("save_settings", format!("failed to persist settings: {e}")))?; Ok(()) } @@ -102,9 +109,9 @@ pub fn store_cert_fingerprint( } } - let store = app - .store(CERTS_STORE) - .map_err(|e| format!("failed to open certs store: {e}"))?; + let store = app.store(CERTS_STORE).map_err(|e| { + log_cmd_err("store_cert_fingerprint", format!("failed to open certs store: {e}")) + })?; // Capture old value before mutating so we can restore it if save fails. let old_value = store.get(&host); @@ -117,7 +124,10 @@ pub fn store_cert_fingerprint( Some(v) => { store.set(&host, v); } None => { let _ = store.delete(&host); } } - return Err(format!("failed to persist cert fingerprint: {e}")); + return Err(log_cmd_err( + "store_cert_fingerprint", + format!("failed to persist cert fingerprint: {e}"), + )); } Ok(()) } @@ -231,7 +241,7 @@ pub fn get_identity_pin( .store(IDENTITY_PINS_STORE) .map_err(|e| format!("failed to open identity pins store: {e}"))?; - let value = store.get(&identity_pin_key(&host, &user_id)).and_then(|v| { + let value = store.get(identity_pin_key(&host, &user_id)).and_then(|v| { if let Value::String(s) = v { Some(s) } else { diff --git a/Client/tauri-client/src-tauri/src/http_proxy.rs b/Client/tauri-client/src-tauri/src/http_proxy.rs index e9a0b22d..82d6bce2 100644 --- a/Client/tauri-client/src-tauri/src/http_proxy.rs +++ b/Client/tauri-client/src-tauri/src/http_proxy.rs @@ -107,12 +107,21 @@ pub async fn start_http_proxy( .port(); let (shutdown_tx, shutdown_rx) = tokio::sync::oneshot::channel::<()>(); - tokio::spawn(run_proxy_loop( + let loop_handle = tokio::spawn(run_proxy_loop( app.clone(), listener, remote_host.clone(), shutdown_rx, )); + // Watch the loop so a panic is logged instead of vanishing silently (which + // would leave JS with a stale cached port and no error). + tokio::spawn(async move { + match loop_handle.await { + Ok(()) => info!("[http_proxy] proxy loop exited"), + Err(e) if e.is_panic() => error!("[http_proxy] proxy loop panicked: {e:?}"), + Err(e) => warn!("[http_proxy] proxy loop join error: {e:?}"), + } + }); info!( "[http_proxy] tunnel started on 127.0.0.1:{} → {}", diff --git a/Client/tauri-client/src-tauri/src/lib.rs b/Client/tauri-client/src-tauri/src/lib.rs index 27c142bf..4b14958d 100644 --- a/Client/tauri-client/src-tauri/src/lib.rs +++ b/Client/tauri-client/src-tauri/src/lib.rs @@ -9,6 +9,26 @@ mod tray; mod update_commands; mod ws_proxy; +/// Map the RUST_LOG env var to a global level filter for the log plugin. +/// ponytail: only the simple global form is honoured ("debug", "info", …); +/// per-module directives like "ws_proxy=debug" fall back to Info. Add a real +/// parser only if per-module control is actually needed. +fn log_level_from_env() -> log::LevelFilter { + match std::env::var("RUST_LOG") + .unwrap_or_default() + .trim() + .to_ascii_lowercase() + .as_str() + { + "trace" => log::LevelFilter::Trace, + "debug" => log::LevelFilter::Debug, + "warn" => log::LevelFilter::Warn, + "error" => log::LevelFilter::Error, + "off" => log::LevelFilter::Off, + _ => log::LevelFilter::Info, + } +} + // Only used by the desktop-only single-instance closure below. #[cfg(desktop)] use tauri::Manager; @@ -31,6 +51,24 @@ pub fn run() { })); let builder = builder + // Log plugin registered early so logging is available to everything + // after it. Writes to stdout (dev) and a rotating file in the OS + // app-log dir so a shipped user — whose release build has no console — + // can retrieve logs. + .plugin( + tauri_plugin_log::Builder::new() + .target(tauri_plugin_log::Target::new( + tauri_plugin_log::TargetKind::Stdout, + )) + .target(tauri_plugin_log::Target::new( + tauri_plugin_log::TargetKind::LogDir { + file_name: Some("owncord-client".into()), + }, + )) + .level(log_level_from_env()) + .max_file_size(10_000_000) // 10 MB rolling file (default 40 KB is too small) + .build(), + ) .plugin(tauri_plugin_store::Builder::new().build()) .plugin(tauri_plugin_notification::init()) .plugin(tauri_plugin_http::init()) @@ -88,14 +126,7 @@ pub fn run() { commands::open_devtools, ]) .setup(|app| { - // Initialize Rust logging (controlled by RUST_LOG env var, defaults to info). - // try_init avoids panic if another logger (e.g. a Tauri plugin) registered first. - let _ = env_logger::Builder::from_env( - env_logger::Env::default().default_filter_or("info"), - ) - .format_timestamp_millis() - .try_init(); - + // Rust logging is initialized by tauri_plugin_log (registered above). tray::create_tray(app.handle())?; Ok(()) }) diff --git a/Client/tauri-client/src-tauri/src/livekit_proxy.rs b/Client/tauri-client/src-tauri/src/livekit_proxy.rs index dde9f4d8..e5f03f3d 100644 --- a/Client/tauri-client/src-tauri/src/livekit_proxy.rs +++ b/Client/tauri-client/src-tauri/src/livekit_proxy.rs @@ -134,7 +134,15 @@ pub async fn start_livekit_proxy( let (shutdown_tx, shutdown_rx) = tokio::sync::oneshot::channel::<()>(); let host = remote_host.clone(); - tokio::spawn(run_proxy_loop(listener, host, fingerprint, shutdown_rx)); + let loop_handle = tokio::spawn(run_proxy_loop(listener, host, fingerprint, shutdown_rx)); + // Watch the loop so a panic is logged instead of vanishing silently. + tokio::spawn(async move { + match loop_handle.await { + Ok(()) => info!("[livekit_proxy] proxy loop exited"), + Err(e) if e.is_panic() => error!("[livekit_proxy] proxy loop panicked: {e:?}"), + Err(e) => warn!("[livekit_proxy] proxy loop join error: {e:?}"), + } + }); info!("[livekit_proxy] proxy started on 127.0.0.1:{} → {}", port, remote_host); diff --git a/Client/tauri-client/src-tauri/src/ws_proxy.rs b/Client/tauri-client/src-tauri/src/ws_proxy.rs index 963e1523..a66bf84e 100644 --- a/Client/tauri-client/src-tauri/src/ws_proxy.rs +++ b/Client/tauri-client/src-tauri/src/ws_proxy.rs @@ -307,13 +307,17 @@ pub fn accept_cert_fingerprint( return Err("fingerprint must be SHA-256 colon-hex format (e.g. aa:bb:cc:...)".into()); } - let store = app - .store(CERTS_STORE) - .map_err(|e| format!("failed to open certs store: {e}"))?; + let store = app.store(CERTS_STORE).map_err(|e| { + log::warn!("[ws_proxy] accept_cert_fingerprint: failed to open certs store: {e}"); + format!("failed to open certs store: {e}") + })?; // Capture old value before mutating so we can restore it if save fails. let old_value = store.get(&host); - store.set(&host, Value::String(fingerprint)); + // A pin that replaces a *different* existing fingerprint is security- + // significant (cert rotation — or a MITM the user just accepted). + let changed = matches!(&old_value, Some(Value::String(s)) if *s != fingerprint); + store.set(&host, Value::String(fingerprint.clone())); if let Err(e) = store.save() { // Restore previous in-memory state: put back old fingerprint if one // existed, or delete if there was none. Without this, the new @@ -323,7 +327,14 @@ pub fn accept_cert_fingerprint( Some(v) => { store.set(&host, v); } None => { let _ = store.delete(&host); } } + log::warn!("[ws_proxy] accept_cert_fingerprint: failed to persist pin for {host}: {e}"); return Err(format!("failed to persist cert fingerprint: {e}")); } + // Fingerprints are public cert hashes — safe to log; this is the TOFU audit trail. + if changed { + log::warn!("[ws_proxy] cert pin CHANGED for {host} -> {fingerprint}"); + } else { + log::info!("[ws_proxy] cert pin accepted for {host} -> {fingerprint}"); + } Ok(()) } diff --git a/Client/tauri-client/src/lib/api.ts b/Client/tauri-client/src/lib/api.ts index 1e74f416..74547982 100644 --- a/Client/tauri-client/src/lib/api.ts +++ b/Client/tauri-client/src/lib/api.ts @@ -129,6 +129,9 @@ export function createApiClient(initialConfig: ApiClientConfig, onUnauthorized?: status: res.status, code: err.error, message: err.message, + // Server echoes its request ID in this header — logging it lets a + // client-side failure be matched to the server's log line for it. + reqId: res.headers.get("x-request-id") ?? undefined, }); throw new ApiClientError(res.status, err.error, err.message); } diff --git a/Client/tauri-client/src/lib/logPersistence.ts b/Client/tauri-client/src/lib/logPersistence.ts index 54508e11..23824c0a 100644 --- a/Client/tauri-client/src/lib/logPersistence.ts +++ b/Client/tauri-client/src/lib/logPersistence.ts @@ -6,7 +6,7 @@ import { appLogDir, join } from "@tauri-apps/api/path"; import { mkdir, writeTextFile, readDir, remove, exists } from "@tauri-apps/plugin-fs"; -import { type LogEntry, addLogListener, createLogger } from "./logger"; +import { type LogEntry, addLogListener, createLogger, getLogBuffer } from "./logger"; const log = createLogger("logPersistence"); const MAX_LOG_FILES = 5; @@ -131,7 +131,18 @@ export async function initLogPersistence(): Promise<() => void> { currentDate = today(); initialized = true; + // Persist entries logged before this listener attached (the bootstrap + // window) so a startup-time problem lands on disk, not just in the + // in-memory ring. Runs synchronously right before addLogListener, so there + // is no gap and no double-capture. + for (const entry of getLogBuffer()) { + buffer.push(JSON.stringify(entry)); + } + const removeListener = addLogListener(onLogEntry); + if (buffer.length > 0) { + scheduleFlush(); + } return () => { removeListener(); // stop receiving new entries first diff --git a/Client/tauri-client/src/lib/ws.ts b/Client/tauri-client/src/lib/ws.ts index 35cd4396..7085b7cb 100644 --- a/Client/tauri-client/src/lib/ws.ts +++ b/Client/tauri-client/src/lib/ws.ts @@ -220,7 +220,9 @@ export function createWsClient() { try { parsed = JSON.parse(raw) as { type?: string; payload?: unknown; id?: string; seq?: number }; } catch { - log.warn("Failed to parse WS message", { data: raw }); + // Log the size only — `raw` is the decrypted frame (chat plaintext, + // usernames) and this line is persisted to the on-disk log. + log.warn("Failed to parse WS message", { bytes: raw.length }); return; } @@ -489,8 +491,11 @@ export function createWsClient() { if (msg.includes("channel full")) { // Outbound channel is saturated — surface the drop to listeners so an // optimistic row fails with retry instead of silently losing the send. + // Log id + size only — a slice of `json` can contain the auth + // envelope's bearer token, and this line is persisted to disk. log.warn("ws_send: outbound channel full, message dropped (backpressure)", { - messagePreview: json.slice(0, 120), + id, + bytes: json.length, }); notifySendFailure(id, "NETWORK"); } else { diff --git a/Client/tauri-client/src/main.ts b/Client/tauri-client/src/main.ts index 72ead6ad..a14d8550 100644 --- a/Client/tauri-client/src/main.ts +++ b/Client/tauri-client/src/main.ts @@ -226,7 +226,10 @@ function runHealthChecks( version: health.version ?? null, onlineUsers: health.online_users ?? null, }); - } catch { + } catch (err) { + // Record why the check failed (TLS/cert-pin/network) — otherwise a + // "can't connect" report has no logged cause to diagnose. + log.warn("health check failed", { host: profile.host, error: String(err) }); connectPage.updateHealthStatus(profile.host, { status: "offline", latencyMs: null, diff --git a/Client/tauri-client/tests/unit/log-persistence.test.ts b/Client/tauri-client/tests/unit/log-persistence.test.ts index db1f752c..9793785d 100644 --- a/Client/tauri-client/tests/unit/log-persistence.test.ts +++ b/Client/tauri-client/tests/unit/log-persistence.test.ts @@ -13,6 +13,7 @@ const { mockRemove, mockReadTextFile, mockAddLogListener, + mockGetLogBuffer, } = vi.hoisted(() => ({ mockAppLogDir: vi.fn().mockResolvedValue("/mock/logs"), mockJoin: vi.fn((...parts: string[]) => parts.join("/")), @@ -23,6 +24,7 @@ const { mockRemove: vi.fn().mockResolvedValue(undefined), mockReadTextFile: vi.fn().mockResolvedValue(""), mockAddLogListener: vi.fn(), + mockGetLogBuffer: vi.fn(() => [] as unknown[]), })); vi.mock("@tauri-apps/api/path", () => ({ @@ -41,6 +43,7 @@ vi.mock("@tauri-apps/plugin-fs", () => ({ vi.mock("@lib/logger", () => ({ addLogListener: mockAddLogListener, + getLogBuffer: mockGetLogBuffer, createLogger: () => ({ debug: vi.fn(), info: vi.fn(), @@ -102,6 +105,7 @@ describe("log persistence", () => { mockRemove.mockReset().mockResolvedValue(undefined); mockReadTextFile.mockReset().mockResolvedValue(""); mockAddLogListener.mockReset(); + mockGetLogBuffer.mockReset().mockReturnValue([]); }); afterEach(() => { @@ -148,6 +152,20 @@ describe("log persistence", () => { expect(typeof mockAddLogListener.mock.calls[0]![0]).toBe("function"); }); + it("persists entries buffered before init (bootstrap drain)", async () => { + mockGetLogBuffer.mockReturnValue([makeEntry({ message: "bootstrap-line" })]); + const { initLogPersistence } = await freshImport(); + captureListener(); + await initLogPersistence(); + + // The drain scheduled a flush; advance past the 2000ms debounce. + await vi.advanceTimersByTimeAsync(2500); + + expect(mockWriteTextFile).toHaveBeenCalled(); + const written = mockWriteTextFile.mock.calls.map((c) => String(c[1])).join(""); + expect(written).toContain("bootstrap-line"); + }); + it("returns a no-op cleanup if already initialized", async () => { const { initLogPersistence } = await freshImport(); captureListener(); diff --git a/Client/tauri-client/tests/unit/ws.test.ts b/Client/tauri-client/tests/unit/ws.test.ts index c3a731f6..4930f594 100644 --- a/Client/tauri-client/tests/unit/ws.test.ts +++ b/Client/tauri-client/tests/unit/ws.test.ts @@ -42,6 +42,7 @@ vi.spyOn(console, "error").mockImplementation(() => {}); // Import after mocks are set up import { createWsClient, toConnectionStatus } from "../../src/lib/ws"; +import { addLogListener, type LogEntry } from "../../src/lib/logger"; /** Simulate Tauri emitting an event to JS */ function emitTauriEvent(event: string, payload: unknown): void { @@ -291,6 +292,23 @@ describe("WebSocket Client (Tauri proxy)", () => { expect(messages).toHaveLength(0); }); + it("does not log raw frame content on parse failure (no plaintext leak)", async () => { + client.connect({ host: "localhost:8443", token: "t" }); + await vi.advanceTimersByTimeAsync(10); + emitTauriEvent("ws-state", "open"); + + const entries: LogEntry[] = []; + const remove = addLogListener((e) => entries.push(e)); + const secret = "SUPER_SECRET_eyJhbGciOiJIUzI1NiJ9"; + emitTauriEvent("ws-message", secret + " not-json{{{"); + remove(); + + // The decrypted frame must never reach the (on-disk-persisted) log... + expect(JSON.stringify(entries)).not.toContain(secret); + // ...but the parse failure is still recorded so it stays debuggable. + expect(entries.some((e) => e.message.includes("Failed to parse WS message"))).toBe(true); + }); + it("disconnect prevents reconnect", async () => { client.connect({ host: "localhost:8443", token: "t" }); await vi.advanceTimersByTimeAsync(10); diff --git a/Server/api/channel_handler.go b/Server/api/channel_handler.go index 33063b93..78e23cb5 100644 --- a/Server/api/channel_handler.go +++ b/Server/api/channel_handler.go @@ -1,6 +1,7 @@ package api import ( + "context" "errors" "log/slog" "net/http" @@ -134,7 +135,7 @@ func handleGetMessages(svc *service.Services) http.HandlerFunc { msgs, hasMore, err := svc.Messages.GetMessages(r.Context(), user.ID, channelID, before, limit) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } @@ -200,7 +201,7 @@ func handleSearch(svc *service.Services) http.HandlerFunc { }) return } - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } if results == nil { @@ -232,7 +233,7 @@ func handleGetPins(svc *service.Services) http.HandlerFunc { msgs, err := svc.Messages.GetPinnedMessages(r.Context(), user.ID, channelID) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } @@ -265,7 +266,7 @@ func handleSetPinned(svc *service.Services, pinned bool) http.HandlerFunc { } if err := svc.Messages.SetMessagePinned(r.Context(), user.ID, channelID, messageID, pinned); err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } w.WriteHeader(http.StatusNoContent) @@ -273,7 +274,7 @@ func handleSetPinned(svc *service.Services, pinned bool) http.HandlerFunc { } // writeServiceError maps a service-layer error to an HTTP response. -func writeServiceError(w http.ResponseWriter, err error) { +func writeServiceError(ctx context.Context, w http.ResponseWriter, err error) { switch { case errors.Is(err, service.ErrRateLimited): writeJSON(w, http.StatusTooManyRequests, errorResponse{Error: "RATE_LIMITED", Message: err.Error()}) @@ -286,10 +287,12 @@ func writeServiceError(w http.ResponseWriter, err error) { case errors.Is(err, service.ErrConflict): writeJSON(w, http.StatusConflict, errorResponse{Error: "CONFLICT", Message: err.Error()}) case errors.Is(err, service.ErrInternal): - slog.Error("service error", "err", err) + // ErrorContext so the enriching handler attaches req_id/trace_id, + // linking this 500 to its request log line and trace. + slog.ErrorContext(ctx, "service error", "error", err) writeJSON(w, http.StatusInternalServerError, errorResponse{Error: "INTERNAL_ERROR", Message: "an internal error occurred"}) default: - slog.Error("service error", "err", err) + slog.ErrorContext(ctx, "service error", "error", err) writeJSON(w, http.StatusInternalServerError, errorResponse{Error: "INTERNAL_ERROR", Message: "internal error"}) } } diff --git a/Server/api/dm_handler.go b/Server/api/dm_handler.go index b61720c3..fff016aa 100644 --- a/Server/api/dm_handler.go +++ b/Server/api/dm_handler.go @@ -75,7 +75,7 @@ func handleCreateDM(svc *service.Services) http.HandlerFunc { result, err := svc.DMs.CreateDM(r.Context(), user.ID, req.RecipientID) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } @@ -115,7 +115,7 @@ func handleListDMs(svc *service.Services) http.HandlerFunc { channels, err := svc.DMs.ListDMs(r.Context(), user.ID) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } writeJSON(w, http.StatusOK, listDMsResponse{DMChannels: channels}) @@ -139,7 +139,7 @@ func handleCloseDM(svc *service.Services, broadcaster DMBroadcaster) http.Handle } if err := svc.DMs.CloseDM(r.Context(), user.ID, channelID); err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } @@ -170,7 +170,7 @@ func handleBlockUser(svc *service.Services) http.HandlerFunc { } if err := svc.Blocks.BlockUser(r.Context(), user.ID, targetID); err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } writeJSON(w, http.StatusOK, map[string]string{"message": "user blocked"}) @@ -192,7 +192,7 @@ func handleUnblockUser(svc *service.Services) http.HandlerFunc { } if err := svc.Blocks.UnblockUser(r.Context(), user.ID, targetID); err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } writeJSON(w, http.StatusOK, map[string]string{"message": "user unblocked"}) @@ -210,7 +210,7 @@ func handleListBlocks(svc *service.Services) http.HandlerFunc { ids, err := svc.Blocks.ListBlocked(r.Context(), user.ID) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } writeJSON(w, http.StatusOK, map[string]any{"blocked_user_ids": ids}) diff --git a/Server/api/invite_handler.go b/Server/api/invite_handler.go index 07689f05..30a6a882 100644 --- a/Server/api/invite_handler.go +++ b/Server/api/invite_handler.go @@ -75,7 +75,7 @@ func handleCreateInvite(svc *service.Services) http.HandlerFunc { inv, err := svc.Invites.CreateInvite(r.Context(), user.ID, req.MaxUses, req.ExpiresInHours) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } writeJSON(w, http.StatusCreated, toInviteResponse(inv)) @@ -87,7 +87,7 @@ func handleListInvites(svc *service.Services) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { invites, err := svc.Invites.ListInvites(r.Context()) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } @@ -104,7 +104,7 @@ func handleRevokeInvite(svc *service.Services) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { code := chi.URLParam(r, "code") if err := svc.Invites.RevokeInvite(r.Context(), code); err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } w.WriteHeader(http.StatusNoContent) diff --git a/Server/api/middleware.go b/Server/api/middleware.go index 3ac03b73..e0fe9d88 100644 --- a/Server/api/middleware.go +++ b/Server/api/middleware.go @@ -44,6 +44,11 @@ func AuthMiddleware(database *db.DB) func(http.Handler) http.Handler { hash := auth.HashToken(token) sess, err := database.GetSessionByTokenHash(r.Context(), hash) if err != nil || sess == nil { + if err != nil { + // A DB error here is an outage, not a bad token — log it so + // it's distinguishable from ordinary invalid-token 401s. + slog.ErrorContext(r.Context(), "auth: session lookup failed", "error", err) + } writeJSON(w, http.StatusUnauthorized, errorResponse{ Error: "UNAUTHORIZED", Message: "invalid or expired session", @@ -58,7 +63,9 @@ func AuthMiddleware(database *db.DB) func(http.Handler) http.Handler { // written, so detach cancellation: the deletion must complete. cleanupCtx := context.WithoutCancel(r.Context()) go func(h string) { - _ = database.DeleteSession(cleanupCtx, h) + if err := database.DeleteSession(cleanupCtx, h); err != nil { + slog.WarnContext(cleanupCtx, "expired session cleanup failed", "error", err) + } }(hash) writeJSON(w, http.StatusUnauthorized, errorResponse{ Error: "UNAUTHORIZED", @@ -70,6 +77,9 @@ func AuthMiddleware(database *db.DB) func(http.Handler) http.Handler { // Load user. user, err := database.GetUserByID(r.Context(), sess.UserID) if err != nil || user == nil { + if err != nil { + slog.ErrorContext(r.Context(), "auth: user lookup failed", "error", err, "user_id", sess.UserID) + } writeJSON(w, http.StatusUnauthorized, errorResponse{ Error: "UNAUTHORIZED", Message: "user not found", @@ -92,6 +102,9 @@ func AuthMiddleware(database *db.DB) func(http.Handler) http.Handler { // and every downstream permission check has to re-guard it. role, err := database.GetRoleByID(r.Context(), user.RoleID) if err != nil || role == nil { + if err != nil { + slog.ErrorContext(r.Context(), "auth: role lookup failed", "error", err, "user_id", user.ID, "role_id", user.RoleID) + } writeJSON(w, http.StatusUnauthorized, errorResponse{ Error: "UNAUTHORIZED", Message: "role not found", diff --git a/Server/api/profile_handler.go b/Server/api/profile_handler.go index 04d42f1e..50aee3ab 100644 --- a/Server/api/profile_handler.go +++ b/Server/api/profile_handler.go @@ -171,14 +171,14 @@ func handleUpdateProfile(svc *service.Services, broadcaster ProfileBroadcaster) updated, err := svc.Users.UpdateProfile(r.Context(), user.ID, req.Username, req.Avatar) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } if req.IdentityPublicKey != nil { updated, err = svc.Users.UpdateIdentityKey(r.Context(), user.ID, *req.IdentityPublicKey) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } } @@ -275,7 +275,7 @@ func handleChangePassword(svc *service.Services, limiter *auth.RateLimiter) http res, err := svc.Users.ChangePassword(r.Context(), user.ID, hash, keepSessionID) if err != nil { // Only reachable when the password itself failed to commit. - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } if res.RevokeFailed { @@ -314,7 +314,7 @@ func handleListSessions(svc *service.Services) http.HandlerFunc { sessions, err := svc.Users.ListSessions(r.Context(), user.ID) if err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } @@ -353,7 +353,7 @@ func handleRevokeSession(svc *service.Services) http.HandlerFunc { } if err := svc.Users.RevokeSession(r.Context(), user.ID, sessionID); err != nil { - writeServiceError(w, err) + writeServiceError(r.Context(), w, err) return } diff --git a/Server/api/router.go b/Server/api/router.go index 12227d81..c278b803 100644 --- a/Server/api/router.go +++ b/Server/api/router.go @@ -18,6 +18,7 @@ import ( "github.com/owncord/server/permissions" "github.com/owncord/server/plugin" "github.com/owncord/server/service" + "github.com/owncord/server/stackutil" "github.com/owncord/server/storage" "github.com/owncord/server/telemetry" "github.com/owncord/server/updater" @@ -39,7 +40,7 @@ func NewRouter(cfg *config.Config, database *db.DB, ver string, logBuf *admin.Ri // NOTE: middleware.RealIP is intentionally omitted — trusting X-Real-IP from // any source allows IP spoofing for rate-limit bypass. IP header trust is now // handled explicitly in clientIPWithProxies using the trusted_proxies config. - r.Use(middleware.Recoverer) + r.Use(recoverer) // slog-routing panic recovery (replaces chi's stderr-only Recoverer) r.Use(requestLogger) // structured request/response logging // Phase B Step 8 — OpenTelemetry HTTP tracing. No-op when telemetry is // disabled or the otel build tag is not set, so this is safe to mount @@ -363,6 +364,44 @@ func setRequestIDHeader(next http.Handler) http.Handler { }) } +// recoverer recovers from panics in HTTP handlers and logs them through slog — +// so they reach the admin log stream and are structured — unlike chi's default +// middleware.Recoverer, which writes an unstructured stack to stderr only. The +// stack is captured via stackutil so it never embeds argument values (which on +// auth/upload paths can carry tokens or passwords). +func recoverer(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // Capture correlation IDs before dispatch so the recovery closure makes + // no context calls (which trip contextcheck inside a defer), while the + // panic log still carries req_id/trace_id. + reqID := middleware.GetReqID(r.Context()) + traceID := telemetry.TraceIDFromContext(r.Context()) + defer func() { + if rec := recover(); rec != nil { + // Preserve chi's behaviour of not swallowing the abort sentinel. + if rec == http.ErrAbortHandler { + panic(rec) + } + attrs := []any{ + "method", r.Method, + "path", r.URL.Path, + "panic", rec, + "stack", stackutil.Capture(), + } + if reqID != "" { + attrs = append(attrs, "req_id", reqID) + } + if traceID != "" { + attrs = append(attrs, "trace_id", traceID) + } + slog.Error("http handler panic recovered", attrs...) + w.WriteHeader(http.StatusInternalServerError) + } + }() + next.ServeHTTP(w, r) + }) +} + // requestLogger logs every HTTP request with method, path, status, and duration. // Health checks are logged at Debug level to avoid noise. func requestLogger(next http.Handler) http.Handler { diff --git a/Server/config/config.go b/Server/config/config.go index 86fe2f13..d1b51828 100644 --- a/Server/config/config.go +++ b/Server/config/config.go @@ -30,6 +30,36 @@ type Config struct { Telemetry TelemetryConfig `koanf:"telemetry"` Plugins PluginsConfig `koanf:"plugins"` GIF GIFConfig `koanf:"gif"` + Logging LoggingConfig `koanf:"logging"` +} + +// LoggingConfig controls server log verbosity. The in-memory ring buffer that +// backs the admin panel's live log view always captures DEBUG regardless of +// this setting — Level only gates what is written to stdout. +type LoggingConfig struct { + // Level is the minimum level written to stdout: "debug" | "info" | "warn" | + // "error". Override at runtime without editing config.yaml via the + // OWNCORD_LOGGING_LEVEL environment variable. + Level string `koanf:"level"` +} + +// ParseLevel maps a config log-level string to a slog.Level. It is +// case-insensitive and treats "" as info. The bool is false for an +// unrecognised value (in which case slog.LevelInfo is returned and the caller +// should warn) so a typo doesn't silently disable logging. +func ParseLevel(s string) (slog.Level, bool) { + switch strings.ToLower(strings.TrimSpace(s)) { + case "debug": + return slog.LevelDebug, true + case "", "info": + return slog.LevelInfo, true + case "warn", "warning": + return slog.LevelWarn, true + case "error": + return slog.LevelError, true + default: + return slog.LevelInfo, false + } } // GIFConfig holds the credentials for the server-side GIF (Klipy) proxy. @@ -221,6 +251,9 @@ func defaults() Config { CPUBudgetMs: 100, HTTPAllowlist: []string{}, }, + Logging: LoggingConfig{ + Level: "info", + }, } } @@ -305,6 +338,12 @@ voice: # Get a key at https://partner.klipy.com # gif: # api_key: "" + +# Logging. "level" gates what is written to stdout; the admin panel's live log +# view always captures debug regardless. Override without editing this file via +# the OWNCORD_LOGGING_LEVEL environment variable. +# logging: +# level: "info" # debug | info | warn | error ` // Load reads configuration from the given YAML file path, merging with diff --git a/Server/config/logging_test.go b/Server/config/logging_test.go new file mode 100644 index 00000000..ab4b1ae9 --- /dev/null +++ b/Server/config/logging_test.go @@ -0,0 +1,48 @@ +package config + +import ( + "log/slog" + "path/filepath" + "testing" +) + +func TestParseLevel(t *testing.T) { + cases := []struct { + in string + want slog.Level + ok bool + }{ + {"debug", slog.LevelDebug, true}, + {"info", slog.LevelInfo, true}, + {"", slog.LevelInfo, true}, + {"WARN", slog.LevelWarn, true}, + {"warning", slog.LevelWarn, true}, + {"error", slog.LevelError, true}, + {" Debug ", slog.LevelDebug, true}, + {"bogus", slog.LevelInfo, false}, + } + for _, c := range cases { + got, ok := ParseLevel(c.in) + if got != c.want || ok != c.ok { + t.Errorf("ParseLevel(%q) = %v,%v want %v,%v", c.in, got, ok, c.want, c.ok) + } + } +} + +// TestLoggingLevelFromEnv verifies the end-to-end wiring: OWNCORD_LOGGING_LEVEL +// overrides config.yaml via koanf's existing env layer. +func TestLoggingLevelFromEnv(t *testing.T) { + cfgPath := filepath.Join(t.TempDir(), "config.yaml") + t.Setenv("OWNCORD_LOGGING_LEVEL", "debug") + + cfg, err := Load(cfgPath) + if err != nil { + t.Fatalf("Load: %v", err) + } + if cfg.Logging.Level != "debug" { + t.Errorf("expected level %q from env, got %q", "debug", cfg.Logging.Level) + } + if lvl, ok := ParseLevel(cfg.Logging.Level); !ok || lvl != slog.LevelDebug { + t.Errorf("ParseLevel(%q) = %v,%v", cfg.Logging.Level, lvl, ok) + } +} diff --git a/Server/config/logvalue.go b/Server/config/logvalue.go new file mode 100644 index 00000000..cbee7bfd --- /dev/null +++ b/Server/config/logvalue.go @@ -0,0 +1,69 @@ +package config + +import "log/slog" + +// This file makes secret-bearing config types safe to log by construction. +// Without it, "never log secrets" holds only by call-site discipline — a +// single slog.Info("cfg", "voice", cfg.Voice) would dump the LiveKit key. By +// implementing slog.LogValuer, secrets are redacted no matter how the value +// reaches a log record. Non-secret fields stay visible so the logs remain +// useful for debugging. + +// redactSecret masks a secret for logging. An empty value stays empty (so an +// unset credential is still visible as "unset"); anything else becomes a fixed +// marker that reveals neither the value nor its length. +func redactSecret(s string) string { + if s == "" { + return "" + } + return "[REDACTED]" +} + +// LogValue redacts the LiveKit API key and secret. +func (v VoiceConfig) LogValue() slog.Value { + return slog.GroupValue( + slog.String("livekit_api_key", redactSecret(v.LiveKitAPIKey)), + slog.String("livekit_api_secret", redactSecret(v.LiveKitAPISecret)), + slog.String("livekit_url", v.LiveKitURL), + slog.String("livekit_binary", v.LiveKitBinaryPath), + slog.String("node_ip", v.NodeIP), + slog.Bool("advertise_internal_ip", v.AdvertiseInternalIP), + slog.String("quality", v.Quality), + ) +} + +// LogValue redacts the GitHub token. +func (g GitHubConfig) LogValue() slog.Value { + return slog.GroupValue( + slog.String("token", redactSecret(g.Token)), + slog.String("owner", g.Owner), + slog.String("repo", g.Repo), + ) +} + +// LogValue redacts the Klipy (GIF proxy) API key. +func (g GIFConfig) LogValue() slog.Value { + return slog.GroupValue( + slog.String("api_key", redactSecret(g.APIKey)), + ) +} + +// LogValue delegates each section through slog.Any so secret-bearing sections +// are redacted via their own LogValue even when the whole Config is logged. +// A section added to Config but not listed here is omitted from the log (safe: +// it is hidden, never leaked). +func (c Config) LogValue() slog.Value { + return slog.GroupValue( + slog.Any("server", c.Server), + slog.Any("database", c.Database), + slog.Any("tls", c.TLS), + slog.Any("upload", c.Upload), + slog.Any("voice", c.Voice), + slog.Any("github", c.GitHub), + slog.Any("event_persistence", c.EventPersistence), + slog.Any("telemetry", c.Telemetry), + slog.Any("plugins", c.Plugins), + slog.Any("gif", c.GIF), + slog.Any("logging", c.Logging), + ) +} diff --git a/Server/config/logvalue_test.go b/Server/config/logvalue_test.go new file mode 100644 index 00000000..888f8d79 --- /dev/null +++ b/Server/config/logvalue_test.go @@ -0,0 +1,45 @@ +package config + +import ( + "bytes" + "log/slog" + "strings" + "testing" +) + +// TestSecretConfigsRedactedInLogs is the security guard for config redaction: +// no matter whether the whole Config or a single section is logged, the +// LiveKit key/secret, GitHub token, and Klipy key must never reach the output. +func TestSecretConfigsRedactedInLogs(t *testing.T) { + const ( + lkKey = "LIVEKIT_KEY_should_not_appear" + lkSecret = "LIVEKIT_SECRET_should_not_appear" + ghToken = "ghp_token_should_not_appear" + gifKey = "klipy_key_should_not_appear" + ) + cfg := Config{ + Voice: VoiceConfig{LiveKitAPIKey: lkKey, LiveKitAPISecret: lkSecret, Quality: "high"}, + GitHub: GitHubConfig{Token: ghToken, Owner: "acme"}, + GIF: GIFConfig{APIKey: gifKey}, + } + + var buf bytes.Buffer + log := slog.New(slog.NewTextHandler(&buf, nil)) + log.Info("whole", "config", cfg) // whole-config path (delegating LogValue) + log.Info("voice", "voice", cfg.Voice) + log.Info("github", "github", cfg.GitHub) + log.Info("gif", "gif", cfg.GIF) + + out := buf.String() + for _, secret := range []string{lkKey, lkSecret, ghToken, gifKey} { + if strings.Contains(out, secret) { + t.Errorf("secret leaked into log output: %q\n%s", secret, out) + } + } + if !strings.Contains(out, "high") || !strings.Contains(out, "acme") { + t.Errorf("expected non-secret fields in output:\n%s", out) + } + if !strings.Contains(out, "[REDACTED]") { + t.Errorf("expected redaction marker in output:\n%s", out) + } +} diff --git a/Server/db/logvalue.go b/Server/db/logvalue.go new file mode 100644 index 00000000..89880fe7 --- /dev/null +++ b/Server/db/logvalue.go @@ -0,0 +1,34 @@ +package db + +import "log/slog" + +// This file makes the secret-bearing domain types safe to log by construction. +// User.PasswordHash / User.TOTPSecret and Session.TokenHash are json:"-", but +// that only guards JSON responses — slog renders struct fields regardless. By +// implementing slog.LogValuer, logging a *db.User or *db.Session (e.g. +// slog.Info("x", "user", user)) never emits the credential. Secret fields are +// omitted entirely; the useful identifying fields stay visible. + +// LogValue omits PasswordHash and TOTPSecret. It exposes whether TOTP is +// enabled (not the secret) since that is often what a log line needs. +func (u User) LogValue() slog.Value { + return slog.GroupValue( + slog.Int64("id", u.ID), + slog.String("username", u.Username), + slog.Int64("role_id", u.RoleID), + slog.String("status", u.Status), + slog.Bool("banned", u.Banned), + slog.Bool("totp_enabled", u.TOTPSecret != nil), + ) +} + +// LogValue omits TokenHash (the session-identifying secret). +func (s Session) LogValue() slog.Value { + return slog.GroupValue( + slog.Int64("id", s.ID), + slog.Int64("user_id", s.UserID), + slog.String("device", s.Device), + slog.String("ip", s.IP), + slog.String("expires_at", s.ExpiresAt), + ) +} diff --git a/Server/db/logvalue_test.go b/Server/db/logvalue_test.go new file mode 100644 index 00000000..f72f44bd --- /dev/null +++ b/Server/db/logvalue_test.go @@ -0,0 +1,41 @@ +package db + +import ( + "bytes" + "log/slog" + "strings" + "testing" +) + +// TestUserSessionRedactedInLogs is the security guard for domain-type +// redaction: logging a db.User / db.Session (by value or by pointer) must never +// emit the password hash, TOTP secret, or session token hash. +func TestUserSessionRedactedInLogs(t *testing.T) { + const ( + pwHash = "PWHASH_should_not_appear" + totp = "TOTP_SECRET_should_not_appear" + token = "TOKENHASH_should_not_appear" + ) + totpPtr := totp + user := User{ID: 7, Username: "alice", PasswordHash: pwHash, TOTPSecret: &totpPtr, RoleID: 2} + sess := Session{ID: 3, UserID: 7, TokenHash: token, Device: "cli"} + + var buf bytes.Buffer + log := slog.New(slog.NewTextHandler(&buf, nil)) + // Value and pointer paths — both must resolve LogValue. + log.Info("u", "user", user, "user_ptr", &user) + log.Info("s", "session", sess, "session_ptr", &sess) + + out := buf.String() + for _, secret := range []string{pwHash, totp, token} { + if strings.Contains(out, secret) { + t.Errorf("secret leaked into log output: %q\n%s", secret, out) + } + } + if !strings.Contains(out, "alice") { + t.Errorf("expected username in output:\n%s", out) + } + if !strings.Contains(out, "totp_enabled=true") { + t.Errorf("expected totp_enabled flag in output:\n%s", out) + } +} diff --git a/Server/logctx/logctx.go b/Server/logctx/logctx.go new file mode 100644 index 00000000..0bacffc6 --- /dev/null +++ b/Server/logctx/logctx.go @@ -0,0 +1,54 @@ +// Package logctx provides a slog.Handler that enriches every log record with +// correlation IDs pulled from the context: the chi request ID (as req_id) and, +// under -tags otel, the OpenTelemetry trace ID (as trace_id). +// +// Wrapping the base handler with New means any log call using the ...Context +// variants (slog.InfoContext, slog.ErrorContext, …) automatically carries +// these IDs, so a log line can be tied back to its HTTP request and its +// distributed trace without threading the IDs through by hand at every site. +package logctx + +import ( + "context" + "log/slog" + + "github.com/go-chi/chi/v5/middleware" + "github.com/owncord/server/telemetry" +) + +type handler struct { + inner slog.Handler +} + +// New wraps inner so that records handled with a context carrying a chi request +// ID (and, in the otel build, an active span) are enriched with req_id and +// trace_id attributes. +func New(inner slog.Handler) slog.Handler { + return handler{inner: inner} +} + +func (h handler) Enabled(ctx context.Context, l slog.Level) bool { + return h.inner.Enabled(ctx, l) +} + +func (h handler) Handle(ctx context.Context, r slog.Record) error { + if reqID := middleware.GetReqID(ctx); reqID != "" { + r.AddAttrs(slog.String("req_id", reqID)) + } + if tid := telemetry.TraceIDFromContext(ctx); tid != "" { + r.AddAttrs(slog.String("trace_id", tid)) + } + return h.inner.Handle(ctx, r) +} + +func (h handler) WithAttrs(attrs []slog.Attr) slog.Handler { + return handler{inner: h.inner.WithAttrs(attrs)} +} + +// WithGroup re-wraps so enrichment survives logger.WithGroup. +// ponytail: req_id/trace_id are added at the record's top level; the codebase +// opens no logger-level groups, so there is no group-nesting concern to handle +// here. Revisit if slog group usage is introduced. +func (h handler) WithGroup(name string) slog.Handler { + return handler{inner: h.inner.WithGroup(name)} +} diff --git a/Server/logctx/logctx_test.go b/Server/logctx/logctx_test.go new file mode 100644 index 00000000..ac6883b6 --- /dev/null +++ b/Server/logctx/logctx_test.go @@ -0,0 +1,38 @@ +package logctx + +import ( + "bytes" + "context" + "log/slog" + "strings" + "testing" + + "github.com/go-chi/chi/v5/middleware" +) + +// TestHandlerAddsReqID verifies the enriching handler stamps req_id when the +// context carries a chi request ID, and omits it otherwise. (trace_id is only +// populated under -tags otel and is covered by manual verification.) +func TestHandlerAddsReqID(t *testing.T) { + var buf bytes.Buffer + log := slog.New(New(slog.NewTextHandler(&buf, nil))) + + ctx := context.WithValue(context.Background(), middleware.RequestIDKey, "req-abc-123") + log.InfoContext(ctx, "hello") + if !strings.Contains(buf.String(), "req_id=req-abc-123") { + t.Errorf("expected req_id in output, got: %s", buf.String()) + } + + buf.Reset() + log.InfoContext(context.Background(), "plain") + if strings.Contains(buf.String(), "req_id") { + t.Errorf("did not expect req_id without a request ID: %s", buf.String()) + } + + // Enrichment must survive logger.With (WithAttrs re-wrap). + buf.Reset() + log.With("k", "v").InfoContext(ctx, "withattrs") + if !strings.Contains(buf.String(), "req_id=req-abc-123") { + t.Errorf("expected req_id to survive With(): %s", buf.String()) + } +} diff --git a/Server/main.go b/Server/main.go index f55821a0..62084944 100644 --- a/Server/main.go +++ b/Server/main.go @@ -23,6 +23,7 @@ import ( "github.com/owncord/server/auth" "github.com/owncord/server/config" "github.com/owncord/server/db" + "github.com/owncord/server/logctx" "github.com/owncord/server/plugin" "github.com/owncord/server/storage" "github.com/owncord/server/telemetry" @@ -36,12 +37,18 @@ func main() { // Create ring buffer for admin log viewer, then build a multi-handler // that tees log records to both stdout (INFO+) and the ring buffer (DEBUG+). logBuf := admin.NewRingBuffer(2000) - stdoutHandler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo}) + // levelVar controls the stdout handler's threshold. It starts at INFO (the + // zero value) so early-startup logs are captured, then run() raises/lowers + // it once config.yaml / OWNCORD_LOGGING_LEVEL is loaded. + levelVar := new(slog.LevelVar) + stdoutHandler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: levelVar}) multiHandler := admin.NewMultiHandler(stdoutHandler, logBuf, slog.LevelDebug) - log := slog.New(multiHandler) + // logctx enriches records logged with a request/trace context (the + // ...Context slog variants) with req_id and, under -tags otel, trace_id. + log := slog.New(logctx.New(multiHandler)) slog.SetDefault(log) - if err := run(log, logBuf); err != nil { + if err := run(log, logBuf, levelVar); err != nil { _, _ = fmt.Fprintf(os.Stderr, "\n [ERROR] %v\n\n", err) log.Error("server exited with error", "error", err) os.Exit(1) @@ -49,7 +56,7 @@ func main() { } // run is the real entrypoint — separated for testability. -func run(log *slog.Logger, logBuf *admin.RingBuffer) error { +func run(log *slog.Logger, logBuf *admin.RingBuffer, levelVar *slog.LevelVar) error { // bgCtx is a cancellable context shared by all background goroutines // (event persister, event pruner, plugin loader, maintenance loop). // It is cancelled early in the shutdown sequence so in-flight DB @@ -78,6 +85,14 @@ func run(log *slog.Logger, logBuf *admin.RingBuffer) error { return fmt.Errorf("loading config: %w", err) } + // Apply the configured stdout log level. The ring buffer keeps capturing + // DEBUG regardless, so the admin panel's live log view is unaffected. + if lvl, ok := config.ParseLevel(cfg.Logging.Level); ok { + levelVar.Set(lvl) + } else { + log.Warn("unknown logging.level, keeping info", "value", cfg.Logging.Level) + } + // ── 2. Ensure data directory exists ──────────────────────────────────── if mkdirErr := os.MkdirAll(cfg.Server.DataDir, 0o750); mkdirErr != nil { return fmt.Errorf("creating data dir %s: %w", cfg.Server.DataDir, mkdirErr) @@ -366,7 +381,7 @@ func isAddrInUse(err error) bool { } // printBanner writes the startup banner to stderr (so it doesn't mix with -// JSON-structured log output on stdout). +// the structured log output on stdout). func printBanner(cfg *config.Config, ver string, tls bool) { scheme := "http" if tls { diff --git a/Server/service/block.go b/Server/service/block.go index 24c4eef9..dded134b 100644 --- a/Server/service/block.go +++ b/Server/service/block.go @@ -46,7 +46,7 @@ func (s *BlockService) BlockUser(ctx context.Context, blockerID, targetID int64) } if err := s.st.BlockUser(ctx, blockerID, targetID); err != nil { - return fmt.Errorf("%w: failed to block user", ErrInternal) + return fmt.Errorf("%w: failed to block user: %v", ErrInternal, err) } slog.Info("user blocked", "blocker_id", blockerID, "target_id", targetID) @@ -59,7 +59,7 @@ func (s *BlockService) UnblockUser(ctx context.Context, blockerID, targetID int6 return fmt.Errorf("%w: user_id must be positive", ErrBadRequest) } if err := s.st.UnblockUser(ctx, blockerID, targetID); err != nil { - return fmt.Errorf("%w: failed to unblock user", ErrInternal) + return fmt.Errorf("%w: failed to unblock user: %v", ErrInternal, err) } slog.Info("user unblocked", "blocker_id", blockerID, "target_id", targetID) return nil @@ -69,7 +69,7 @@ func (s *BlockService) UnblockUser(ctx context.Context, blockerID, targetID int6 func (s *BlockService) ListBlocked(ctx context.Context, blockerID int64) ([]int64, error) { ids, err := s.st.ListBlockedUsers(ctx, blockerID) if err != nil { - return nil, fmt.Errorf("%w: failed to list blocked users", ErrInternal) + return nil, fmt.Errorf("%w: failed to list blocked users: %v", ErrInternal, err) } if ids == nil { ids = []int64{} diff --git a/Server/service/dm.go b/Server/service/dm.go index 526e48f0..006298f2 100644 --- a/Server/service/dm.go +++ b/Server/service/dm.go @@ -55,7 +55,7 @@ func (s *DMService) CreateDM(ctx context.Context, userID, recipientID int64) (*C blocked, err := s.st.IsEitherBlocked(ctx, userID, recipientID) if err != nil { - return nil, fmt.Errorf("%w: failed to check block status", ErrInternal) + return nil, fmt.Errorf("%w: failed to check block status: %v", ErrInternal, err) } if blocked { return nil, fmt.Errorf("%w: cannot create DM — user is blocked", ErrForbidden) @@ -78,7 +78,7 @@ func (s *DMService) CreateDM(ctx context.Context, userID, recipientID int64) (*C func (s *DMService) ListDMs(ctx context.Context, userID int64) ([]db.DMChannelInfo, error) { dms, err := s.st.GetUserDMChannels(ctx, userID) if err != nil { - return nil, fmt.Errorf("%w: failed to list DMs", ErrInternal) + return nil, fmt.Errorf("%w: failed to list DMs: %v", ErrInternal, err) } return dms, nil } @@ -95,7 +95,7 @@ func (s *DMService) CloseDM(ctx context.Context, userID, channelID int64) error } if err := s.st.CloseDM(ctx, userID, channelID); err != nil { - return fmt.Errorf("%w: failed to close DM", ErrInternal) + return fmt.Errorf("%w: failed to close DM: %v", ErrInternal, err) } slog.Debug("DM closed", "user_id", userID, "channel_id", channelID) diff --git a/Server/service/invite.go b/Server/service/invite.go index 6f453d5d..896ae25b 100644 --- a/Server/service/invite.go +++ b/Server/service/invite.go @@ -50,12 +50,12 @@ func (s *InviteService) CreateInvite(ctx context.Context, createdBy int64, maxUs code, err := s.st.CreateInvite(ctx, createdBy, maxUses, expiresAt) if err != nil { - return nil, fmt.Errorf("%w: failed to create invite", ErrInternal) + return nil, fmt.Errorf("%w: failed to create invite: %v", ErrInternal, err) } invite, err := s.st.GetInvite(ctx, code) if err != nil || invite == nil { - return nil, fmt.Errorf("%w: failed to retrieve invite", ErrInternal) + return nil, fmt.Errorf("%w: failed to retrieve invite: %v", ErrInternal, err) } return invite, nil } @@ -64,7 +64,7 @@ func (s *InviteService) CreateInvite(ctx context.Context, createdBy int64, maxUs func (s *InviteService) ListInvites(ctx context.Context) ([]*db.Invite, error) { invites, err := s.st.ListInvites(ctx) if err != nil { - return nil, fmt.Errorf("%w: failed to list invites", ErrInternal) + return nil, fmt.Errorf("%w: failed to list invites: %v", ErrInternal, err) } return invites, nil } @@ -76,7 +76,7 @@ func (s *InviteService) RevokeInvite(ctx context.Context, code string) error { return fmt.Errorf("%w: invite not found", ErrNotFound) } if err := s.st.RevokeInvite(ctx, code); err != nil { - return fmt.Errorf("%w: failed to revoke invite", ErrInternal) + return fmt.Errorf("%w: failed to revoke invite: %v", ErrInternal, err) } return nil } diff --git a/Server/service/message.go b/Server/service/message.go index 8ee6272c..e2e4a749 100644 --- a/Server/service/message.go +++ b/Server/service/message.go @@ -559,7 +559,7 @@ func (s *MessageService) SearchMessages(ctx context.Context, userID int64, query } results, err := s.st.SearchMessages(ctx, query, channelID, limit) if err != nil { - return nil, fmt.Errorf("%w: search failed", ErrInternal) + return nil, fmt.Errorf("%w: search failed: %v", ErrInternal, err) } return results, nil } @@ -575,7 +575,7 @@ func (s *MessageService) SearchMessages(ctx context.Context, userID int64, query results, err := s.st.SearchMessagesInChannels(ctx, query, accessibleIDs, limit) if err != nil { - return nil, fmt.Errorf("%w: search failed", ErrInternal) + return nil, fmt.Errorf("%w: search failed: %v", ErrInternal, err) } return results, nil } @@ -599,7 +599,7 @@ func (s *MessageService) GetPinnedMessages(ctx context.Context, userID, channelI } msgs, err := s.st.GetPinnedMessages(ctx, channelID, userID) if err != nil { - return nil, fmt.Errorf("%w: failed to fetch pinned messages", ErrInternal) + return nil, fmt.Errorf("%w: failed to fetch pinned messages: %v", ErrInternal, err) } return msgs, nil } @@ -633,12 +633,12 @@ func (s *MessageService) SetMessagePinned(ctx context.Context, userID, channelID func (s *MessageService) GetAccessibleChannelIDs(ctx context.Context, userID int64) ([]int64, error) { channels, err := s.st.ListChannels(ctx) if err != nil { - return nil, fmt.Errorf("%w: failed to list channels", ErrInternal) + return nil, fmt.Errorf("%w: failed to list channels: %v", ErrInternal, err) } role, err := s.perms.GetRoleForUser(ctx, userID) if err != nil || role == nil { - return nil, fmt.Errorf("%w: failed to get role", ErrInternal) + return nil, fmt.Errorf("%w: failed to get role: %v", ErrInternal, err) } var overrides map[int64]db.ChannelOverride @@ -646,7 +646,7 @@ func (s *MessageService) GetAccessibleChannelIDs(ctx context.Context, userID int var overrideErr error overrides, overrideErr = s.st.GetAllChannelPermissionsForRole(ctx, role.ID) if overrideErr != nil { - return nil, fmt.Errorf("%w: failed to fetch channel overrides", ErrInternal) + return nil, fmt.Errorf("%w: failed to fetch channel overrides: %v", ErrInternal, overrideErr) } } @@ -693,7 +693,7 @@ func (s *MessageService) checkSendPermission(ctx context.Context, userID, channe if isDM { ok, err := s.st.IsDMParticipant(ctx, userID, channelID) if err != nil { - return fmt.Errorf("%w: failed to check DM participation", ErrInternal) + return fmt.Errorf("%w: failed to check DM participation: %v", ErrInternal, err) } if !ok { return fmt.Errorf("%w: not a participant in this DM", ErrForbidden) @@ -702,7 +702,7 @@ func (s *MessageService) checkSendPermission(ctx context.Context, userID, channe if err == nil && recipient != nil { blocked, blkErr := s.st.IsEitherBlocked(ctx, userID, recipient.ID) if blkErr != nil { - return fmt.Errorf("%w: failed to check block status", ErrInternal) + return fmt.Errorf("%w: failed to check block status: %v", ErrInternal, blkErr) } if blocked { return fmt.Errorf("%w: cannot send messages — user is blocked", ErrBlocked) diff --git a/Server/service/moderation.go b/Server/service/moderation.go index 03198e93..b4545f52 100644 --- a/Server/service/moderation.go +++ b/Server/service/moderation.go @@ -96,7 +96,7 @@ func (s *ModerationService) BanUser(ctx context.Context, actorID, targetID int64 } if err := s.st.BanUser(ctx, targetID, reason, expires); err != nil { - return fmt.Errorf("%w: failed to ban user", ErrInternal) + return fmt.Errorf("%w: failed to ban user: %v", ErrInternal, err) } // Audit rows must survive a request canceled after the ban committed. @@ -125,7 +125,7 @@ func (s *ModerationService) UnbanUser(ctx context.Context, actorID, targetID int } if err := s.st.UnbanUser(ctx, targetID); err != nil { - return fmt.Errorf("%w: failed to unban user", ErrInternal) + return fmt.Errorf("%w: failed to unban user: %v", ErrInternal, err) } // Audit rows must survive a request canceled after the unban committed. diff --git a/Server/service/user.go b/Server/service/user.go index 1f41e616..acd3a207 100644 --- a/Server/service/user.go +++ b/Server/service/user.go @@ -38,11 +38,11 @@ func (s *UserService) UpdateProfile(ctx context.Context, userID int64, username if db.IsUniqueConstraintError(err) { return nil, fmt.Errorf("%w: username is already taken", ErrConflict) } - return nil, fmt.Errorf("%w: failed to update profile", ErrInternal) + return nil, fmt.Errorf("%w: failed to update profile: %v", ErrInternal, err) } user, err := s.st.GetUserByID(ctx, userID) if err != nil { - return nil, fmt.Errorf("%w: failed to fetch updated user", ErrInternal) + return nil, fmt.Errorf("%w: failed to fetch updated user: %v", ErrInternal, err) } // Audit rows must survive a request canceled after the write committed. db.WriteAudit(context.WithoutCancel(ctx), s.st, userID, "profile_update", "user", userID, @@ -82,7 +82,7 @@ type ChangePasswordResult struct { // ChangePassword updates the user's password and revokes other sessions. func (s *UserService) ChangePassword(ctx context.Context, userID int64, newPasswordHash string, keepSessionID int64) (ChangePasswordResult, error) { if err := s.st.UpdateUserPassword(ctx, userID, newPasswordHash); err != nil { - return ChangePasswordResult{}, fmt.Errorf("%w: failed to update password", ErrInternal) + return ChangePasswordResult{}, fmt.Errorf("%w: failed to update password: %v", ErrInternal, err) } // The password is committed from here on: every path below reports @@ -114,7 +114,7 @@ func (s *UserService) ChangePassword(ctx context.Context, userID int64, newPassw func (s *UserService) ListSessions(ctx context.Context, userID int64) ([]db.Session, error) { sessions, err := s.st.ListUserSessions(ctx, userID) if err != nil { - return nil, fmt.Errorf("%w: failed to list sessions", ErrInternal) + return nil, fmt.Errorf("%w: failed to list sessions: %v", ErrInternal, err) } return sessions, nil } @@ -125,7 +125,7 @@ func (s *UserService) RevokeSession(ctx context.Context, userID, sessionID int64 if errors.Is(err, db.ErrNotFound) { return fmt.Errorf("%w: session not found", ErrNotFound) } - return fmt.Errorf("%w: failed to revoke session", ErrInternal) + return fmt.Errorf("%w: failed to revoke session: %v", ErrInternal, err) } // Audit rows must survive a request canceled after the delete committed. db.WriteAudit(context.WithoutCancel(ctx), s.st, userID, "session_revoke", "session", sessionID, "session revoked") diff --git a/Server/stackutil/stackutil.go b/Server/stackutil/stackutil.go new file mode 100644 index 00000000..deadf7ec --- /dev/null +++ b/Server/stackutil/stackutil.go @@ -0,0 +1,45 @@ +// Package stackutil captures goroutine stack traces for panic logging in a +// form that is safe to persist and stream. +// +// runtime.Stack embeds function argument values as raw hex words. For +// arguments passed by value (e.g. a [32]byte room key or a [16]byte IV) that +// exposes the actual bytes — secret material such as E2EE keys, session +// tokens, or passwords that flowed through a panicking call. Because the +// server tees panic logs into the admin ring buffer and streams them over SSE, +// a single panic on a crypto or auth path could leak keys to any admin viewer. +// +// Capture avoids this by using runtime.Callers + CallersFrames, which yields +// only function names and source locations — never argument data. +package stackutil + +import ( + "runtime" + "strconv" + "strings" +) + +// Capture returns a compact, argument-free stack trace for the calling +// goroutine: one "func" line followed by a "\tfile:line" line per frame. It is +// safe to log even when the panicking function held sensitive arguments. +func Capture() string { + pcs := make([]uintptr, 64) + n := runtime.Callers(2, pcs) // skip runtime.Callers and Capture itself + if n == 0 { + return "" + } + frames := runtime.CallersFrames(pcs[:n]) + var b strings.Builder + for { + f, more := frames.Next() + b.WriteString(f.Function) + b.WriteString("\n\t") + b.WriteString(f.File) + b.WriteByte(':') + b.WriteString(strconv.Itoa(f.Line)) + b.WriteByte('\n') + if !more { + break + } + } + return b.String() +} diff --git a/Server/stackutil/stackutil_test.go b/Server/stackutil/stackutil_test.go new file mode 100644 index 00000000..1451dea9 --- /dev/null +++ b/Server/stackutil/stackutil_test.go @@ -0,0 +1,48 @@ +package stackutil + +import ( + "strings" + "testing" +) + +//go:noinline +func panicWithSecretArgs(key [32]byte, token string) { + // key is passed by value, so runtime.Stack would render its bytes as hex. + _ = key + _ = token + panic("boom") +} + +// TestCaptureOmitsArguments is the security guard: Capture must never emit +// argument values. runtime.Stack renders by-value args as hex words ("0x..."), +// so asserting the output is free of hex verifies no argument bytes leaked, +// while still carrying the panicking function name and source location. +func TestCaptureOmitsArguments(t *testing.T) { + var key [32]byte + for i := range key { + key[i] = 0xAB + } + + var stack string + func() { + defer func() { + if recover() != nil { + stack = Capture() + } + }() + panicWithSecretArgs(key, "super-secret-token") + }() + + if stack == "" { + t.Fatal("expected a captured stack after recover") + } + if strings.Contains(stack, "0x") { + t.Errorf("captured stack contains hex argument words (possible secret leak):\n%s", stack) + } + if !strings.Contains(stack, "panicWithSecretArgs") { + t.Errorf("captured stack missing the panicking function name:\n%s", stack) + } + if !strings.Contains(stack, "stackutil_test.go:") { + t.Errorf("captured stack missing source location:\n%s", stack) + } +} diff --git a/Server/telemetry/telemetry_default.go b/Server/telemetry/telemetry_default.go index 78e671ce..5f1d8c64 100644 --- a/Server/telemetry/telemetry_default.go +++ b/Server/telemetry/telemetry_default.go @@ -20,3 +20,7 @@ func Init(_ context.Context, cfg config.TelemetryConfig) (ShutdownFunc, error) { SetGlobal(noopProvider{}) return func(context.Context) error { return nil }, nil } + +// TraceIDFromContext returns the active trace ID as a hex string, or "" when no +// span is active. The default build has no tracing, so it always returns "". +func TraceIDFromContext(_ context.Context) string { return "" } diff --git a/Server/telemetry/telemetry_otel.go b/Server/telemetry/telemetry_otel.go index fd9c3506..7fd437c7 100644 --- a/Server/telemetry/telemetry_otel.go +++ b/Server/telemetry/telemetry_otel.go @@ -178,6 +178,16 @@ func (p *otelProvider) HTTPMiddleware(next http.Handler) http.Handler { // exporter registry. func (p *otelProvider) PrometheusHandler() http.Handler { return p.promHandler } +// TraceIDFromContext returns the active trace ID as a hex string, or "" when no +// span is recording in ctx. Used to stamp log records with trace_id so logs +// correlate with traces. +func TraceIDFromContext(ctx context.Context) string { + if sc := trace.SpanContextFromContext(ctx); sc.HasTraceID() { + return sc.TraceID().String() + } + return "" +} + // ── Tracer / Span adapters ───────────────────────────────────────────────── type otelTracer struct{ inner trace.Tracer } diff --git a/Server/ws/hub.go b/Server/ws/hub.go index 5a712752..749ae46b 100644 --- a/Server/ws/hub.go +++ b/Server/ws/hub.go @@ -6,7 +6,6 @@ import ( "context" "fmt" "log/slog" - "runtime" "sync" "sync/atomic" "time" @@ -16,6 +15,7 @@ import ( "github.com/owncord/server/permissions" "github.com/owncord/server/plugin" "github.com/owncord/server/service" + "github.com/owncord/server/stackutil" "github.com/owncord/server/syncutil" ) @@ -276,12 +276,10 @@ func (h *Hub) Run() { } panicCount++ - buf := make([]byte, 4096) - n := runtime.Stack(buf, false) slog.Error("hub: panic recovered", "panic", r, "panic_count", panicCount, - "stack", string(buf[:n])) + "stack", stackutil.Capture()) if panicCount >= 3 { slog.Error("hub: too many panics in 60s, stopping") diff --git a/Server/ws/registry.go b/Server/ws/registry.go index 7a55c3aa..ee97bd46 100644 --- a/Server/ws/registry.go +++ b/Server/ws/registry.go @@ -4,7 +4,8 @@ import ( "context" "fmt" "log/slog" - "runtime" + + "github.com/owncord/server/stackutil" ) // handlerV2Entry pairs a V2 handler with its domain-specific dependency struct. @@ -47,15 +48,13 @@ func (r *HandlerRegistry) DispatchV2(ctx context.Context, cmd Command, info Clie } defer func() { if rec := recover(); rec != nil { - buf := make([]byte, 4096) - n := runtime.Stack(buf, false) - // TODO: stack trace may contain sensitive function arguments - // (e.g. encrypted keys). Consider scrubbing or limiting frames. + // stackutil.Capture omits argument values, which for E2EE + // handlers can include encrypted key material. slog.Error("DispatchV2 panic recovered", "type", cmd.Type(), "user_id", info.UserID, "panic", rec, - "stack", string(buf[:n]), + "stack", stackutil.Capture(), ) result = Result{Error: ClientError{Code: ErrCodeInternal, Message: "internal error"}} ok = true diff --git a/Server/ws/serve.go b/Server/ws/serve.go index 9e2336e4..089cbfcf 100644 --- a/Server/ws/serve.go +++ b/Server/ws/serve.go @@ -503,6 +503,11 @@ func authenticateConn(parent context.Context, conn *websocket.Conn, database *db sess, err := database.GetSessionByTokenHash(ctx, hash) if err != nil || sess == nil { _ = conn.Write(ctx, websocket.MessageText, buildAuthError("invalid token")) + if err != nil { + // DB outage, not a bad token — carry the cause so the caller's log + // distinguishes it from an ordinary invalid-token rejection. + return nil, "", 0, fmt.Errorf("auth: session lookup failed: %w", err) + } return nil, "", 0, fmt.Errorf("auth: invalid session") } @@ -514,6 +519,9 @@ func authenticateConn(parent context.Context, conn *websocket.Conn, database *db user, err := database.GetUserByID(ctx, sess.UserID) if err != nil || user == nil { _ = conn.Write(ctx, websocket.MessageText, buildAuthError("user not found")) + if err != nil { + return nil, "", 0, fmt.Errorf("auth: user lookup failed: %w", err) + } return nil, "", 0, fmt.Errorf("auth: user not found") } diff --git a/Server/ws/voice_e2ee.go b/Server/ws/voice_e2ee.go index 66737a5a..c3ad5956 100644 --- a/Server/ws/voice_e2ee.go +++ b/Server/ws/voice_e2ee.go @@ -4,6 +4,7 @@ import ( "context" "encoding/base64" "fmt" + "log/slog" "time" ) @@ -226,10 +227,18 @@ func (h *Hub) sendToUserIfInVoiceChannel(voiceChannelID, targetUserID int64, msg target, ok := h.clients[targetUserID] if !ok { - return // target not connected — silently drop + // Undeliverable key offer can leave the peer unable to decrypt — the + // payload is dropped, but log (IDs only, never the encrypted key) so + // the failure is diagnosable rather than silent. + slog.Debug("e2ee: key offer dropped, target not connected", + "target_user_id", targetUserID, "voice_channel_id", voiceChannelID) + return } if target.getVoiceChID() != voiceChannelID { - return // target not in expected voice channel — silently drop + slog.Debug("e2ee: key offer dropped, target not in expected voice channel", + "target_user_id", targetUserID, "voice_channel_id", voiceChannelID, + "target_voice_channel_id", target.getVoiceChID()) + return } target.sendMsg(msg) }