mirror of
https://github.com/J3vb/OwnCord.git
synced 2026-09-03 03:50:00 +03:00
Merge pull request #1235 from J3vb/feat/logging-hardening
feat: logging & error-visibility hardening (server + client)
This commit is contained in:
Generated
+61
-49
@@ -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",
|
||||
|
||||
@@ -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 }
|
||||
|
||||
|
||||
@@ -47,6 +47,13 @@ pub fn get_settings(app: tauri::AppHandle) -> Result<Value, String> {
|
||||
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 {
|
||||
|
||||
@@ -107,12 +107,21 @@ pub async fn start_http_proxy<R: Runtime>(
|
||||
.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:{} → {}",
|
||||
|
||||
@@ -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(())
|
||||
})
|
||||
|
||||
@@ -134,7 +134,15 @@ pub async fn start_livekit_proxy<R: Runtime>(
|
||||
|
||||
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);
|
||||
|
||||
|
||||
@@ -307,13 +307,17 @@ pub fn accept_cert_fingerprint<R: Runtime>(
|
||||
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<R: Runtime>(
|
||||
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(())
|
||||
}
|
||||
|
||||
@@ -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);
|
||||
}
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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 {
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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();
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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"})
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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})
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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
|
||||
}
|
||||
|
||||
|
||||
+40
-1
@@ -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 {
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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),
|
||||
)
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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),
|
||||
)
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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)}
|
||||
}
|
||||
@@ -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())
|
||||
}
|
||||
}
|
||||
+20
-5
@@ -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 {
|
||||
|
||||
@@ -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{}
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -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
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -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")
|
||||
|
||||
@@ -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()
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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 "" }
|
||||
|
||||
@@ -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 }
|
||||
|
||||
+2
-4
@@ -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")
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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")
|
||||
}
|
||||
|
||||
|
||||
+11
-2
@@ -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)
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user