diff --git a/client-v3/src/js/logger.test.ts b/client-v3/src/js/logger.test.ts new file mode 100644 index 000000000..49e6427ce --- /dev/null +++ b/client-v3/src/js/logger.test.ts @@ -0,0 +1,62 @@ +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; + +const userState: { authToken: string | null } = { authToken: null }; + +vi.mock('@/stores/user', () => ({ useUserStore: () => userState })); +vi.mock('@/stores/system', () => ({ + useSystemStore: () => ({ settings: { client_log_enabled: true, client_log_level: 'DEBUG' } }), +})); + +describe('remote logger', () => { + const fetchMock = vi.fn(() => Promise.resolve(new Response('{}'))); + + beforeEach(async () => { + vi.useFakeTimers(); + vi.resetModules(); + fetchMock.mockClear(); + vi.stubGlobal('fetch', fetchMock); + userState.authToken = null; + const { initRemoteLogging } = await import('./logger'); + initRemoteLogging(); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.unstubAllGlobals(); + }); + + it('holds log entries until a token exists, then sends them with it', async () => { + const log = (await import('loglevel')).default; + log.error('before login'); + await vi.advanceTimersByTimeAsync(2000); + expect(fetchMock).not.toHaveBeenCalled(); + + userState.authToken = 'tok'; + log.error('after login'); + await vi.advanceTimersByTimeAsync(2000); + + expect(fetchMock).toHaveBeenCalledTimes(1); + const [, init] = fetchMock.mock.calls[0] as unknown as [string, RequestInit]; + expect((init.headers as Record).Authorization).toBe('Bearer tok'); + const messages = JSON.parse(init.body as string).batch.map( + (e: { message: string }) => e.message + ); + expect(messages).toEqual(expect.arrayContaining(['before login', 'after login'])); + }); + + it('keeps only the most recent 50 entries while logged out', async () => { + const log = (await import('loglevel')).default; + for (let i = 0; i < 80; i++) log.error(`entry ${i}`); + + userState.authToken = 'tok'; + await vi.advanceTimersByTimeAsync(2000); + log.error('final'); + await vi.advanceTimersByTimeAsync(2000); + + const [, init] = fetchMock.mock.calls[0] as unknown as [string, RequestInit]; + const batch = JSON.parse(init.body as string).batch as { message: string }[]; + expect(batch.length).toBeLessThanOrEqual(50); + expect(batch.map((e) => e.message)).not.toContain('entry 0'); + expect(batch.map((e) => e.message)).toContain('final'); + }); +}); diff --git a/client-v3/src/js/logger.ts b/client-v3/src/js/logger.ts index fbcc197e1..246b8acd6 100644 --- a/client-v3/src/js/logger.ts +++ b/client-v3/src/js/logger.ts @@ -19,6 +19,7 @@ let flushTimer: ReturnType | null = null; function enqueueLog(level: string, message: string, extra: Record): void { logQueue.push({ level, message, extra }); + if (logQueue.length > MAX_QUEUE_SIZE) logQueue.shift(); if (logQueue.length >= MAX_QUEUE_SIZE) { flushQueue(); return; @@ -33,9 +34,13 @@ function flushQueue() { flushTimer = null; if (logQueue.length === 0) return; + // The server only accepts log posts from logged-in users, so entries stay queued + // (capped in enqueueLog) until a token exists. + const token = useUserStore().authToken; + if (!token) return; + const batch = logQueue.splice(0); - const token = useUserStore().authToken; const headers: Record = { 'Content-Type': 'application/json' }; if (token) headers['Authorization'] = `Bearer ${token}`; diff --git a/client-v3/src/stores/user.ts b/client-v3/src/stores/user.ts index 05fbe2c4b..0775d4e73 100644 --- a/client-v3/src/stores/user.ts +++ b/client-v3/src/stores/user.ts @@ -57,6 +57,7 @@ export const useUserStore = defineStore('user', { try { await useSystemStore().getRbacRoles(); + await useSystemStore().getRawSettings(); await this.getCurrentUser(); await this.getCurrentRbac(); await this.getUserSettings(); @@ -94,6 +95,7 @@ export const useUserStore = defineStore('user', { this.userSettings = {}; this.stageDirectionStyleOverrides = []; this.cueColourOverrides = []; + void useSystemStore().getRawSettings(); // drop admin-only values from the cache // Mark the open WebSocket as waiting for authentication (as the legacy // client's CLEAR_WS_AUTHENTICATION does), so the next in-app login diff --git a/client/src/js/logger.test.ts b/client/src/js/logger.test.ts new file mode 100644 index 000000000..f68b208bd --- /dev/null +++ b/client/src/js/logger.test.ts @@ -0,0 +1,65 @@ +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; + +const getters: Record = {}; + +vi.mock('@/store/store', () => ({ default: { getters, watch: vi.fn() } })); + +describe('remote logger', () => { + const fetchMock = vi.fn(() => Promise.resolve(new Response('{}'))); + let log: typeof import('loglevel').default; + + const sentBatches = () => + fetchMock.mock.calls.map((call) => { + const [, init] = call as unknown as [string, RequestInit]; + return { + auth: (init.headers as Record).Authorization, + messages: (JSON.parse(init.body as string).batch as { message: string }[]).map( + (e) => e.message + ), + }; + }); + + beforeEach(async () => { + vi.useFakeTimers(); + vi.resetModules(); + fetchMock.mockClear(); + vi.stubGlobal('fetch', fetchMock); + getters.AUTH_TOKEN = null; + getters.SETTINGS = { client_log_enabled: true, client_log_level: 'DEBUG' }; + await (await import('./logger')).initRemoteLogging(); + log = (await import('loglevel')).default; + }); + + afterEach(() => { + vi.useRealTimers(); + vi.unstubAllGlobals(); + }); + + it('does not post while logged out and flushes the held entries after login', async () => { + log.error('queued while logged out'); + await vi.advanceTimersByTimeAsync(2000); + expect(fetchMock).not.toHaveBeenCalled(); + + getters.AUTH_TOKEN = 'tok'; + log.error('logged in'); + await vi.advanceTimersByTimeAsync(2000); + + const [batch] = sentBatches(); + expect(batch.auth).toBe('Bearer tok'); + expect(batch.messages).toEqual( + expect.arrayContaining(['queued while logged out', 'logged in']) + ); + }); + + it('caps the logged-out queue at the 50 most recent entries', async () => { + for (let i = 0; i < 80; i++) log.error(`entry ${i}`); + getters.AUTH_TOKEN = 'tok'; + log.error('final'); + await vi.advanceTimersByTimeAsync(2000); + + const [batch] = sentBatches(); + expect(batch.messages.length).toBeLessThanOrEqual(50); + expect(batch.messages).not.toContain('entry 0'); + expect(batch.messages).toContain('final'); + }); +}); diff --git a/client/src/js/logger.ts b/client/src/js/logger.ts index 9df953cd6..544d23290 100644 --- a/client/src/js/logger.ts +++ b/client/src/js/logger.ts @@ -22,6 +22,7 @@ let flushTimer: ReturnType | null = null; */ function enqueueLog(level: string, message: string, extra: Record): void { logQueue.push({ level, message, extra }); + if (logQueue.length > MAX_QUEUE_SIZE) logQueue.shift(); if (logQueue.length >= MAX_QUEUE_SIZE) { flushQueue(); return; @@ -39,9 +40,13 @@ function flushQueue() { flushTimer = null; if (logQueue.length === 0) return; + // The server only accepts log posts from logged-in users, so entries stay queued + // (capped in enqueueLog) until a token exists. + const token = store.getters.AUTH_TOKEN; + if (!token) return; + const batch = logQueue.splice(0); - const token = store.getters.AUTH_TOKEN; const headers: Record = { 'Content-Type': 'application/json' }; if (token) headers['Authorization'] = `Bearer ${token}`; diff --git a/client/src/store/modules/user/user.ts b/client/src/store/modules/user/user.ts index 2a6ac1820..bde2e139e 100644 --- a/client/src/store/modules/user/user.ts +++ b/client/src/store/modules/user/user.ts @@ -116,6 +116,7 @@ const module: Module = { await context.commit('SET_AUTH_TOKEN', data.access_token); } await context.dispatch('GET_RBAC_ROLES'); + await context.dispatch('GET_RAW_SETTINGS'); await context.dispatch('GET_CURRENT_USER'); await context.dispatch('GET_CURRENT_RBAC'); await context.dispatch('GET_USER_SETTINGS'); @@ -150,6 +151,8 @@ const module: Module = { await context.commit('SET_USER_SETTINGS', []); await context.commit('SET_STAGE_DIRECTION_STYLE_OVERRIDES', []); await context.commit('CLEAR_WS_AUTHENTICATION'); + // Re-fetch (now anonymous) so admin-only values are dropped from the cache. + context.dispatch('GET_RAW_SETTINGS'); if (token) { try { const response = await fetch(makeURL('/api/v1/auth/logout'), { diff --git a/docs/pages/user_config.md b/docs/pages/user_config.md index d22164cc1..b399b48e4 100644 --- a/docs/pages/user_config.md +++ b/docs/pages/user_config.md @@ -97,6 +97,8 @@ All log entries are attributed to the logged-in user where one is present: - **Server logs**: Each HTTP access log line and request-body debug line includes `[username]` in the message (e.g. `200 GET /api/v1/user/settings (127.0.0.1) [alice] 5.23ms`). WebSocket messages and close events also include the username once the connection has been authenticated. - **Client logs**: The server extracts the username from the JWT token on each batch submission, so all client log entries are attributed even if the client sends no user information itself. +- **Client log limits**: Submitting client logs requires being logged in, so entries generated before login are held in the browser and sent after login. A single batch may contain at most 100 entries, messages are truncated at 4 KB, oversized extra data is dropped, and each IP address is limited to 600 entries per minute (further entries are rejected until the window resets). +- **Server file paths**: The database, log, compiled script and draft script locations are only shown to administrators (on the Settings tab); other users and logged-out visitors never receive them. #### Filtering diff --git a/server/controllers/api/v1/logging.py b/server/controllers/api/v1/logging.py index 75856952c..1502ae23c 100644 --- a/server/controllers/api/v1/logging.py +++ b/server/controllers/api/v1/logging.py @@ -1,4 +1,6 @@ -from typing import Any, Dict, List +import json +import time +from typing import Any, Dict, List, NamedTuple, Optional, Tuple from tornado import escape, httputil @@ -6,6 +8,103 @@ from digi_server.logger import get_logger, map_client_level from utils.web.base_controller import BaseAPIController from utils.web.route import ApiRoute, ApiVersion +from utils.web.web_decorators import api_authenticated + + +#: Maximum number of entries accepted in one batch request. +MAX_BATCH_ENTRIES = 100 +#: Maximum length (characters) of a single log message; longer ones are truncated. +MAX_MESSAGE_LENGTH = 4096 +#: Maximum serialised size (characters) of an entry's ``extra``; larger is replaced. +MAX_EXTRA_LENGTH = 4096 +#: Per-IP budget: at most this many log entries per window. +RATE_LIMIT_ENTRIES = 600 +RATE_LIMIT_WINDOW_SECONDS = 60.0 + + +class _Window(NamedTuple): + """A client's current rate-limit window.""" + + start: float + used: int + + +class ClientLogRateLimiter: + """Fixed-window, per-IP limiter on the number of client log entries. + + One instance lives on the application object, so no state is shared between + application instances (or test workers). Clients are keyed by raw IP address, + so users sharing an IP (NAT, proxy) share one budget. + """ + + def __init__( + self, + limit: int = RATE_LIMIT_ENTRIES, + window: float = RATE_LIMIT_WINDOW_SECONDS, + ): + """ + :param limit: Entries allowed per window; must be positive. + :param window: Window length in seconds; must be positive. + :raises ValueError: If *limit* or *window* is not positive. + """ + if limit <= 0 or window <= 0: + raise ValueError("limit and window must be positive") + self.limit = limit + self.window = window + self._windows: Dict[str, _Window] = {} + + def check( + self, key: str, cost: int, now: Optional[float] = None + ) -> Optional[float]: + """Try to consume *cost* entries for *key*. + + :param key: The client identifier (IP address). + :param cost: Number of entries in the request. + :param now: Current monotonic time; defaults to ``time.monotonic()``. + :returns: None if allowed, otherwise the seconds (at least 1) until the + window resets. + """ + now = time.monotonic() if now is None else now + # Runs on every call (not periodically): this bounds memory and is also what + # resets a key's window once it has expired. + expired = [ + ip for ip, win in self._windows.items() if now - win.start >= self.window + ] + for ip in expired: + del self._windows[ip] + win = self._windows.get(key, _Window(now, 0)) + if win.used + cost > self.limit: + return max(self.window - (now - win.start), 1.0) + self._windows[key] = _Window(win.start, win.used + cost) + return None + + +def _clean_text(value: Any, limit: int) -> str: + """Coerce *value* to a bounded, single-line string safe to write to a log.""" + text = value if isinstance(value, str) else str(value) + if len(text) > limit: + text = text[:limit] + "...[truncated]" + return text.replace("\r", "\\r").replace("\n", "\\n") + + +def _clean_extra(value: Any) -> Tuple[Dict, Optional[str]]: + """Sanitise an entry's client-supplied ``extra``. + + :param value: The raw ``extra`` value. + :returns: A ``(extra, omitted_reason)`` pair. A small JSON-serialisable dict is + returned as-is with no reason. Non-dict input is dropped silently + (``{}``, no reason). An oversized or non-serialisable dict is replaced by + ``{}`` with a reason, which the caller records under a server-controlled + key so a client cannot forge it. + """ + if not isinstance(value, dict): + return {}, None + try: + if len(json.dumps(value, default=str)) > MAX_EXTRA_LENGTH: + return {}, "too large" + except (TypeError, ValueError, RecursionError): + return {}, "not serialisable" + return {str(k): v for k, v in value.items()}, None class ClientLoggingBase(BaseAPIController): @@ -18,20 +117,47 @@ def __init__( super().__init__(application, request, **kwargs) self.client_logger = get_logger("Client") - def process_logs(self, entries: List[Dict]): + def process_logs(self, entries: List[Any]): + """Validate, bound and write a list of client log entries. + + Responds 429 (with ``Retry-After``) if the caller's IP exceeded its budget. + + :param entries: The raw entries from the request body. + """ + limiter = getattr(self.application, "client_log_limiter", None) + if limiter is None: + limiter = ClientLogRateLimiter() + self.application.client_log_limiter = limiter + retry_after = limiter.check(self.request.remote_ip or "unknown", len(entries)) + if retry_after is not None: + self.set_status(429) + self.set_header("Retry-After", str(int(retry_after) + 1)) + self.write({"message": "Too many log entries"}) + return + # Build request-level context added to every entry's extra request_extra = { "remote_ip": self.request.remote_ip, - "agent": self.request.headers.get("User-Agent", "Unknown"), + "agent": _clean_text( + self.request.headers.get("User-Agent", "Unknown"), 256 + ), } if self.current_user: request_extra["user_id"] = self.current_user.get("id") request_extra["username"] = self.current_user.get("username") + dropped = 0 for entry in entries: - level = entry.get("level", "INFO").upper() - message = entry.get("message", "") - extra = {**entry.get("extra", {}), **request_extra} + if not isinstance(entry, dict): + dropped += 1 + continue + level = _clean_text(entry.get("level", "INFO"), 16).upper() + message = _clean_text(entry.get("message", ""), MAX_MESSAGE_LENGTH) + client_extra, omitted = _clean_extra(entry.get("extra")) + # Server-set keys come last so a client cannot forge them. + extra = {**client_extra, **request_extra} + if omitted: + extra["extra_omitted"] = omitted log_level = map_client_level(level) @@ -52,12 +178,19 @@ def process_logs(self, entries: List[Dict]): }, ) + if dropped: + get_logger().warning( + f"Dropped {dropped} malformed client log entries from " + f"{request_extra['remote_ip']}" + ) + self.set_status(200) self.write({"status": "OK"}) @ApiRoute("logs/batch", ApiVersion.V1, ignore_logging=True) class ClientLoggingBatchController(ClientLoggingBase): + @api_authenticated async def post(self): client_log_enabled = await self.application.digi_settings.get( "client_log_enabled" @@ -69,7 +202,7 @@ async def post(self): try: data = escape.json_decode(self.request.body) - except ValueError: + except (ValueError, RecursionError): self.set_status(400) self.write({"message": "Invalid JSON"}) return @@ -85,11 +218,19 @@ async def post(self): self.write({"message": "Expected 'batch' to be a list of log entries"}) return + if len(batch) > MAX_BATCH_ENTRIES: + self.set_status(413) + self.write( + {"message": f"Batch exceeds the {MAX_BATCH_ENTRIES} entry limit"} + ) + return + self.process_logs(batch) @ApiRoute("logs", ApiVersion.V1, ignore_logging=True) class ClientLoggingController(ClientLoggingBase): + @api_authenticated async def post(self): client_log_enabled = await self.application.digi_settings.get( "client_log_enabled" @@ -101,9 +242,14 @@ async def post(self): try: data = escape.json_decode(self.request.body) - except ValueError: + except (ValueError, RecursionError): self.set_status(400) self.write({"message": "Invalid JSON"}) return + if not isinstance(data, dict): + self.set_status(400) + self.write({"message": "Expected a JSON object log entry"}) + return + self.process_logs([data]) diff --git a/server/controllers/api/v1/settings.py b/server/controllers/api/v1/settings.py index 56fe472ec..a2f7556f3 100644 --- a/server/controllers/api/v1/settings.py +++ b/server/controllers/api/v1/settings.py @@ -51,7 +51,8 @@ async def _collab_mode_change_blocked(self, settings: Settings, data: dict) -> b @allow_when_password_required async def get(self): settings: Settings = self.application.digi_settings - settings_json = await settings.as_json() + is_admin = bool(self.current_user and self.current_user["is_admin"]) + settings_json = await settings.as_json(include_sensitive=is_admin) await self.finish(settings_json) @api_authenticated @@ -114,5 +115,6 @@ async def get(self): class RawSettingsController(BaseAPIController): async def get(self): settings: Settings = self.application.digi_settings - settings_json = await settings.raw_json() + is_admin = bool(self.current_user and self.current_user["is_admin"]) + settings_json = await settings.raw_json(include_sensitive=is_admin) await self.finish(settings_json) diff --git a/server/controllers/controllers.py b/server/controllers/controllers.py index d5b67150c..183beadfb 100644 --- a/server/controllers/controllers.py +++ b/server/controllers/controllers.py @@ -9,6 +9,7 @@ from utils.module_discovery import get_resource_path, import_modules, is_frozen from utils.web.base_controller import BaseAPIController, BaseController from utils.web.route import ApiRoute, ApiVersion, Route +from utils.web.web_decorators import api_authenticated, require_admin IMPORTED_CONTROLLERS = {} @@ -128,6 +129,8 @@ def delete(self): @Route("/debug") class DebugController(BaseController): + @api_authenticated + @require_admin def get(self): self.set_status(200) self.set_header("Content-Type", "application/json") diff --git a/server/digi_server/settings.py b/server/digi_server/settings.py index fa5fa4ccf..426c43a05 100644 --- a/server/digi_server/settings.py +++ b/server/digi_server/settings.py @@ -55,6 +55,7 @@ def __init__( hide_from_ui: bool = False, choice_options: Optional[list] = None, choice_labels: Optional[list] = None, + sensitive: bool = False, ): if val_type not in self.ALLOWED_TYPES: raise RuntimeError( @@ -110,6 +111,9 @@ def __init__( self.display_name = display_name self.help_text = help_text self.hide_from_ui = hide_from_ui + # Sensitive settings (e.g. server filesystem paths) are only ever disclosed to + # admins: every payload sent to other users or broadcast omits them. + self.sensitive = sensitive self.choice_options = choice_options self.choice_labels = choice_labels @@ -222,6 +226,7 @@ def init_settings(self): False, nullable=False, display_name="Database Path", + sensitive=True, ) self.define( "current_show", @@ -280,6 +285,7 @@ def init_settings(self): self._application.regen_logging, display_name="Application Log Path", category="Logging", + sensitive=True, ) self.define( "max_log_mb", @@ -329,6 +335,7 @@ def init_settings(self): self._application.regen_logging, display_name="Database Log Path", category="DB Logging", + sensitive=True, ) self.define( "db_max_log_mb", @@ -355,6 +362,7 @@ def init_settings(self): False, display_name="Compiled Script Path", help_text="Directory used to store compiled scripts.", + sensitive=True, ) self.define( "draft_script_path", @@ -363,6 +371,7 @@ def init_settings(self): False, display_name="Draft Script Path", help_text="Directory used to store collaborative editing draft files.", + sensitive=True, ) self.define( "client_log_enabled", @@ -393,6 +402,7 @@ def init_settings(self): display_name="Client Log Path", help_text="Path to the log file for client-side log messages.", category="Client Logging", + sensitive=True, ) self.define( "client_max_log_mb", @@ -464,6 +474,7 @@ def define( choice_options: Optional[list] = None, choice_labels: Optional[list] = None, category: str = "General", + sensitive: bool = False, ): if key in self.settings: raise KeyError(f"Setting {key} is already defined") @@ -480,6 +491,7 @@ def define( hide_from_ui, choice_options, choice_labels, + sensitive, ) if category not in self.categories: self.categories[category] = [key] @@ -490,13 +502,22 @@ def file_deleted(self): get_logger().info("Settings file deleted; recreating from in memory settings") self._save() + def _values(self, include_sensitive: bool) -> dict: + """Return the current value of every setting, omitting sensitive ones unless asked. + + :param include_sensitive: Include settings defined with ``sensitive=True``. + """ + return { + key: value.get_value() + for key, value in self.settings.items() + if include_sensitive or not value.sensitive + } + def auto_reload_changes(self): get_logger().info("Settings file changed; auto reloading") self._load(spawn_callbacks=True) - settings_json = {} - for key, value in self.settings.items(): - settings_json[key] = value.get_value() + settings_json = self._values(include_sensitive=False) for client in self._application.clients.copy(): client.write_message( @@ -599,17 +620,27 @@ def _json(self): settings_json[key] = value.get_value() return settings_json - async def as_json(self): + async def as_json(self, include_sensitive: bool = False): + """Return all setting values plus the server version. + + :param include_sensitive: Include sensitive settings. Only pass True for + administrators. + """ async with self.lock: - settings_json = {} - for key, value in self.settings.items(): - settings_json[key] = value.get_value() + settings_json = self._values(include_sensitive) settings_json["version"] = _get_version() return json.loads(json.dumps(settings_json)) - async def raw_json(self): + async def raw_json(self, include_sensitive: bool = False): + """Return full setting metadata (type, default, help text, ...). + + :param include_sensitive: Include sensitive settings. Only pass True for + administrators. + """ async with self.lock: settings_json = {} for key, value in self.settings.items(): + if not include_sensitive and value.sensitive: + continue settings_json[key] = value.as_json() return json.loads(json.dumps(settings_json)) diff --git a/server/test/controllers/api/v1/test_logging.py b/server/test/controllers/api/v1/test_logging.py index 905ed3edc..20823757f 100644 --- a/server/test/controllers/api/v1/test_logging.py +++ b/server/test/controllers/api/v1/test_logging.py @@ -1,72 +1,195 @@ import json from tornado import escape -from tornado.testing import gen_test +from controllers.api.v1.logging import ( + MAX_BATCH_ENTRIES, + MAX_MESSAGE_LENGTH, + ClientLogRateLimiter, +) +from digi_server.logger import get_logger from test.conftest import DigiScriptTestCase class TestLoggingController(DigiScriptTestCase): - @gen_test - async def test_logging_endpoint_success(self): - """Test that the logging endpoint successfully receives logs.""" + def _post(self, path, payload, token=None, body=None): + headers = {"Content-Type": "application/json"} + if token: + headers["Authorization"] = f"Bearer {token}" + return self.fetch( + path, + method="POST", + body=body if body is not None else json.dumps(payload), + headers=headers, + ) + + def test_logging_endpoint_success(self): + token = self._create_and_login_admin() payload = { "level": "INFO", "message": "Test message from client", "extra": {"source": "unit-test"}, } - response = await self.http_client.fetch( - self.get_url("/api/v1/logs"), - method="POST", - body=json.dumps(payload), - headers={"Content-Type": "application/json"}, - ) + response = self._post("/api/v1/logs", payload, token) self.assertEqual(200, response.code) - data = escape.json_decode(response.body) - self.assertEqual("OK", data["status"]) - - @gen_test - async def test_logging_endpoint_disabled(self): - """Test that the logging endpoint returns 403 when disabled in settings.""" - # Disable client logging in settings - await self._app.digi_settings.set("client_log_enabled", False) - - payload = {"level": "INFO", "message": "Test message from client"} - response = await self.http_client.fetch( - self.get_url("/api/v1/logs"), - method="POST", - body=json.dumps(payload), - headers={"Content-Type": "application/json"}, - raise_error=False, - ) - self.assertEqual(403, response.code) - data = escape.json_decode(response.body) - self.assertEqual("Client logging is disabled", data["message"]) + self.assertEqual("OK", escape.json_decode(response.body)["status"]) - # Re-enable for other tests - await self._app.digi_settings.set("client_log_enabled", True) + def test_logging_requires_authentication(self): + payload = {"level": "INFO", "message": "anonymous"} + with self.assertNoLogs(get_logger("Client"), level="DEBUG"): + self.assertEqual(401, self._post("/api/v1/logs", payload).code) + self.assertEqual( + 401, self._post("/api/v1/logs/batch", {"batch": [payload]}).code + ) - @gen_test - async def test_logging_endpoint_invalid_json(self): - """Test that the logging endpoint returns 400 for invalid JSON.""" - response = await self.http_client.fetch( - self.get_url("/api/v1/logs"), - method="POST", - body="invalid json", - headers={"Content-Type": "application/json"}, - raise_error=False, + def test_logging_endpoint_disabled(self): + token = self._create_and_login_admin() + self.io_loop.run_sync( + lambda: self._app.digi_settings.set("client_log_enabled", False) ) + response = self._post("/api/v1/logs", {"level": "INFO", "message": "x"}, token) + self.assertEqual(403, response.code) + self.assertEqual( + "Client logging is disabled", escape.json_decode(response.body)["message"] + ) + + def test_logging_endpoint_invalid_json(self): + token = self._create_and_login_admin() + response = self._post("/api/v1/logs", None, token, body="invalid json") self.assertEqual(400, response.code) - @gen_test - async def test_logging_endpoint_different_levels(self): - """Test that the logging endpoint accepts various log levels.""" + def test_logging_endpoint_different_levels(self): + token = self._create_and_login_admin() for level in ["DEBUG", "INFO", "WARN", "ERROR"]: - payload = {"level": level, "message": f"Test level {level}"} - response = await self.http_client.fetch( - self.get_url("/api/v1/logs"), - method="POST", - body=json.dumps(payload), - headers={"Content-Type": "application/json"}, + response = self._post( + "/api/v1/logs", {"level": level, "message": f"lvl {level}"}, token ) self.assertEqual(200, response.code) + + def test_batch_over_limit_rejected(self): + token = self._create_and_login_admin() + batch = [{"level": "INFO", "message": "m"}] * (MAX_BATCH_ENTRIES + 1) + self.assertEqual( + 413, self._post("/api/v1/logs/batch", {"batch": batch}, token).code + ) + batch = batch[:MAX_BATCH_ENTRIES] + self.assertEqual( + 200, self._post("/api/v1/logs/batch", {"batch": batch}, token).code + ) + + def test_message_truncated_and_newlines_escaped(self): + token = self._create_and_login_admin() + message = "A\nFAKE LOG LINE " + "x" * (MAX_MESSAGE_LENGTH * 2) + with self.assertLogs(get_logger("Client"), level="DEBUG") as logs: + response = self._post( + "/api/v1/logs", {"level": "INFO", "message": message}, token + ) + self.assertEqual(200, response.code) + out = logs.records[0].getMessage() + self.assertNotIn("\n", out) + self.assertIn("[truncated]", out) + self.assertLess(len(out), MAX_MESSAGE_LENGTH + 1500) + + def test_oversized_extra_replaced(self): + token = self._create_and_login_admin() + with self.assertLogs(get_logger("Client"), level="DEBUG") as logs: + self._post( + "/api/v1/logs", + {"level": "INFO", "message": "m", "extra": {"k": "y" * 100000}}, + token, + ) + out = logs.records[0].getMessage() + self.assertIn("too large", out) + self.assertNotIn("yyyyyyyyyy", out) + + def test_non_string_fields_coerced_and_malformed_entries_dropped(self): + token = self._create_and_login_admin() + batch = [ + {"level": 5, "message": {"a": 1}, "extra": "not-a-dict"}, + {"level": None, "message": None, "extra": [1, 2]}, + "not-an-object", + ] + with self.assertLogs(get_logger("Client"), level="DEBUG") as client_logs: + with self.assertLogs(get_logger(), level="WARNING") as server_logs: + response = self._post("/api/v1/logs/batch", {"batch": batch}, token) + self.assertEqual(200, response.code) + self.assertEqual(2, len(client_logs.records)) + self.assertIn("{'a': 1}", client_logs.records[0].getMessage()) + self.assertIn("None", client_logs.records[1].getMessage()) + self.assertTrue(any("Dropped 1 malformed" in m for m in server_logs.output)) + + def test_client_extra_cannot_forge_server_omission_marker(self): + token = self._create_and_login_admin() + with self.assertLogs(get_logger("Client"), level="DEBUG") as logs: + self._post( + "/api/v1/logs", + {"message": "m", "extra": {"extra_omitted": "too large"}}, + token, + ) + # A client-supplied key of the same name is its own data, not a server marker: + # the server only ever adds the marker for entries it actually reduced. + self.assertEqual(1, logs.records[0].getMessage().count("extra_omitted")) + + def test_oversize_entry_does_not_affect_sibling_entries(self): + token = self._create_and_login_admin() + batch = [ + {"message": "A" * (MAX_MESSAGE_LENGTH * 2), "extra": {"k": "y" * 100000}}, + {"message": "small sibling", "extra": {"k": "v"}}, + ] + with self.assertLogs(get_logger("Client"), level="DEBUG") as logs: + self._post("/api/v1/logs/batch", {"batch": batch}, token) + self.assertIn("[truncated]", logs.records[0].getMessage()) + self.assertIn("too large", logs.records[0].getMessage()) + sibling = logs.records[1].getMessage() + self.assertIn("small sibling", sibling) + self.assertNotIn("truncated", sibling) + self.assertNotIn("extra_omitted", sibling) + + def test_empty_batch_accepted(self): + token = self._create_and_login_admin() + response = self._post("/api/v1/logs/batch", {"batch": []}, token) + self.assertEqual(200, response.code) + + def test_single_entry_must_be_an_object(self): + token = self._create_and_login_admin() + for body in ("42", '"x"', "[1, 2, 3]"): + response = self._post("/api/v1/logs", None, token, body=body) + self.assertEqual(400, response.code) + + def test_deeply_nested_json_returns_400(self): + token = self._create_and_login_admin() + nested = "[" * 200000 + "1" + "]" * 200000 + response = self._post("/api/v1/logs", None, token, body=nested) + self.assertEqual(400, response.code) + response = self._post( + "/api/v1/logs/batch", None, token, body='{"batch":' + nested + "}" + ) + self.assertEqual(400, response.code) + + def test_rate_limit_returns_429(self): + token = self._create_and_login_admin() + self._app.client_log_limiter = ClientLogRateLimiter(limit=3, window=60) + payload = {"level": "INFO", "message": "m"} + for _ in range(3): + self.assertEqual(200, self._post("/api/v1/logs", payload, token).code) + response = self._post("/api/v1/logs", payload, token) + self.assertEqual(429, response.code) + self.assertIn("Retry-After", response.headers) + + def test_rate_limiter_window_resets_and_prunes(self): + limiter = ClientLogRateLimiter(limit=2, window=10) + self.assertIsNone(limiter.check("a", 2, now=0)) + self.assertGreaterEqual(limiter.check("a", 1, now=1), 1.0) + self.assertIsNone(limiter.check("b", 1, now=11)) + self.assertNotIn("a", limiter._windows) + + def test_rate_limiter_budgets_are_per_ip(self): + limiter = ClientLogRateLimiter(limit=2, window=10) + self.assertIsNone(limiter.check("a", 2, now=0)) + self.assertIsNotNone(limiter.check("a", 1, now=1)) + self.assertIsNone(limiter.check("b", 2, now=1)) + + def test_rate_limiter_rejects_non_positive_configuration(self): + for kwargs in ({"limit": 0}, {"limit": -1}, {"window": 0}): + with self.assertRaises(ValueError): + ClientLogRateLimiter(**kwargs) diff --git a/server/test/controllers/api/v1/test_settings.py b/server/test/controllers/api/v1/test_settings.py index 4d6f1778e..4f82dc271 100644 --- a/server/test/controllers/api/v1/test_settings.py +++ b/server/test/controllers/api/v1/test_settings.py @@ -1,4 +1,5 @@ import pytest +from tornado import escape from tornado.testing import gen_test from digi_server.logger import get_logger @@ -66,6 +67,68 @@ def test_jwt_lifetime_as_json_includes_choice_labels(self): ) +class TestSettingsDisclosure(DigiScriptTestCase): + PATH_KEYS = ( + "db_path", + "log_path", + "db_log_path", + "client_log_path", + "compiled_script_path", + "draft_script_path", + ) + + def _get(self, path, token=None): + headers = {"Authorization": f"Bearer {token}"} if token else {} + return escape.json_decode(self.fetch(path, headers=headers).body) + + def test_settings_hide_paths_from_anonymous(self): + for path in ("/api/v1/settings", "/api/v1/settings/raw"): + data = self._get(path) + for key in self.PATH_KEYS: + self.assertNotIn(key, data) + self.assertIn("client_log_enabled", data) + + def test_settings_hide_paths_from_non_admin(self): + admin = self._create_and_login_admin() + user = self._create_and_login_user(admin) + for path in ("/api/v1/settings", "/api/v1/settings/raw"): + data = self._get(path, user) + for key in self.PATH_KEYS: + self.assertNotIn(key, data) + + def test_settings_show_paths_to_admin(self): + admin = self._create_and_login_admin() + for path in ("/api/v1/settings", "/api/v1/settings/raw"): + data = self._get(path, admin) + for key in self.PATH_KEYS: + self.assertIn(key, data) + + def test_file_reload_broadcast_has_no_paths(self): + class FakeClient: + def __init__(self): + self.messages = [] + + def write_message(self, message): + self.messages.append(message) + + client = FakeClient() + self._app.clients.append(client) + try: + self._app.digi_settings.auto_reload_changes() + finally: + self._app.clients.remove(client) + self.assertEqual(1, len(client.messages)) + data = client.messages[0]["DATA"] + for key in self.PATH_KEYS: + self.assertNotIn(key, data) + self.assertIn("client_log_enabled", data) + + def test_broadcast_payload_has_no_paths(self): + data = self.io_loop.run_sync(self._app.digi_settings.as_json) + for key in self.PATH_KEYS: + self.assertNotIn(key, data) + + class TestSettingsController(DigiScriptTestCase): def test_patch_invalid_json_returns_400(self): token = self._create_and_login_admin() diff --git a/server/test/digi_server/test_digi_server.py b/server/test/digi_server/test_digi_server.py index e272b0ad2..bbd51ee01 100644 --- a/server/test/digi_server/test_digi_server.py +++ b/server/test/digi_server/test_digi_server.py @@ -14,13 +14,21 @@ class TestDigiScriptServer(DigiScriptTestCase): def test_debug(self): - response = self.fetch("/debug") + token = self._create_and_login_admin() + response = self.fetch("/debug", headers={"Authorization": f"Bearer {token}"}) response_body = tornado.escape.json_decode(response.body) self.assertEqual(200, response.code) self.assertTrue("status" in response_body) self.assertEqual("OK", response_body["status"]) + def test_debug_requires_admin(self): + self.assertEqual(401, self.fetch("/debug").code) + admin = self._create_and_login_admin() + user = self._create_and_login_user(admin) + response = self.fetch("/debug", headers={"Authorization": f"Bearer {user}"}) + self.assertEqual(403, response.code) + def test_debug_mode_is_opt_in(self): """Debug mode must be opt-in via ``--debug``.""" tree = ast.parse(