feat: implement togglable debug log streaming for server stdout/stderr and client console logs

- Created server/utils/logCapture.js to intercept and buffer server output, stripping ANSI escape codes.
- Created server/middleware/logStreamAuth.js enforcing subnet IP filtering (LOG_ALLOW_SUBNETS), Emby session cookie, Basic Auth fallback, and X-Webhook-Secret header bypass.
- Created server/routes/debug.js with SSE streams /api/debug/server-logs, /api/debug/client-logs and batched POST /api/debug/client-logs. Exposes public configuration status at /api/debug/status.
- Integrated log capture and mounted debug routes in server/app.js and server/index.js.
- Implemented client/src/utils/clientLogCapture.js in the frontend SPA to hook console log/warn/error and flush batched console events.
- Documented all endpoints in OpenAPI server/openapi.yaml, ARCHITECTURE.md, and README.md.
- Wrote route integration tests and frontend console capture tests, with full validation in swagger-coverage.
This commit is contained in:
2026-05-24 11:31:36 +01:00
parent afc940aba7
commit 3c6791658c
12 changed files with 1127 additions and 0 deletions
+48
View File
@@ -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
+10
View File
@@ -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
+4
View File
@@ -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) {
+137
View File
@@ -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);
}
}
+2
View File
@@ -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);
+4
View File
@@ -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);
+156
View File
@@ -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;
+169
View File
@@ -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'
+143
View File
@@ -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;
+131
View File
@@ -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
};
@@ -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');
});
});
+213
View File
@@ -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');
});
});
});