diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index e345c6e..2aaabd3 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -994,6 +994,42 @@ For AI agents and automated tooling, every endpoint includes: - Lints `server/openapi.yaml` with `@stoplight/spectral-cli` - Runs the coverage test suite on every push +### 7.5 Real-Time Debug Log Streaming Subsystem + +sofarr provides a togglable, real-time log capturing and streaming engine allowing developer-administrators to view server standard output stream activity and browser console log activity for easy debugging in production. + +#### Architecture + +```mermaid +flowchart LR + subgraph Browser (SPA) + console["console.log/warn/error"] --> queue["logQueue (batched)"] + queue --> |POST /api/debug/client-logs| ingestionRoute["POST router handler"] + end + + subgraph Node.js (Server) + stdout["process.stdout.write"] --> capture["processStreamData()"] + stderr["process.stderr.write"] --> capture + capture --> |stripAnsi()| serverBuffer["logBuffer (rolling 1000 lines)"] + capture --> |emit('server-log')| serverSse["GET /api/debug/server-logs (SSE)"] + + ingestionRoute --> clientBuffer["clientLogBuffer (rolling 1000 lines)"] + ingestionRoute --> |emit('client-log')| clientSse["GET /api/debug/client-logs (SSE)"] + end +``` + +#### In-Process Interceptor (Stdout & Stderr) +To guarantee 100% logging completeness without requiring complex and insecure external Docker daemon sockets, the server hooks directly into standard output stream writers `process.stdout.write` and `process.stderr.write` during the process boot cycle. +- Custom accumulators process streams, strip ANSI terminal colors (colors are stripped using a standard regex matching all terminal escape codes), and split incoming chunks into structured lines. +- Historical lines are appended to a rolling in-memory array `logBuffer` capped at 1,000 entries. +- Real-time logging events are broadcasted via a central `EventEmitter` allowing connected SSE stream clients to receive updates instantly. + +#### Client Console Log Capture +To assist developers in troubleshooting client-side runtime errors without access to developer consoles (e.g., in embedded WebViews, smart TVs, or custom mobile browser instances), the SPA implements an automatic logging interceptor. +- If `/api/debug/status` indicates log streaming is active, the bootstrap process replaces global `console.log`, `console.warn`, and `console.error` methods. +- Logs are added to an in-memory queue and flushed in batches using a stateless `POST /api/debug/client-logs` request every 2,000ms (or when the queue size reaches 20 items) to prevent browser thread blocking. +- A synchronous cleanup check is registered via standard `beforeunload` to flush any remaining logs using `navigator.sendBeacon()` or `keepalive: true` fetch on page refresh or navigate. + --- ## 8. Directory Structure @@ -1203,6 +1239,18 @@ Each instance receives an `id` derived from `name` (or index if unnamed), used a | **Authorisation matrix** | Regular users see only their own downloads. Admins can view all users, see paths and *arr links, and blocklist any download. Non-admins can only blocklist when import issues exist or (for qBittorrent) the torrent is >1 h old with <100% availability. | | **Container security** | Docker image runs as the non-root `node` user (UID 1000). `/app/data` is owned by `node`. | +### 10.4 Debug Log Streaming Security + +Access to the debug log stream endpoints (`/api/debug/server-logs` and `/api/debug/client-logs`) is secured via a strict multi-layered policy: + +| Layer | Mechanism | +|-------|-----------| +| **Feature lock toggle** | Strictly disabled by default; only enableable when environment variable `ENABLE_LOG_STREAM=true` is set. | +| **Subnet filtering** | If environment variable `LOG_ALLOW_SUBNETS` is configured (using standard comma-separated CIDR notation), incoming client IPs (`req.ip`) are parsed and validated via the `ipaddr.js` library. Unmatched subnets receive a `403 Forbidden` response immediately. | +| **Fast-path webhook bypass** | A valid webhook secret bypasses the active Emby authentication layer when provided on the `X-Webhook-Secret` header. | +| **Active Emby session** | Validates that an active `emby_user` session cookie is present and that the authenticated Emby user is an administrator. | +| **Emby basic auth fallback** | Allows Basic Authentication headers by performing an on-demand asynchronous credentials check against Emby's `/Users/authenticatebyname` and `/Users/{id}` endpoints to assert active policy administrator status. | + --- ## 11. Technology Stack diff --git a/README.md b/README.md index c464630..59cf0c2 100644 --- a/README.md +++ b/README.md @@ -227,6 +227,10 @@ PORT=3001 # Server port LOG_LEVEL=info # Logging: debug, info, warn, error, silent POLL_INTERVAL=5000 # Background polling interval in ms (default: 5000) # Set to 0 or "off" to disable (on-demand mode) + +# Debug Log Streaming Subsystem +ENABLE_LOG_STREAM=false # Set to true to enable logs debugging routes +LOG_ALLOW_SUBNETS=127.0.0.1/32 # Comma-separated allowed CIDR blocks (e.g. 127.0.0.1/32,192.168.1.0/24) ``` ### Webhooks & Smart Polling @@ -441,6 +445,12 @@ The proxy routes (`/api/sonarr/**`, `/api/radarr/**`, `/api/sabnzbd/**`, `/api/e ### History - `GET /api/history/recent` — Recently completed downloads from Sonarr/Radarr history +### Debug Logs (requires ENABLE_LOG_STREAM=true) +- `GET /api/debug/status` — Get runtime log stream configurations (public) +- `GET /api/debug/server-logs` — **SSE stream**: push server `stdout`/`stderr` in real-time (requires auth & subnet check) +- `GET /api/debug/client-logs` — **SSE stream**: push ingested frontend console logs in real-time (requires auth & subnet check) +- `POST /api/debug/client-logs` — Ingest batched frontend console logs (requires auth & subnet check) + ### Webhook Receiver (no user auth — protected by `X-Sofarr-Webhook-Secret`) - `POST /api/webhook/sonarr` — receive Sonarr webhook events - `POST /api/webhook/radarr` — receive Radarr webhook events diff --git a/client/src/main.js b/client/src/main.js index 468f505..402656d 100644 --- a/client/src/main.js +++ b/client/src/main.js @@ -11,8 +11,12 @@ import { initThemeSwitcher } from './ui/theme.js'; import { initTabs, goHome } from './ui/tabs.js'; import { handleShowAllToggle } from './sse.js'; import { loadAppVersion } from './api.js'; +import { initClientLogCapture } from './utils/clientLogCapture.js'; document.addEventListener('DOMContentLoaded', () => { + // Initialize client console log capturing early + initClientLogCapture(); + // Login form const loginForm = document.getElementById('login-form'); if (loginForm) { diff --git a/client/src/utils/clientLogCapture.js b/client/src/utils/clientLogCapture.js new file mode 100644 index 0000000..cb21d77 --- /dev/null +++ b/client/src/utils/clientLogCapture.js @@ -0,0 +1,137 @@ +// Copyright (c) 2026 Gordon Bolton. MIT License. + +const logQueue = []; +const MAX_QUEUE_SIZE = 20; +const FLUSH_INTERVAL_MS = 2000; + +// Original console functions +const originalLog = console.log; +const originalWarn = console.warn; +const originalError = console.error; + +let isSending = false; +let isInitialized = false; +let flushInterval = null; + +function formatArgs(args) { + return args.map(arg => { + if (arg === null) return 'null'; + if (arg === undefined) return 'undefined'; + if (arg instanceof Error) { + return `${arg.name}: ${arg.message}\n${arg.stack || ''}`; + } + if (typeof arg === 'object') { + try { + return JSON.stringify(arg); + } catch { + return String(arg); + } + } + return String(arg); + }).join(' '); +} + +function enqueue(level, args) { + const formattedMsg = formatArgs(args); + + // Still write to the developer console! + if (level === 'info') originalLog.apply(console, args); + else if (level === 'warn') originalWarn.apply(console, args); + else if (level === 'error') originalError.apply(console, args); + + // Guard against infinite loop during logs dispatching + if (isSending) return; + + logQueue.push({ + timestamp: new Date().toISOString(), + level, + message: formattedMsg + }); + + // Flush immediately if queue is full + if (logQueue.length >= MAX_QUEUE_SIZE) { + flushQueue(); + } +} + +async function flushQueue() { + if (logQueue.length === 0 || isSending) return; + + isSending = true; + const batch = [...logQueue]; + logQueue.length = 0; + + try { + const response = await fetch('/api/debug/client-logs', { + method: 'POST', + headers: { + 'Content-Type': 'application/json' + }, + body: JSON.stringify(batch), + // keepalive allows request to survive page unload + keepalive: true + }); + + if (!response.ok) { + originalError.call(console, '[clientLogCapture] Ingestion server returned error status:', response.status); + } + } catch (err) { + originalError.call(console, '[clientLogCapture] Ingestion post request failed:', err.message); + } finally { + isSending = false; + } +} + +// Perform a fast/unblocked payload flush using sendBeacon on page unload +function flushOnUnload() { + if (logQueue.length === 0) return; + + const batch = [...logQueue]; + logQueue.length = 0; + + try { + const blob = new Blob([JSON.stringify(batch)], { type: 'application/json' }); + navigator.sendBeacon('/api/debug/client-logs', blob); + } catch (err) { + // sendBeacon failure, fallback to synchronous fetch with keepalive if available + try { + fetch('/api/debug/client-logs', { + method: 'POST', + headers: { 'Content-Type': 'application/json' }, + body: JSON.stringify(batch), + keepalive: true + }); + } catch { + // Ignore + } + } +} + +export async function initClientLogCapture() { + if (isInitialized) return; + + try { + // 1. Check if the server toggle for logging is active + const response = await fetch('/api/debug/status'); + if (!response.ok) return; + + const data = await response.json(); + if (data && data.enabled === true) { + // 2. Override global console methods + console.log = (...args) => enqueue('info', args); + console.warn = (...args) => enqueue('warn', args); + console.error = (...args) => enqueue('error', args); + + // 3. Set interval for batch updates + flushInterval = setInterval(flushQueue, FLUSH_INTERVAL_MS); + + // 4. Setup beforeunload listener for clean flushing + window.addEventListener('beforeunload', flushOnUnload); + + isInitialized = true; + console.log('[clientLogCapture] Browser console logging interceptor initialized successfully.'); + } + } catch (err) { + originalError.call(console, '[clientLogCapture] Check failed to start interceptor:', err.message); + } +} diff --git a/server/app.js b/server/app.js index d625c02..a98fb7c 100644 --- a/server/app.js +++ b/server/app.js @@ -26,6 +26,7 @@ const historyRoutes = require('./routes/history'); const authRoutes = require('./routes/auth'); const webhookRoutes = require('./routes/webhook'); const ombiRoutes = require('./routes/ombi'); +const debugRoutes = require('./routes/debug'); const verifyCsrf = require('./middleware/verifyCsrf'); function createApp({ skipRateLimits = false } = {}) { @@ -213,6 +214,7 @@ function createApp({ skipRateLimits = false } = {}) { app.use('/api', apiLimiter); app.use('/api/auth', authRoutes); app.use('/api/webhook', webhookRoutes); + app.use('/api/debug', debugRoutes); // CSRF protection for all state-changing API requests below app.use('/api', verifyCsrf); diff --git a/server/index.js b/server/index.js index f4536ef..4c3d84b 100644 --- a/server/index.js +++ b/server/index.js @@ -13,6 +13,8 @@ const swaggerJsdoc = require('swagger-jsdoc'); const YAML = require('yamljs'); require('dotenv').config(); require('./utils/loadSecrets')(); +const logCapture = require('./utils/logCapture'); +logCapture.init(); const { version } = require('../package.json'); // Setup logging with levels @@ -90,6 +92,7 @@ const historyRoutes = require('./routes/history'); const authRoutes = require('./routes/auth'); const webhookRoutes = require('./routes/webhook'); const ombiRoutes = require('./routes/ombi'); +const debugRoutes = require('./routes/debug'); const verifyCsrf = require('./middleware/verifyCsrf'); const { startPoller, POLL_INTERVAL, POLLING_ENABLED } = require('./utils/poller'); const { validateInstanceUrl } = require('./utils/config'); @@ -367,6 +370,7 @@ function serveIndex(req, res) { app.use('/api', apiLimiter); app.use('/api/auth', authRoutes); app.use('/api/webhook', webhookRoutes); +app.use('/api/debug', debugRoutes); // All routes below this point require CSRF validation on mutating methods app.use('/api', verifyCsrf); diff --git a/server/middleware/logStreamAuth.js b/server/middleware/logStreamAuth.js new file mode 100644 index 0000000..b399bd3 --- /dev/null +++ b/server/middleware/logStreamAuth.js @@ -0,0 +1,156 @@ +// Copyright (c) 2026 Gordon Bolton. MIT License. +const axios = require('axios'); +const crypto = require('crypto'); +const ipaddr = require('ipaddr.js'); + +function getEmbyUrl() { + return process.env.EMBY_URL; +} + +function isIpAllowed(clientIp, allowedSubnetsStr) { + if (!allowedSubnetsStr) return true; + try { + const clientIpParsed = ipaddr.parse(clientIp); + const subnets = allowedSubnetsStr.split(',').map(s => s.trim()).filter(Boolean); + + for (const subnet of subnets) { + let rangeStr = subnet; + let bits = null; + if (subnet.includes('/')) { + const parts = subnet.split('/'); + rangeStr = parts[0]; + bits = parseInt(parts[1], 10); + } + + const rangeIpParsed = ipaddr.parse(rangeStr); + + if (bits === null) { + // Exact IP match + if (clientIpParsed.toString() === rangeIpParsed.toString()) { + return true; + } + // Handle IPv4 mapped IPv6 address case + if (clientIpParsed.kind() === 'ipv6' && clientIpParsed.isIPv4MappedAddress() && rangeIpParsed.kind() === 'ipv4') { + if (clientIpParsed.toIPv4Address().toString() === rangeIpParsed.toString()) { + return true; + } + } + continue; + } + + // Match with subnet bits + if (clientIpParsed.kind() === rangeIpParsed.kind()) { + if (clientIpParsed.match(rangeIpParsed, bits)) { + return true; + } + } else if (clientIpParsed.kind() === 'ipv6' && clientIpParsed.isIPv4MappedAddress() && rangeIpParsed.kind() === 'ipv4') { + // Handle IPv4 mapped IPv6 address case matching IPv4 range + if (clientIpParsed.toIPv4Address().match(rangeIpParsed, bits)) { + return true; + } + } + } + } catch (err) { + console.error(`[logStreamAuth] IP parsing error for IP ${clientIp}:`, err.message); + } + return false; +} + +async function logStreamAuth(req, res, next) { + // 1. Subnet IP Filtering (First Priority) + const allowedSubnets = process.env.LOG_ALLOW_SUBNETS; + if (allowedSubnets && !isIpAllowed(req.ip, allowedSubnets)) { + console.warn(`[logStreamAuth] Access denied from unauthorized IP: ${req.ip}`); + return res.status(403).json({ error: `Access denied from IP: ${req.ip}` }); + } + + // 2. Webhook Secret Bypass (High Priority) + const secretHeader = req.headers['x-webhook-secret']; + const configuredSecret = process.env.SOFARR_WEBHOOK_SECRET; + if (configuredSecret && secretHeader === configuredSecret) { + return next(); + } + + // 3. Session Cookie + const signed = !!process.env.COOKIE_SECRET; + const rawCookie = signed ? req.signedCookies.emby_user : req.cookies.emby_user; + if (rawCookie && rawCookie !== false) { + try { + const u = JSON.parse(rawCookie); + if (u && typeof u.id === 'string' && u.id && u.isAdmin === true) { + req.user = u; + return next(); + } + } catch { + // Ignore JSON parse errors, fallback to basic auth + } + } + + // 4. Basic Authentication Fallback + const authHeader = req.headers.authorization; + if (authHeader && authHeader.startsWith('Basic ')) { + try { + const credentialsBase64 = authHeader.substring(6); + const credentialsStr = Buffer.from(credentialsBase64, 'base64').toString('utf8'); + const colonIdx = credentialsStr.indexOf(':'); + + if (colonIdx !== -1) { + const username = credentialsStr.substring(0, colonIdx).trim(); + const password = credentialsStr.substring(colonIdx + 1); + + if (username && password) { + const embyUrl = getEmbyUrl(); + if (!embyUrl) { + console.error('[logStreamAuth] Emby auth fallback failed: EMBY_URL is not configured'); + res.setHeader('WWW-Authenticate', 'Basic realm="sofarr log stream debug"'); + return res.status(401).json({ error: 'Authentication service unavailable' }); + } + + // Authenticate with Emby using stable DeviceId derived from username + const stableDeviceId = 'sofarr-' + crypto.createHash('sha256').update(username.toLowerCase()).digest('hex').slice(0, 16); + + console.log(`[logStreamAuth] Attempting Basic Auth login for: ${username}`); + const authResponse = await axios.post(`${embyUrl}/Users/authenticatebyname`, { + Username: username, + Pw: password + }, { + headers: { + 'X-Emby-Authorization': `MediaBrowser Client="sofarr", Device="sofarr", DeviceId="${stableDeviceId}", Version="1.0.0"` + }, + timeout: 5000 + }); + + const authData = authResponse.data; + const userId = authData.User.Id || authData.User.id; + + // Fetch detailed profile to verify administrator status + const userResponse = await axios.get(`${embyUrl}/Users/${userId}`, { + headers: { + 'X-MediaBrowser-Token': authData.AccessToken + }, + timeout: 5000 + }); + + const user = userResponse.data; + const isAdmin = !!(user.Policy && user.Policy.IsAdministrator); + + if (isAdmin) { + console.log(`[logStreamAuth] Basic Auth successful for administrator: ${user.Name}`); + req.user = { id: user.Id, name: user.Name, isAdmin: true }; + return next(); + } else { + console.warn(`[logStreamAuth] Basic Auth rejected: user ${user.Name} is not an administrator`); + } + } + } + } catch (err) { + console.error('[logStreamAuth] Emby authentication error:', err.message); + } + } + + // 5. Unauthorized / Access Denied + res.setHeader('WWW-Authenticate', 'Basic realm="sofarr log stream debug"'); + return res.status(401).json({ error: 'Unauthorized' }); +} + +module.exports = logStreamAuth; diff --git a/server/openapi.yaml b/server/openapi.yaml index bdb4f30..30ef42a 100644 --- a/server/openapi.yaml +++ b/server/openapi.yaml @@ -1752,3 +1752,172 @@ paths: application/json: schema: $ref: '#/components/schemas/ErrorResponse' + + /api/debug/status: + get: + tags: [Debug] + summary: Check if log streaming is enabled + description: Returns whether the log streaming feature is enabled at runtime. No authentication required. + security: [] + responses: + '200': + description: Feature status returned successfully + content: + application/json: + schema: + type: object + properties: + enabled: + type: boolean + example: true + + /api/debug/server-logs: + get: + tags: [Debug] + summary: Stream server logs in real-time + description: | + Streams server-side standard output (stdout/stderr) logs via Server-Sent Events (SSE). + + **Security Policies:** + - **Subnet IP Filtering**: IP must match subnet ranges configured in `LOG_ALLOW_SUBNETS` (if set). + - **Bypass Header**: Direct bypass if `X-Webhook-Secret` header matches the configured `SOFARR_WEBHOOK_SECRET`. + - **Session Auth**: Emby session cookie `emby_user` where user is an administrator. + - **Basic Auth Fallback**: `Authorization` header containing credentials of a valid Emby administrator. + security: + - CookieAuth: [] + parameters: + - name: X-Webhook-Secret + in: header + required: false + schema: + type: string + description: Fast-track webhook secret bypass token + responses: + '200': + description: Event stream established + content: + text/event-stream: + schema: + type: string + '401': + description: Unauthorized + content: + application/json: + schema: + $ref: '#/components/schemas/ErrorResponse' + '403': + description: Forbidden (feature disabled or IP not in subnet allowlist) + content: + application/json: + schema: + $ref: '#/components/schemas/ErrorResponse' + + /api/debug/client-logs: + get: + tags: [Debug] + summary: Stream client console logs in real-time + description: | + Streams client-side console logs via Server-Sent Events (SSE). + + **Security Policies:** + - **Subnet IP Filtering**: IP must match subnet ranges configured in `LOG_ALLOW_SUBNETS` (if set). + - **Bypass Header**: Direct bypass if `X-Webhook-Secret` header matches the configured `SOFARR_WEBHOOK_SECRET`. + - **Session Auth**: Emby session cookie `emby_user` where user is an administrator. + - **Basic Auth Fallback**: `Authorization` header containing credentials of a valid Emby administrator. + security: + - CookieAuth: [] + parameters: + - name: X-Webhook-Secret + in: header + required: false + schema: + type: string + description: Fast-track webhook secret bypass token + responses: + '200': + description: Event stream established + content: + text/event-stream: + schema: + type: string + '401': + description: Unauthorized + content: + application/json: + schema: + $ref: '#/components/schemas/ErrorResponse' + '403': + description: Forbidden (feature disabled or IP not in subnet allowlist) + content: + application/json: + schema: + $ref: '#/components/schemas/ErrorResponse' + post: + tags: [Debug] + summary: Ingest client console logs + description: | + Ingests a batch of client-side console logs into the server-side rolling clientLogBuffer. + + **Security Policies:** + - **Subnet IP Filtering**: IP must match subnet ranges configured in `LOG_ALLOW_SUBNETS` (if set). + - **Bypass Header**: Direct bypass if `X-Webhook-Secret` header matches the configured `SOFARR_WEBHOOK_SECRET`. + - **Session Auth**: Emby session cookie `emby_user` where user is an administrator. + - **Basic Auth Fallback**: `Authorization` header containing credentials of a valid Emby administrator. + security: + - CookieAuth: [] + parameters: + - name: X-Webhook-Secret + in: header + required: false + schema: + type: string + description: Fast-track webhook secret bypass token + requestBody: + required: true + content: + application/json: + schema: + type: array + items: + type: object + required: [level, message] + properties: + timestamp: + type: string + format: date-time + level: + type: string + enum: [info, warn, error] + message: + type: string + responses: + '200': + description: Logs ingested successfully + content: + application/json: + schema: + type: object + properties: + success: + type: boolean + count: + type: integer + '400': + description: Invalid JSON body + content: + application/json: + schema: + $ref: '#/components/schemas/ErrorResponse' + '401': + description: Unauthorized + content: + application/json: + schema: + $ref: '#/components/schemas/ErrorResponse' + '403': + description: Forbidden (feature disabled or IP not in subnet allowlist) + content: + application/json: + schema: + $ref: '#/components/schemas/ErrorResponse' + diff --git a/server/routes/debug.js b/server/routes/debug.js new file mode 100644 index 0000000..bf630b3 --- /dev/null +++ b/server/routes/debug.js @@ -0,0 +1,143 @@ +// Copyright (c) 2026 Gordon Bolton. MIT License. +const express = require('express'); +const router = express.Router(); +const logStreamAuth = require('../middleware/logStreamAuth'); +const { + logEmitter, + logBuffer, + clientLogBuffer, + ingestClientLogs +} = require('../utils/logCapture'); + +// Public status check (no auth, no 403 block, returns standard config state) +router.get('/status', (req, res) => { + res.json({ enabled: process.env.ENABLE_LOG_STREAM === 'true' }); +}); + +// Global toggle check +router.use((req, res, next) => { + if (process.env.ENABLE_LOG_STREAM !== 'true') { + return res.status(403).json({ error: 'Log streaming feature is disabled' }); + } + next(); +}); + +// Enforce subnet and authentication validations on all debug routes +router.use(logStreamAuth); + +/** + * GET /api/debug/server-logs + * Exposes a real-time SSE stream of intercepted server stdout/stderr logs. + */ +router.get('/server-logs', (req, res) => { + res.writeHead(200, { + 'Content-Type': 'text/event-stream', + 'Cache-Control': 'no-cache', + 'Connection': 'keep-alive', + 'X-Accel-Buffering': 'no' + }); + + // Send historical server logs buffer first + for (const line of logBuffer) { + res.write(`data: ${line}\n\n`); + } + + // Gracefully close for integration testing + if (req.query.testClose === 'true') { + res.end(); + return; + } + + const sendLog = (line) => { + try { + res.write(`data: ${line}\n\n`); + } catch (err) { + console.error('[debugRoutes] Error sending server log line:', err.message); + } + }; + + logEmitter.on('server-log', sendLog); + + // 25s heartbeat comment to prevent proxy timeouts + const heartbeat = setInterval(() => { + try { + res.write(': heartbeat\n\n'); + } catch { + // Ignore + } + }, 25000); + + req.on('close', () => { + clearInterval(heartbeat); + logEmitter.off('server-log', sendLog); + }); +}); + +/** + * GET /api/debug/client-logs + * Exposes a real-time SSE stream of ingested client-side console logs. + */ +router.get('/client-logs', (req, res) => { + res.writeHead(200, { + 'Content-Type': 'text/event-stream', + 'Cache-Control': 'no-cache', + 'Connection': 'keep-alive', + 'X-Accel-Buffering': 'no' + }); + + // Send historical client logs buffer first + for (const line of clientLogBuffer) { + res.write(`data: ${line}\n\n`); + } + + // Gracefully close for integration testing + if (req.query.testClose === 'true') { + res.end(); + return; + } + + const sendClientLog = (line) => { + try { + res.write(`data: ${line}\n\n`); + } catch (err) { + console.error('[debugRoutes] Error sending client log line:', err.message); + } + }; + + logEmitter.on('client-log', sendClientLog); + + // 25s heartbeat comment to prevent proxy timeouts + const heartbeat = setInterval(() => { + try { + res.write(': heartbeat\n\n'); + } catch { + // Ignore + } + }, 25000); + + req.on('close', () => { + clearInterval(heartbeat); + logEmitter.off('client-log', sendClientLog); + }); +}); + +/** + * POST /api/debug/client-logs + * Receives batches of frontend console logs to store in buffer and emit. + */ +router.post('/client-logs', (req, res) => { + const logs = req.body; + if (!Array.isArray(logs)) { + return res.status(400).json({ error: 'Body must be a JSON array of log entries' }); + } + + try { + ingestClientLogs(logs); + return res.status(200).json({ success: true, count: logs.length }); + } catch (err) { + console.error('[debugRoutes] Ingestion failed:', err.message); + return res.status(500).json({ error: 'Internal server error during ingestion' }); + } +}); + +module.exports = router; diff --git a/server/utils/logCapture.js b/server/utils/logCapture.js new file mode 100644 index 0000000..8704b2a --- /dev/null +++ b/server/utils/logCapture.js @@ -0,0 +1,131 @@ +// Copyright (c) 2026 Gordon Bolton. MIT License. +const EventEmitter = require('events'); + +class LogEmitter extends EventEmitter {} +const logEmitter = new LogEmitter(); + +const logBuffer = []; +const clientLogBuffer = []; +const MAX_BUFFER_SIZE = 1000; + +// ANSI escape code regular expression for stripping terminal colors +const ansiRegex = /[\u001b\u009b][[()#;?]*(?:[0-9]{1,4}(?:;[0-9]{0,4})*)?[0-9A-ORZcf-nqry=><]/g; + +function stripAnsi(str) { + return typeof str === 'string' ? str.replace(ansiRegex, '') : str; +} + +// Keep track of original stdout/stderr write functions +const originalStdoutWrite = process.stdout.write; +const originalStderrWrite = process.stderr.write; + +// Buffer to accumulate partial lines from stdout and stderr +let stdoutLineBuffer = ''; +let stderrLineBuffer = ''; + +function processStreamData(data, encoding, callback, streamName, lineAccumulator) { + let str = ''; + if (Buffer.isBuffer(data)) { + str = data.toString(encoding || 'utf8'); + } else if (typeof data === 'string') { + str = data; + } + + // Delegate writing to the original stream first + callback.call(this, data, encoding); + + // Append new data to the accumulator + const accumulated = lineAccumulator.buffer + str; + const lines = accumulated.split(/\r?\n/); + + // The last element is either empty (if str ended with \n) or a partial line + lineAccumulator.buffer = lines.pop(); + + for (const line of lines) { + const cleanLine = stripAnsi(line); + if (!cleanLine) continue; + + // Prepend timestamp if not present (format: [ISO] Message) + const timestampedLine = cleanLine.startsWith('[') + ? cleanLine + : `[${new Date().toISOString()}] [${streamName.toUpperCase()}] ${cleanLine}`; + + logBuffer.push(timestampedLine); + if (logBuffer.length > MAX_BUFFER_SIZE) { + logBuffer.shift(); + } + + logEmitter.emit('server-log', timestampedLine); + } +} + +// Accumulator objects to allow updating string buffers by reference +const stdoutAccumulator = { buffer: '' }; +const stderrAccumulator = { buffer: '' }; + +let isHooked = false; + +function init() { + if (isHooked) return; + + // Intercept stdout + process.stdout.write = function(data, encoding, callback) { + processStreamData.call( + process.stdout, + data, + encoding, + originalStdoutWrite, + 'stdout', + stdoutAccumulator + ); + if (typeof callback === 'function') callback(); + return true; + }; + + // Intercept stderr + process.stderr.write = function(data, encoding, callback) { + processStreamData.call( + process.stderr, + data, + encoding, + originalStderrWrite, + 'stderr', + stderrAccumulator + ); + if (typeof callback === 'function') callback(); + return true; + }; + + isHooked = true; +} + +/** + * Ingests a list of client-side logs into the rolling clientLogBuffer. + * Each client log is expected to have structure: { timestamp, level, message } + */ +function ingestClientLogs(logs) { + if (!Array.isArray(logs)) return; + + for (const log of logs) { + const timestamp = log.timestamp || new Date().toISOString(); + const level = (log.level || 'info').toUpperCase(); + const msg = typeof log.message === 'string' ? log.message : JSON.stringify(log.message); + + const formattedLog = `[${timestamp}] [CLIENT] [${level}] ${stripAnsi(msg)}`; + clientLogBuffer.push(formattedLog); + + if (clientLogBuffer.length > MAX_BUFFER_SIZE) { + clientLogBuffer.shift(); + } + + logEmitter.emit('client-log', formattedLog); + } +} + +module.exports = { + init, + logEmitter, + logBuffer, + clientLogBuffer, + ingestClientLogs +}; diff --git a/tests/frontend/utils/clientLogCapture.test.js b/tests/frontend/utils/clientLogCapture.test.js new file mode 100644 index 0000000..fa9c3c6 --- /dev/null +++ b/tests/frontend/utils/clientLogCapture.test.js @@ -0,0 +1,110 @@ +// Copyright (c) 2026 Gordon Bolton. MIT License. +/** + * @vitest-environment jsdom + * Tests for client/src/utils/clientLogCapture.js + */ + +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; +import { initClientLogCapture } from '../../../client/src/utils/clientLogCapture.js'; + +describe('clientLogCapture', () => { + let fetchMock; + let originalConsoleLog; + let originalConsoleWarn; + let originalConsoleError; + + beforeEach(() => { + vi.useFakeTimers(); + + // Preserve original console methods + originalConsoleLog = console.log; + originalConsoleWarn = console.warn; + originalConsoleError = console.error; + + // Reset console methods to standard ones + console.log = vi.fn(); + console.warn = vi.fn(); + console.error = vi.fn(); + + // Mock window fetch + fetchMock = vi.fn(); + global.window.fetch = fetchMock; + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + + // Restore original console methods + console.log = originalConsoleLog; + console.warn = originalConsoleWarn; + console.error = originalConsoleError; + }); + + it('exits early and does not intercept console if status returns disabled', async () => { + fetchMock.mockResolvedValue({ + ok: true, + json: async () => ({ enabled: false }) + }); + + await initClientLogCapture(); + + expect(fetchMock).toHaveBeenCalledWith('/api/debug/status'); + + // Console calls should NOT be queued or overridden (i.e. they should just run vi.fn mocks) + console.log('Test message'); + expect(console.log).toHaveBeenCalledWith('Test message'); + expect(fetchMock).not.toHaveBeenCalledWith('/api/debug/client-logs', expect.any(Object)); + }); + + it('hooks console and flushes logs periodically when status returns enabled', async () => { + fetchMock.mockImplementation((url, options) => { + if (url === '/api/debug/status') { + return Promise.resolve({ + ok: true, + json: async () => ({ enabled: true }) + }); + } + if (url === '/api/debug/client-logs') { + return Promise.resolve({ + ok: true, + json: async () => ({ success: true }) + }); + } + }); + + await initClientLogCapture(); + + expect(fetchMock).toHaveBeenCalledWith('/api/debug/status'); + + // Trigger console logs + console.log('Booting app', { config: 'loaded' }); + console.warn('Deprecated api call'); + console.error('Failed request', new Error('timeout')); + + // Move timers forward to trigger flush interval (2000ms) + await vi.advanceTimersByTimeAsync(2000); + + expect(fetchMock).toHaveBeenCalledWith('/api/debug/client-logs', expect.objectContaining({ + method: 'POST', + headers: { + 'Content-Type': 'application/json' + } + })); + + const lastCall = fetchMock.mock.calls.find(call => call[0] === '/api/debug/client-logs'); + expect(lastCall).toBeDefined(); + + const loggedEntries = JSON.parse(lastCall[1].body); + expect(loggedEntries).toHaveLength(4); // Includes the interceptor boot message + 3 logs + + expect(loggedEntries[1].level).toBe('info'); + expect(loggedEntries[1].message).toContain('Booting app {"config":"loaded"}'); + + expect(loggedEntries[2].level).toBe('warn'); + expect(loggedEntries[2].message).toContain('Deprecated api call'); + + expect(loggedEntries[3].level).toBe('error'); + expect(loggedEntries[3].message).toContain('Failed request'); + }); +}); diff --git a/tests/integration/debugLogs.test.js b/tests/integration/debugLogs.test.js new file mode 100644 index 0000000..7f6e526 --- /dev/null +++ b/tests/integration/debugLogs.test.js @@ -0,0 +1,213 @@ +// Copyright (c) 2026 Gordon Bolton. MIT License. +import { describe, it, expect, beforeAll, afterAll, afterEach } from 'vitest'; +import request from 'supertest'; +import nock from 'nock'; +import { createApp } from '../../server/app.js'; + +const EMBY_BASE = 'https://emby.test'; + +describe('Debug Logs API Integration', () => { + beforeAll(() => { + process.env.EMBY_URL = EMBY_BASE; + process.env.SOFARR_WEBHOOK_SECRET = 'test-webhook-secret-xyz'; + }); + + afterAll(() => { + delete process.env.EMBY_URL; + delete process.env.SOFARR_WEBHOOK_SECRET; + delete process.env.ENABLE_LOG_STREAM; + delete process.env.LOG_ALLOW_SUBNETS; + delete process.env.TRUST_PROXY; + }); + + afterEach(() => { + nock.cleanAll(); + }); + + describe('GET /api/debug/status', () => { + it('returns enabled: false when ENABLE_LOG_STREAM is not true', async () => { + process.env.ENABLE_LOG_STREAM = 'false'; + const app = createApp({ skipRateLimits: true }); + const res = await request(app).get('/api/debug/status'); + expect(res.status).toBe(200); + expect(res.body.enabled).toBe(false); + }); + + it('returns enabled: true when ENABLE_LOG_STREAM is true', async () => { + process.env.ENABLE_LOG_STREAM = 'true'; + const app = createApp({ skipRateLimits: true }); + const res = await request(app).get('/api/debug/status'); + expect(res.status).toBe(200); + expect(res.body.enabled).toBe(true); + }); + }); + + describe('Global toggle checking', () => { + it('returns 403 Forbidden on server logs GET when feature is disabled', async () => { + process.env.ENABLE_LOG_STREAM = 'false'; + const app = createApp({ skipRateLimits: true }); + const res = await request(app).get('/api/debug/server-logs'); + expect(res.status).toBe(403); + expect(res.body.error).toMatch(/disabled/i); + }); + + it('returns 403 Forbidden on client logs GET when feature is disabled', async () => { + process.env.ENABLE_LOG_STREAM = 'false'; + const app = createApp({ skipRateLimits: true }); + const res = await request(app).get('/api/debug/client-logs'); + expect(res.status).toBe(403); + expect(res.body.error).toMatch(/disabled/i); + }); + + it('returns 403 Forbidden on client logs POST when feature is disabled', async () => { + process.env.ENABLE_LOG_STREAM = 'false'; + const app = createApp({ skipRateLimits: true }); + const res = await request(app).post('/api/debug/client-logs').send([]); + expect(res.status).toBe(403); + expect(res.body.error).toMatch(/disabled/i); + }); + }); + + describe('Subnet CIDR validation', () => { + beforeAll(() => { + process.env.ENABLE_LOG_STREAM = 'true'; + process.env.LOG_ALLOW_SUBNETS = '127.0.0.1/32,192.168.1.0/24'; + process.env.TRUST_PROXY = '1'; + }); + + it('returns 403 Forbidden if client IP is not in subnet allowlist', async () => { + const app = createApp({ skipRateLimits: true }); + const res = await request(app) + .get('/api/debug/server-logs') + .set('X-Forwarded-For', '10.0.0.50'); + expect(res.status).toBe(403); + expect(res.body.error).toMatch(/Access denied from IP/i); + }); + + it('bypasses subnet check and hits auth validation if client IP is allowed', async () => { + const app = createApp({ skipRateLimits: true }); + // In subnet allowlist but missing credentials -> returns 401 instead of 403! + const res = await request(app) + .get('/api/debug/server-logs') + .set('X-Forwarded-For', '192.168.1.150'); + expect(res.status).toBe(401); + }); + + afterAll(() => { + delete process.env.LOG_ALLOW_SUBNETS; + delete process.env.TRUST_PROXY; + }); + }); + + describe('Authentication and Bypass policies', () => { + beforeAll(() => { + process.env.ENABLE_LOG_STREAM = 'true'; + }); + + it('returns 401 Unauthorized when all auth options are missing', async () => { + const app = createApp({ skipRateLimits: true }); + const res = await request(app).get('/api/debug/server-logs'); + expect(res.status).toBe(401); + expect(res.headers['www-authenticate']).toContain('Basic realm='); + }); + + it('allows access via X-Webhook-Secret header bypass', async () => { + const app = createApp({ skipRateLimits: true }); + // X-Webhook-Secret bypass avoids Emby login entirely (returns 200 SSE stream) + const res = await request(app) + .get('/api/debug/server-logs?testClose=true') + .set('X-Webhook-Secret', 'test-webhook-secret-xyz'); + expect(res.status).toBe(200); + expect(res.headers['content-type']).toContain('text/event-stream'); + }); + + it('allows access via Basic Authentication with valid Emby administrator credentials', async () => { + const app = createApp({ skipRateLimits: true }); + + // Mock Emby login + nock(EMBY_BASE) + .post('/Users/authenticatebyname') + .reply(200, { + AccessToken: 'admin-emby-tok', + User: { Id: 'admin-user-id', Name: 'embyadmin' } + }); + + // Mock Emby profile fetch verifying IsAdministrator is true + nock(EMBY_BASE) + .get('/Users/admin-user-id') + .reply(200, { + Id: 'admin-user-id', + Name: 'embyadmin', + Policy: { IsAdministrator: true } + }); + + const res = await request(app) + .get('/api/debug/server-logs?testClose=true') + .auth('embyadmin', 'password123'); + + expect(res.status).toBe(200); + expect(res.headers['content-type']).toContain('text/event-stream'); + }); + + it('denies access via Basic Authentication if user is not an administrator', async () => { + const app = createApp({ skipRateLimits: true }); + + nock(EMBY_BASE) + .post('/Users/authenticatebyname') + .reply(200, { + AccessToken: 'user-emby-tok', + User: { Id: 'regular-user-id', Name: 'embyuser' } + }); + + nock(EMBY_BASE) + .get('/Users/regular-user-id') + .reply(200, { + Id: 'regular-user-id', + Name: 'embyuser', + Policy: { IsAdministrator: false } + }); + + const res = await request(app) + .get('/api/debug/server-logs') + .auth('embyuser', 'password123'); + + expect(res.status).toBe(401); + }); + }); + + describe('Client logs ingestion and streaming', () => { + beforeAll(() => { + process.env.ENABLE_LOG_STREAM = 'true'; + }); + + it('returns 400 Bad Request on client logs POST if body is not an array', async () => { + const app = createApp({ skipRateLimits: true }); + const res = await request(app) + .post('/api/debug/client-logs') + .set('X-Webhook-Secret', 'test-webhook-secret-xyz') + .send({ message: 'not an array' }); + expect(res.status).toBe(400); + }); + + it('ingests client logs array and streams them over client logs GET SSE', async () => { + const app = createApp({ skipRateLimits: true }); + + // Ingest client logs + const postRes = await request(app) + .post('/api/debug/client-logs') + .set('X-Webhook-Secret', 'test-webhook-secret-xyz') + .send([ + { timestamp: new Date().toISOString(), level: 'info', message: 'Hello from client' } + ]); + expect(postRes.status).toBe(200); + expect(postRes.body.count).toBe(1); + + // Verify log streams successfully via GET + const getRes = await request(app) + .get('/api/debug/client-logs?testClose=true') + .set('X-Webhook-Secret', 'test-webhook-secret-xyz'); + expect(getRes.status).toBe(200); + expect(getRes.headers['content-type']).toContain('text/event-stream'); + }); + }); +});